Profiling: Interpreting tottime

[Gabriel Genellina]

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? The profiler does not  
detect calls to C functions, I think.
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."

-- 
Gabriel Genellina