launchpad-dev team mailing list archive

[Robert Collins <robert.collins@xxxxxxxxxxxxx>]

On Wed, Nov 16, 2011 at 1:23 PM, Robert Collins
<robert.collins@xxxxxxxxxxxxx> wrote:
> So, I'd like to capture a backtrace whenever we make a SQL query or
> HTTP service call.
...

I misread timeits python API. Unlike the command line it doesn't
normalise - so you need to divide by your main loop count.

Wgrant points out that 20 frames is too shallow due to TAL.

So, here is an updated simulation:60 frames, and repeats normalised
out (you can change 'number =xxx' to any value, and the results should
stay pretty constant.

The updated timing is:
0.25 seconds for 1000 backtraces at 60 frames deep. Or 0.25ms per
backtrace. This is less than the overhead caused by a page cache miss
on the DB server, so I'm going to grab them all.

:!./backtracetiming.py
0.251479740143
0.000343389511108
tb time: 0.251136350632


-Rob

#!/usr/bin/env python

import timeit

# This generates a 20 deep stackframe, and then calls a function that makes a
# stack trace, 1000 times - to simulate a deep appserver stack + oops capturing
# and formating tracebacks.

code = """import traceback
oops = []
def stackframe(depth=60):
    l = locals()
    for i in range(10):
        l[str(i)] = i
    if depth:
        stackframe(depth-1)
    else:
        for i in range(1000):
            oops.append(''.join(traceback.format_stack()))
stackframe()
"""
code2 = """import traceback
oops = []
def stackframe(depth=60):
    l = locals()
    for i in range(10):
        l[str(i)] = i
    if depth:
        stackframe(depth-1)
    else:
        for i in range(1000):
            oops.append('')
stackframe()
"""

# Time with tracebacks
number = 100
t = timeit.Timer(code)
times = t.repeat(number=number)
best_with = min(times) / float(number)
print best_with
# Time without
t = timeit.Timer(code2)
times = t.repeat(number=number)
best_without = min(times) / float(number)
print best_without
print "tb time:", best_with - best_without