[ZODB-Dev] [Report] ZEO (Client+Server together) spends almost 25% of time in code controlled by "if __debug__:"

[Tim Peters]

[Dieter Maurer]
> Recently, I analysed ZEO communication efficiency (as we have
> still unexplained non-deterministic problems (50 to 90 % of the time
> spent in ZEO operations)).
>
> I found out, that a heavily ZEO centric operation (reading about
> 120.000 keys from a "BTrees.OOBTree.OOBTree" instance) is sped up by
> almost 25% when Python's "__debug__" is set to false (after I had fixed
> the quadratic runtime behaviour in "short_repr").
>
> Python's "__debug__" is automatically set to "0" when Python is
> run with "-O" option.

More, __debug__ is set to 0 at *compile* time under -O, and code for blocks
of the form

    if __debug__:
        whatever

isn't generated at all then.  Such blocks "vanish".  It's a lot like doing

#if 0
whatever
#endif

in C then.  So code like connection.py's

        if __debug__:
            self.log("recv msg: %s, %s, %s, %s" % (msgid, flags, name,
                                                   short_repr(args)),
                     level=zLOG.TRACE)

is effectively thrown away under -O.  Otherwise (no -O) the block exists,
and all the work of building the arguments to, and calling, self.log is
done, and regardless of the current logging level.  That can be (as you
said) a significant drag on performance

> However, in this case, Python is using "optimized" byte codes without
> "SET_LINENO" instructions. I fear, this will make debugging impossible

It shouldn't hurt getting the right line numbers in tracebacks, but it does
make it impossible to set breakpoints in the Python debugger.

> (Python 2.3 may be debuggable without "SET_LINENO" instructions,
> but I am not sure).

Yes, SET_LINENO is never generated (regardless of -O) in 2.3; different
mechanisms are used in the 2.3 debugger.

> Therefore, I would not like to run Zope with "-O".
>
> I hacked "zLOG/__init__.py" to set "__debug__" to "None"
> in case the log level is ">= 0" and "zdaemon/Daemon.py"
> to start python in optimized mode only when "__debug__ == 0".
> I know that "<PythonDoc>/ref/assert.html" states that
> assignment to "__debug__" is illegal. For Python 2.1.3,
> however, there seem to be no problem as the interpreter
> apparently uses an internal variable for its purposes.

Trying to assign to __debug__ raises SyntaxError (at compile-time) starting
in 2.2.  Whatever happens under 2.1.x is an accident (the docs said "don't
do that", so the result of doing it anyway is undefined and unsupported;
BTW, I disagreed with Guido's decision to enforce not assigning to
__debug__, but didn't prevail).

> Maybe, code should avoid "if __debug__:" conditions to
> protect expensive operations and use its own "if doDebug:" conditions
> instead?

Yes!  I don't believe "if __debug__:" is used anywhere in a damaging way
outside of ZEO/zrpc/connection.py.  smac.py's SizedMessageAsyncConnection
uses self._debug instead, and uses __debug__ only to initialize self._debug
if the constructor's "debug" argument isn't specified.  Its

        if __debug__:
            if self._debug:
                log('message_output %d bytes: %s' %
                    (len(message), short_repr(message)),
                    level=zLOG.TRACE)

is a bit of over-zealous optimization that shouldn't be significantly worse
if collapsed to:

        if self._debug:
            log('message_output %d bytes: %s' %
                (len(message), short_repr(message)),
                level=zLOG.TRACE)


connection.py should do something similar to that (instead of looking at
__debug__ directly everywhere).