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

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

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