Profiling: Interpreting tottime

[Nikolaus Rath]

Hello,

Consider the following function:

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.


Puzzled,

-Nikolaus

 

[Gabriel Genellina]

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]

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."

 

[Nikolaus Rath]

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