[ZODB-Dev] profiling zLOG and inspect

[Guido van Rossum]

> Subject: Re: [ZODB-Dev] profiling zLOG and inspect
> From: Christian Reis <kiko at async.com.br>
> To: Guido van Rossum <guido at python.org>
> Cc: ZODB-Dev at zope.org
> Date: Sun, 15 Jun 2003 15:30:39 -0300
> X-MailScanner: Found to be clean
> 
> On Sun, Jun 15, 2003 at 02:04:27PM -0400, Guido van Rossum wrote:
> > > My 2.1/2.2 profile runs are showing me that the import zLOG step is
> > > taking a bit less than 1 second on some of the slower boxes here
> > > (400~500mhz). In the end, it piles down to the fact that import inspect
> > > takes an amazingly long time:
> > > 
> > inspect imports tons of other modules; it begins with this line:
> > 
> >   import sys, os, types, string, re, dis, imp, tokenize, linecache
> > 
> > Several of these import more things in turn.
> 
> I imagine, but the real culprit for slowness is that import inspect for
> some reason generates a *LOT* of calls to sre_*.py (can't recall
> exactly, I'm at home).

I suggest you do some more digging before pointing fingers.  The
source for inspect doesn't do any of that.  Maybe you're confused by
tokenize, which does do that.

> > Inspect in 2.3 has the same line of imports.  It appears faster
> > because more of those modules are already loaded during Python's
> > startup, so the later import doesn't execute any code.
> 
> I see. I understand we'll see diminishing returns, but I am just
> pointing out that if the environment LOG_ variables aren't set, it's not
> really useful to import zLOG anyway, since it seems to me it won't do
> anything (logging.py says it `swallows up logs').
> 
> There's also the runtime cost of making calls to zLOG that won't do
> anything. I'd (lambda x: pass) all those calls out (if not
> environ.has_key()).

If you submit a patch to do that, we might consider it.  But I expect
that during the creation of the patch you'll find how inelegant the
approach you are proposing is.

> > > (As a parting note, the whole ZODB import takes an amazingly long time:
> > >     >>> import time; t = time.time() ; import ZODB ; time.time() - t
> > >     1.7814439535140991
> > > so I suppose getting that number down would be highly welcome)
> > 
> > Yeah, well, good luck. :-(  ZODB just imports lots of *stuff*.
> > 
> > Anyway, I'm unclear why one-time startup costs are important for you.
> > Do you start a lot of processes?
> 
> No, but the user clicks on an icon (it's a desktop app) and then waits,
> and waits, and waits. Then a window shows up and the application itself
> runs quite fast. This initial load time is a problem for testing, too,
> since we need to restart the app a lot during the process.

Two seconds isn't quite so bad.  Perhaps you can make a mroe careful
analysis of what it's really doing all that time?

--Guido van Rossum (home page: http://www.python.org/~guido/)