Profiling: Interpreting tottime

[Nikolaus Rath]

"Gabriel Genellina" <gagsl-py2 at yahoo.com.ar> writes:
> En Wed, 07 Apr 2010 18:44:39 -0300, Nikolaus Rath <Nikolaus at rath.org>
> escribió:
>
>> def check_s3_refcounts():
>>     """Check s3 object reference counts"""
>>
>>     global found_errors
>>     log.info('Checking S3 object reference counts...')
>>
>>     for (key, refcount) in conn.query("SELECT id, refcount FROM
>> s3_objects"):
>>
>>         refcount2 = conn.get_val("SELECT COUNT(inode) FROM blocks
>> WHERE s3key=?",
>>                                  (key,))
>>         if refcount != refcount2:
>>             log_error("S3 object %s has invalid refcount, setting
>> from %d to %d",
>>                       key, refcount, refcount2)
>>             found_errors = True
>>             if refcount2 != 0:
>>                 conn.execute("UPDATE s3_objects SET refcount=? WHERE
>> id=?",
>>                              (refcount2, key))
>>             else:
>>                 # Orphaned object will be picked up by check_keylist
>>                 conn.execute('DELETE FROM s3_objects WHERE id=?', (key,))
>>
>> When I ran cProfile.Profile().runcall() on it, I got the following
>> result:
>>
>>    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>>         1 7639.962 7639.962 7640.269 7640.269
>> fsck.py:270(check_s3_refcounts)
>>
>> So according to the profiler, the entire 7639 seconds where spent
>> executing the function itself.
>>
>> How is this possible? I really don't see how the above function can
>> consume any CPU time without spending it in one of the called
>> sub-functions.
>
> Is the conn object implemented as a C extension?

No, it's pure Python.

> The profiler does not
> detect calls to C functions, I think.

Hmm. Isn't this a C function?

       26    2.317    0.089    2.317    0.089 {method 'execute' of 'apsw.Cursor' objects}

> You may be interested in this package by Robert Kern:
> http://pypi.python.org/pypi/line_profiler
> "Line-by-line profiler.
> line_profiler will profile the time individual lines of code take to
> execute."

That looks interesting nevertheless, thanks!


   -Nikolaus

-- 
 »Time flies like an arrow, fruit flies like a Banana.«

  PGP fingerprint: 5B93 61F8 4EA2 E279 ABF6  02CF A9AD B7F8 AE4E 425C