4

The title pretty much speaks for itself, but I'll provide the current decision I am facing.

I am migrating python code towards the use of generators. The current code looks like this:

...
l = returns_a_list(args)
log.debug('examining {} entries', len(l))
for e in l:
    do_stuff(e)
...

Outside of the debug log, l fits the use case of a generator very well, and its length is not needed anywhere else. However, due to the debug log, using a generator would look something like this:

...
log.debug('examining {} entries', sum(1 for _ in returns_a_generator(args))
for e in returns_a_generator(args):
    do_stuff(e)
...

This one is less readable and calls the generator twice. However, the production code is straightforward. Another option would be:

...
count = 0
for e in returns_a_generator(args):
    do_stuff(e)
    count += 1
log.debug('examining {} entries', count)
...

This one does not call the generator twice, which is not a big deal since we do not really care about performance in debug mode. In my opinion it looks a bit more straightforward in terms of counting elements compared to sum(1 for _ in generator), which does not convey the intentions as clearly (however, the preceding debug message should hint towards what that snippet is doing). However I am still not certain if moving the log is acceptable (what if do_stuff fails? what if for some reason the generator yields way to many values? I'd like to have that debug line before the program crashes or starts computing until the universe's heat death.). Moreover, the counting is still done even in with no debug log.

So, what is your opinion on this general issue? What would you think when stumbling onto one of those three options? After having understood them, would you care about the debug log being convoluted and file an issue/patch or would you think "Ah, got it, it's reasonable like that"?

EDIT: This is the programmers community. I am not that interested in concrete solutions to this particular problem, but more in opinions on the first, larger question (unless of course there is a good argument that such a choice should never happen).

  • I'm not really sure but did my answer miss some points ? it's true than in the end i didn't choose any of your three options, I provide a 4th, but maybe that was unclear of me. IMHO the third the worst, because you add specific debug code within your production code. Just use the 1st and wrap in a if where it is needed (= where it's not not necessary optimization). – Walfrat Oct 20 '16 at 13:58
  • Your suggestions were all very interesting, but as I said in the edit, I'm looking for a more general reflexion about how you value the readability of debug code vs production code. If you are concerned about me validating an answer, you can check, I believe I systematically upvote and select an answer in the questions I ask, it's just that I like to see several answers and experiment for a few days before selecting one. – nathdwek Oct 20 '16 at 14:53
  • @JaredGoguen : That's why you have to call returns_a_generator twice. But again, not really the point of the question. – nathdwek Oct 20 '16 at 16:48
  • And it was unclear, i added a last point, can you tell me if this address what you seak ? – Walfrat Oct 21 '16 at 6:35
5

On a generic case : if the logging make you some non-productions operations that can have a real impact on production performance wrap your code with code like isDebugEnabled() (or directive #ifdef DEBUG or whatever), for instance :

l = returns_a_list(args)
if(logger.isDebugEnabled()){
    // your code
    log.debug('examining {} entries', len(l))
}
for e in l:
    do_stuff(e)

Use only the wrapping when there is extra calculation, a simple log without don't need it and will make your code less readable.

Another way :

if(logger.isDebugEnabled()){
   l = returns_a_list(args);
    log.debug('examining {} entries', len(l))
}else{
    l = returns_a_generator(args);
}

for e in l:
    do_stuff(e)

You have to be sure however that changing returns_a_generator / returns_a_list don't impact the behaviour of your code, like not having the same ordering could impact something.

However, don't use your last solution for debug purpose, adding code like this only for debug is not worth, because people won't be sure it's only for debug purpose unless you didn't forget to put a comment.

Note : I don't know what is the real difference between returns_a_genrator / returns_a_list So I don't know if the case presented doesn't belong to unecessary pre-optimization (computing length cost generally nothing). I'm just showing a standard usage considering the sample given.

EDIT To conclude :

I value prod readability/maintenability/logic over everything about debugging :

  • I don't mix any additional logic for debugging code within my producion's logic. This make harder to isolate what is really required for the production and what is used for debugging. Your 3rd option is a breach of that "rule".
  • All the code that happen in the if wrapper musn't modify variables used by prod code. So when i see a if(logger.isDebugEnabled) and I'm checking some problem code with the production, I don't even read it. So I'm reading as fast as the debug code wasn't here.
  • That is what log.debug does. – nathdwek Oct 20 '16 at 7:52
  • @nathdwek Of course it does, this is why i say to put it only where it is needed but only after your perform your computation. This is why you wrap your code when you really need it as i said in my last sentence – Walfrat Oct 20 '16 at 7:54
  • I don't understand. If logging is not enabled, the counting operation is never done. So I don't really understand what the check you are proposing is accomplishing besides adding lines of code. Is is because wrapping it in a debug check makes it clearer that it is debug code? In my opinion, log.debug already clearly indicates what is happening. Moreover, the code you propose is not using generators, so I don't know how you think it would be best to do the actual counting. – nathdwek Oct 20 '16 at 7:58
  • 3
    Even when logging is not available log.debug does not prevent the counting operation. log.debug is simply a method that receives arguments - the arguments are calculated before the method is invoked and determines whether or not it needs to do the actual logging. – Idan Arye Oct 20 '16 at 10:49
  • 1
    And this is why wrapping become necessary :) – Walfrat Oct 20 '16 at 11:36
3

When something is unreadable, it often helps to encapsulate it in a function(or, sometimes, a class). The function invocation is readable(as long as the name is meaningful and the API is clear) and the function definition should be readable because you are moving to the domain of a smaller problem.

In your example, you can create a function that'll wrap the generator and log the count:

def iteration_logger(generator):
    count = 0
    for value in generator:
        yield value
        count += 1
    log.debug('examining {} entries', count)

for e in iteration_logger(returns_a_generator(args)):
    do_stuff(e)

Other cases can usually be extracted to their own function.

If you choose this approach, be careful to avoid doing things in statements that their root function is a logger. For example:

log.debug('do_stuff resulted in {}', do_stuff())

This is bad because when one reads such code they may subconsciously skip these statements because it looks like all they do is logging. Something like this, however, is OK:

result = logged('do_stuff resulted in {}', do_stuff())

Because here it is clear that this line is more than just logging - it sets a variable, so it has to do some computation/lookup.

2

Another option - if you are just need to handle generators lengths, you can use format conversions. A very basic example - let's define:

from string import Formatter


class MyFormatter(Formatter):
    def convert_field(self, value, conversion):
        try:
            return super().convert_field(value, conversion)
        except ValueError:
            if conversion == 'c':
                return sum(1 for _ in value)
            raise


class log:
    def __init__(self):
        self.formatter = MyFormatter()

    def debug(self, fmt, *args, **kwargs):
        print(self.formatter.format(fmt, *args, **kwargs))

    info = debug
log = log()

(log here is super-simplified compared to your logger - it's just for demonstrating custom format conversions)

Then you can use:

log.debug('examining {!c} entries', returns_a_generator(args))

for e in returns_a_generator(args):
    do_stuff(e)

Because we use {!c} our custom conversion will activate and calculate the length of the generator - but this will only happen if the debug logging is on. If it's off, the generator will be created but it won't run.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.