Using debug print routine inside assert

Discussion in 'Python' started by Edvard Majakari, Nov 4, 2003.

  1. 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";
     
    Edvard Majakari, Nov 4, 2003
    #1
    1. Advertising

  2. On Tuesday 04 Nov 2003 12:15 pm, Edvard Majakari wrote:
    ....
    > 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.
    --
    Michael Sparks, Senior R&D Engineer, Digital Media Group
    , +44 (0) 1737 839754
    British Broadcasting Corporation, Research and Development
    Kingswood Warren, Surrey KT20 6NP
     
    Michael Sparks, Nov 4, 2003
    #2
    1. Advertising

  3. Edvard Majakari

    Ben Finney Guest

    On Tue, 04 Nov 2003 14:15:30 +0200, Edvard Majakari wrote:
    > 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.

    --
    \ "If you make people think they're thinking, they'll love you; |
    `\ but if you really make them think, they'll hate you." -- |
    _o__) Anonymous |
    Ben Finney <http://bignose.squidly.org/>
     
    Ben Finney, Nov 4, 2003
    #3
  4. Edvard Majakari

    Peter Hansen Guest

    Edvard Majakari wrote:
    >

    [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
     
    Peter Hansen, Nov 4, 2003
    #4
  5. Ben Finney <> writes:

    > 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, Nov 4, 2003
    #5
  6. Peter Hansen <> writes:

    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;
     
    Edvard Majakari, Nov 4, 2003
    #6
  7. "Edvard Majakari" <> wrote in message
    news:...

    > 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/
     
    Richard Brodie, Nov 4, 2003
    #7
  8. 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
     
    Alex Martelli, Nov 4, 2003
    #8
  9. Edvard Majakari

    Peter Hansen Guest

    Edvard Majakari wrote:
    >
    > 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
     
    Peter Hansen, Nov 4, 2003
    #9
  10. "Alex Martelli" <> wrote in message news:0cPpb.91638$...
    > 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_.


    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.
     
    Richard Brodie, Nov 4, 2003
    #10
  11. Edvard Majakari

    Peter Hansen Guest

    Richard Brodie wrote:
    >
    > 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
     
    Peter Hansen, Nov 4, 2003
    #11
  12. "Richard Brodie" <> writes:

    > 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, Nov 4, 2003
    #12
  13. Alex Martelli <> writes:

    > 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;
     
    Edvard Majakari, Nov 5, 2003
    #13
  14. Edvard Majakari wrote:

    > Alex Martelli <> writes:
    >
    >> 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 :)


    <bow> :)


    > 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
     
    Alex Martelli, Nov 5, 2003
    #14
    1. Advertising

Want to reply to this thread or ask your own question?

It takes just 2 minutes to sign up (and it's free!). Just click the sign up button to choose a username and then you can ask your own questions on the forum.
Similar Threads
  1. Robert Brewer
    Replies:
    1
    Views:
    519
    bsmith
    Nov 7, 2004
  2. Thomas Guettler

    assert 0, "foo" vs. assert(0, "foo")

    Thomas Guettler, Feb 23, 2005, in forum: Python
    Replies:
    3
    Views:
    2,566
    Carl Banks
    Feb 23, 2005
  3. Alex Vinokur

    assert(x) and '#define ASSERT(x) assert(x)'

    Alex Vinokur, Nov 25, 2004, in forum: C Programming
    Replies:
    5
    Views:
    960
    Keith Thompson
    Nov 25, 2004
  4. Replies:
    2
    Views:
    399
    Marek Vondrak
    Apr 16, 2006
  5. ImpalerCore

    To assert or not to assert...

    ImpalerCore, Apr 27, 2010, in forum: C Programming
    Replies:
    79
    Views:
    1,755
    Richard Bos
    May 17, 2010
Loading...

Share This Page