Using debug print routine inside assert

[Edvard Majakari]

Hello, fellow Pythonistas!

Today I shortly discussed the problems in using print statements for
debugging problems in Python. Often in coding, in addition to asserts it
is nice to have a debug routine like

import time
global DEBUG_LVL = 0
....
def debug(msg, threshold=1):
if threshold > DEBUG_LVL:
return

print "%s %s\n" %(time.strftime("%d%m%y %H:%M:%S"), msg)

# somewhere in the program
debug("subfrobnicate(%s, %s) returned %s" %(p1, p2, subfrobnicate(p1, p2)))

The idea here is to have consistent debug print messages. However,
parameters or expressions inside the debug statement might be very
time-consuming to run. Assume for a moment that calling subfrobnicate()
takes 0.02 seconds, and it is called 10 000 times in your test
program. During the debug stage, over three minutes of waiting is not
necessarily bad, but if you have lots of that kind of debug statements, it
really pays to take them away from the final product. But this could be
tedious if you have lots of code.

The problem is, if DEBUG_LVL is less than threshold (like in the example
above), parameters to method call are evaluated but results are thrown
away, rendering parameter evaluation (and potential calculations)
useless. You spent extra time in evaluating debug parameter just to throw
results away. If you could skip the evaluation of debug(), given low
enough DEBUG_LVL, you would be fine.

One solution - though not elegant and rather ugly - is to use Python's
ability to remove assert statements from byte-compiled programs, and
modify debug routine so that it prints given argument and returns true:

def debug(msg, threshold=1):
if threshold > DEBUG_LVL:
return

print "%s %s\n" %(time.strftime("%d%m%y %H:%M:%S"), msg)
return True # return true so that assert always succeeds

# use in the program:

assert(debug("subfrobnicate(%s, %s) returned %s" \
%(p1, p2, subfrobnicate(p1, p2))))


In C, you could use macros to implement assert-wrapped debug function, but
due to their hard-to-detect nature I wouldn't resort to macros, and
nevertheless, in Python, you don't have such thing as macros(?).

What do you think, what is the best solution for this kind of problem? I
for one wouldn't like to see myself writing assert(debug(...)) every now
and then

--
# Edvard Majakari Software Engineer
# PGP PUBLIC KEY available Soli Deo Gloria!

$_ = '456476617264204d616a616b6172692c20612043687269737469616e20'; print
join('',map{chr hex}(split/(\w{2})/)),uc substr(crypt(60281449,'es'),2,4),"\n";

 

[Michael Sparks]

.

What do you think, what is the best solution for this kind of problem? I
for one wouldn't like to see myself writing assert(debug(...)) every now
and then

I haven't got a solution to this, but I would be interested in a solution as
well. I came to similar conclusions some months back and have been doing
assert/debug for a while now, and the difference between -OO and debug is
diverging very heavily. (couple of orders of magnitude kinds of differences)


Michael.

 

[Ben Finney]

Today I shortly discussed the problems in using print statements for
debugging problems in Python. Often in coding, in addition to asserts it
is nice to have a debug routine like

import time
global DEBUG_LVL = 0
...
def debug(msg, threshold=1):
if threshold > DEBUG_LVL:
return

print "%s %s\n" %(time.strftime("%d%m%y %H:%M:%S"), msg)

# somewhere in the program
debug("subfrobnicate(%s, %s) returned %s" %(p1, p2, subfrobnicate(p1, p2)))

The debug routine looks elegant and useful; thanks.

The instance of its use is the problem.

You're performing two discrete operations: get the result of the
subfrobnicate() call, and then emit a debug message. The problem isn't
with the debug message -- it's with the subfrobnicate() call. Or more
precisely, the fact that you only seem to be using it for the debug()
call.


If the code only ever uses subfrobnicate() when you emit the debug
message -- which isn't going to occur in the released program -- you
don't really need to see it.

# somewhere in the program
debug( "p1 is %s, p2 is %s", % ( p1, p2 ) )


If the result of subfrobnicate() is important enough that you want to
track it with a debug() call, it's probably because you're using the
same result elsewhere. So why are you calling it each time it's needed?
Calculate it, emit the message, then use it some more.

# somewhere in the program
sf_result = subfrobnicate( p1, p2 )
debug( "sf_result is %s (subfrobnicated from %s, %s)" %
( sf_result, p1, p2 )
)
do_other_stuff( sf_result )


Either the subfrobnicate() call is a waste of cycles -- remove it. Or,
it's a necessary part of the program -- keep its result for use in the
debug message *and* the main program.

 

[Peter Hansen]

[snip problem]
What do you think, what is the best solution for this kind of problem? I
for one wouldn't like to see myself writing assert(debug(...)) every now
and then

My solution has been to dispense completely with "debugging code"
except *during* debugging (when a print or two might appear temporarily,
or a call to pdb.set_trace()), and instead do all my development using
unit tests.

With adequate use of the "unittest" standard module, I haven't encountered
any reason to call one of those old debug() routines or have a global
"debug level" variable for eons...

(I'm sorry that my advice is pretty much to change the way you do
development, but it has worked for me.)

-Peter

 

[Edvard Majakari]

The debug routine looks elegant and useful; thanks.

You're welcome

The instance of its use is the problem.

You're performing two discrete operations: get the result of the
subfrobnicate() call, and then emit a debug message. The problem isn't
with the debug message -- it's with the subfrobnicate() call. Or more
precisely, the fact that you only seem to be using it for the debug()
call.

If the code only ever uses subfrobnicate() when you emit the debug
message -- which isn't going to occur in the released program -- you
don't really need to see it.

I think I got your point. In general you are right, but consider the
situation: you have a complex data structure (graph linked to
some complex, associated data) and you use it in your program. Suppose
subfrobnicate() doesn't return any values usable by program, but instead
it traverses the data structure and converts the representation from
(eg) numerical to more human readable form. Then the only use for
subfrobnicate() would be inside a debug-like print statement, and my
original question is valid.

Then again, if somebody suggests that proper architectural design of the
software helps to avoid that kind of problems, I'd say he's right but I'd
also welcome him to real life, where debugging is always part of the
software process.

If the result of subfrobnicate() is important enough that you want to
track it with a debug() call, it's probably because you're using the
same result elsewhere. So why are you calling it each time it's needed?
Calculate it, emit the message, then use it some more.

Either the subfrobnicate() call is a waste of cycles -- remove it. Or,
it's a necessary part of the program -- keep its result for use in the
debug message *and* the main program.

See above. Would this be a place for PEP ?-)

--
# Edvard Majakari Software Engineer
# PGP PUBLIC KEY available Soli Deo Gloria!
One day, when he was naughty, Mr Bunnsy looked over the hedge into Farmer
Fred's field and it was full of fresh green lettuces. Mr Bunnsy, however, was
not full of lettuces. This did not seem fair. --Mr Bunnsy has an adventure

 

[Edvard Majakari]

Hi!

My solution has been to dispense completely with "debugging code"
except *during* debugging (when a print or two might appear temporarily,
or a call to pdb.set_trace()), and instead do all my development using
unit tests.

Now, if I had to name a person for Father of All Unit Testing Advocates, I
think I knew who'd I name...

With adequate use of the "unittest" standard module, I haven't encountered
any reason to call one of those old debug() routines or have a global
"debug level" variable for eons...

Personally, I think you're right. I've become fascinated with the idea of
unit testing myself, but the problem is that

a) you often have to find out bugs from somebody else's code

b) you've developed system using testing, but the bug didn't appear in
your tests and now you don't know what causes the problem

c) you didn't do unit testing yet when you coded the module or

d) you don't believe in unit testing

to which we'd say d is the wrong answer, c is more likely and a and b just
happen.

--
#!/usr/bin/perl -w
$h={23,69,28,'6e',2,64,3,76,7,20,13,61,8,'4d',24,73,10,'6a',12,'6b',21,68,14,
72,16,'2c',17,20,9,61,11,61,25,74,4,61,1,45,29,20,5,72,18,61,15,69,20,43,26,
69,19,20,6,64,27,61,22,72};$_=join'',map{chr hex $h->{$_}}sort{$a<=>$b}
keys%$h;m/(\w).*\s(\w+)/x;$_.=uc substr(crypt(join('',60,28,14,49),join'',
map{lc}($1,substr $2,4,1)),2,4)."\n"; print;

 

[Richard Brodie]

Today I shortly discussed the problems in using print statements for
debugging problems in Python. Often in coding, in addition to asserts it
is nice to have a debug routine like

# somewhere in the program
debug("subfrobnicate(%s, %s) returned %s" %(p1, p2, subfrobnicate(p1, p2)))

The idea here is to have consistent debug print messages. However,
parameters or expressions inside the debug statement might be very
time-consuming to run.

I'm not sure how often you would need to write:

debug("subfrobnicate(%s, %s) returned %s" %(p1, p2, subfrobnicate(p1, p2)))

without having called subfrobnicate in the main code. Assuming that you do,
though, it's relatively easy to juggle around the code by having something like:

def defer(f, *args):
f(*args)

and writing:

debug("subfrobnicate(%s, %s) returned %s" % (p1, p2, defer(subfrobnicate, p1, p2)))

Also note that Python now has a standard logging module since 2.3:
http://www.python.org/doc/2.3/whatsnew/

 

[Alex Martelli]

Richard Brodie wrote:
...

def defer(f, *args):
f(*args)

Hmmm, this doesn't defer anything -- the moment you call defer, it in
turns calls f _at once_.

You can't impose lazy evaluation in Python unless the function you
are calling -- e.g. debug in the following:

debug("subfrobnicate(%s, %s) returned %s" % (p1, p2, defer(subfrobnicate,
p1, p2)))

_explicitly supports_ laziness -- e.g., accepts a callable and only
calls it if it needs its value (or, similarly, accepts an iterator and
only steps into it if it needs to, etc, etc).

So, for example, 'debug' would have to be changed to:

def debug(msg, *args):
if not must_do_some_output: return

if args:
msg = msg % args[0](*args[1:])

# proceed to output msg

and called as

debug("subfrobnicate(%s, %s) returned %%s" % (p1, p2),
subfrobnicate, p1, p2)


Alex

 

[Peter Hansen]

Personally, I think you're right. I've become fascinated with the idea of
unit testing myself, but the problem is that

a) you often have to find out bugs from somebody else's code

True, and for that I do throw in a few prints or resort to pdb.set_trace(),
but only temporarily.

b) you've developed system using testing, but the bug didn't appear in
your tests and now you don't know what causes the problem

Same as above, but of course you also would add a test that does
catch the bug, so you know you've fixed it.

c) you didn't do unit testing yet when you coded the module or

I think the OP was talking about code he was developing, so this is
sort of a moot point...

d) you don't believe in unit testing

to which we'd say d is the wrong answer, c is more likely and a and b just
happen.

All true. And the fix for c is obvious.

-Peter

 

[Richard Brodie]

Richard Brodie wrote:
...

Hmmm, this doesn't defer anything -- the moment you call defer, it in
turns calls f _at once_.

Yeah, I was just sketching out a pattern on how to write the debug routine
but overedited it to omit the if (debug) part. Then compounded my error
by conflating the two debug implementations later.

Thanks for expressing more clearly and correctly what I was thinking.

On the unittest vs. logging debate: logging can be useful at the level, where
you couldn't deduce from the code what should be happening. For
example, if you have to interoperate with third-party, possibly buggy clients.
"What requests have been rejected as malformed?" is a question unit tests can't
address. OTOH if you are adding debug code to find how an individual unit
works, that probably is bad practice.

 

[Peter Hansen]

On the unittest vs. logging debate: logging can be useful at the level, where
you couldn't deduce from the code what should be happening. For
example, if you have to interoperate with third-party, possibly buggy clients.
"What requests have been rejected as malformed?" is a question unit tests can't
address. OTOH if you are adding debug code to find how an individual unit
works, that probably is bad practice.

I agree, logging can be very useful. In fact, we tend to find that we've
built at least some kind of logging into almost every non-trivial program
we write, to make it more efficient to find just such interface-related
problems as you describe above. There are certainly times when a user or
external program will do something unexpected, and if you have a record
of the situation that caused it, you've got a big head start on finding
the problem. (Mainly this lets you immediate create a new acceptance test
case, generally reproducing the problem fairly quickly, and then you
can focus on the debugging process.)

For internal interfaces, this kind of thing is much less useful if you
have tests, and I would agree it's now "probably bad practice".

-Peter

 

[Edvard Majakari]

I'm not sure how often you would need to write:

debug("subfrobnicate(%s, %s) returned %s" %(p1, p2, subfrobnicate(p1,
p2)))

Of course you're right here - my example was pretty synthetic.

Also note that Python now has a standard logging module since 2.3:
http://www.python.org/doc/2.3/whatsnew/

That listing seemed quite impressive. Thanks!

--
# Edvard Majakari Software Engineer
# PGP PUBLIC KEY available Soli Deo Gloria!

$_ = '456476617264204d616a616b6172692c20612043687269737469616e20'; print
join('',map{chr hex}(split/(\w{2})/)),uc substr(crypt(60281449,'es'),2,4),"\n";

 

[Edvard Majakari]

def debug(msg, *args):
if not must_do_some_output: return

if args:
msg = msg % args[0](*args[1:])

# proceed to output msg

and called as

Gee - I'm impressed to receive answer to my original problem from
Martellibot himself

This is an excellent solution. I just realised it is backwards compatible
with my current system - calling debug('foo bar baf %s' %method_call())
works just fine with Alex's version; it just works the same as before, and
doesn't get any advantage from deferred parameter list evaluation.

Of course there's still minor overhead in calling the method instead of
completely skipping it like with assert(), but usually that doesn't matter
at all.

--
#!/usr/bin/perl -w
$h={23,69,28,'6e',2,64,3,76,7,20,13,61,8,'4d',24,73,10,'6a',12,'6b',21,68,14,
72,16,'2c',17,20,9,61,11,61,25,74,4,61,1,45,29,20,5,72,18,61,15,69,20,43,26,
69,19,20,6,64,27,61,22,72};$_=join'',map{chr hex $h->{$_}}sort{$a<=>$b}
keys%$h;m/(\w).*\s(\w+)/x;$_.=uc substr(crypt(join('',60,28,14,49),join'',
map{lc}($1,substr $2,4,1)),2,4)."\n"; print;

 

[Alex Martelli]

def debug(msg, *args):
if not must_do_some_output: return

if args:
msg = msg % args[0](*args[1:])

# proceed to output msg

and called as

Gee - I'm impressed to receive answer to my original problem from
Martellibot himself

This is an excellent solution. I just realised it is backwards compatible
with my current system - calling debug('foo bar baf %s' %method_call())
works just fine with Alex's version; it just works the same as before, and
doesn't get any advantage from deferred parameter list evaluation.

Yes, the deferred evaluation above is just optional.

Of course there's still minor overhead in calling the method instead of
completely skipping it like with assert(), but usually that doesn't matter
at all.

Usually not. When it does (you've got lots of calls to debug that you'd
rather not just comment out and the overhead even just for debug checking
a flag and returning is annoying) the fastest approach is

debug = noop.noop

where noop is a do-nothing C-coded callable that accepts any args at all
and returns None... (also make sure the name 'debug' is local to the
function doing the calls, else the name lookup overhead is being paid


Alex