Vinay:

Yes, the bulk of the time was spent in getEffectiveLevel().  Since that method is only called by isEnabledFor(), it made sense to cache isEnabledFor().  But, that probably reflects the characteristics of my use of logging.  I never call getEffectiveLevel() otherwise, so caching isEnabledFor() minimized the total cost of logging.  I think you could sensibly argue for caching getEffectiveLevel().

I had somewhat shallow logger hierarchies (3-4 deep).  The real problem was that this was being called in a kernel of my code ... so even that additional cost was noteworthy.

I think it's smart to focus on Python 3.3. As it happens, my colleagues did some explicit caching of logging information that made pyutilib.logging redundant.  When you don't think you need this as a reference implementation, I'll delete it.

--Bill



On Wed, Mar 2, 2011 at 2:25 AM, Vinay Sajip <report@bugs.python.org> wrote:

Vinay Sajip <vinay_sajip@yahoo.co.uk> added the comment:

Bill,

Thanks for the suggestion and the patch. It's a good idea, though I wonder whether you found that the bulk of the time spent in isEnabledFor() was actually spent in getEffectiveLevel()? That's the one which loops through a logger's ancestors looking for a level which is actually set, so intuitively it would take a while - especially for deeper levels in the logging hierarchy. If so (which I suspect to be the case, but it would be good to have you confirm it), a better solution may be to cache the effective level.

Roughly how deep are/were your logger hierarchies in the situation where you experienced performance problems?

I'm happy to look at caching effective level for Python 3.3: The 2.X branches are now closed for additions other than bugs and security issues.

----------
assignee:  -> vinay.sajip

_______________________________________
Python tracker <report@bugs.python.org>
<http://bugs.python.org/issue11369>
_______________________________________