Discardable debug message logging in python

After a short discussion about handling of diagnostics messages in python, and the cost of calling 'do nothing' functions in python, I just had an idea.

The point is to be able to (quite) brainlessly insert calls to some debug logging function through python scripts.

Alas, these calls have a cost, which we are willing to pay for a 'debug' run, but not a 'release' run, where things should go fast (or python-fast to be relative).

One first option would be to have a 'do-nothing' function replacing the logging function in 'release' runs :

if __debug__:
  def DBGLOG(message):
    print "[D] " + message
else:
  def DBGLOG(message):
    pass # do nothing
...
DBGLOG("some fancy message")

This works fine, but as CPython does not have any fancy dead code optimization combined with function inlining, it will always evaluate the arguments to the function before doing nothing. Hence, the following call will always cost some time :

DBGLOG("some message with costy parameter : '%s'" + str( [x for x in SOME_LIST ] ))

To prevent evaluating the arguments, we could use a good old if, but I don't like the thought of cluttering code with if statements...

if __debug__:
  DBGLOG("some message with costy parameter : '%s'" + str( [x for x in SOME_LIST ] ))

The only form of conditional compilation I could find, in python, is related to the assert statement ; which is only evaluated if the interpreter constant __debug__ is true. We can use this at our advantage here :

assert DBGLOG("some message with costy parameter : '%s'" + str( [x for x in SOME_LIST ] ))

In this case, the parameters are not evaluated in 'release' runs (interpreter running with '-O' option).

Some quick and dirty benchmark comes below :

With the following results, on my machine :

'pass' time: 3.934145msec

'empty logging function' time: 247.512817msec

'if __debug__' time: 3.726006msec

'if ENABLE_DEBUG_MESSAGES' time: 6.114006msec

'assert logging function' time: 3.714085msec

building with Scons & MSVC8 using PCH with PDB and /Zi

Some note concerning my current attempts to evaluate Scons 1.2 for my needs to replace my 'pure' Visual Studio solutions builds.

After trying to automatically convert my solutions to Scons scripts, which did not work at all, I decided to start from scratch.

I easily got the bare build and link done on one of my modules. And I tried to gradually introduce 'features' in my build : namely Precompiled header (PCH) support, and Debug information generation.

Adding both was easy, using the Scons man page as a reference, I used a construct like this one :

env['PCHSTOP'] = "precompiled.h"

env['PCH'] = env.PCH( os.path.join(builddir, 'precompiled.cpp') )[0]

env['PDB'] = os.path.join( builddir, "%s.pdb" % BASE_NAME )


Using this setup, it works fine out-of-the-box, but Scons msvc tool uses the /Z7 compiler flag to create the debug information. This has the effect to store debug informations in every built obj file, and according to Scons man page (at CCPDBFLAGS information), allow parallel builds to work fast & correctly.

This duplication of debug information lead my, simple, build directory to grow from about 33Mb (using my existing reference MSVC vcproj to build) to about 60Mb, almost 100% bigger...

I took a look at using /Zi instead of /Z7, to have a single PDB containing my debug information, and it took some to figure out how to have it work with PCH altogether.

According to Scons man page, all you have to do is ::

env['CCPDBFLAGS'] = ['${(PDB and "/Zi /Fd%s" % File(PDB)) or ""}']

Using this setup, I had two problems :

• the linker complained about LNK4203 errors, preventing debugging information to be linked.
• when doing a partial build of the project, the compiler complained about a C2859 error, indicating that the PDB file was not the one generated with the PCH, and instructing me to rebuild all.

In fact, what happens, is that Scons instructs the compiler to issue debug information in a given PDB file (say A.PDB) and also instructs the linker to output the debug information in A.PDB. My supposition is that the linker first starts to trash the PDB, and hence cannot find the debug information (LNK4203 errors). Afterwards, the A.PDB file is the one generated by the linker, and the compiler cannot use it anymore with the PCH...

I changed the PDB flags to instruct the compiler to use an intermediate PDB file :

env['CCPDBFLAGS']  = ['${(PDB and "/Fd%s_incremental.pdb /Zi" % File(PDB)) or ""}']

And now everything works fine.