Is it reasonable to write worse debug code in order to improve production code?

Question

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).

Answer 1

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.

Answer 2

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.

Answer 3

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.