Contact: fumanchu@aminus.org

Log in as guest/misc to create tickets

Stöpwatch

Stöpwatch is a tool to profile Python. It excels at timing systems in production with minimal impact.

The Stopwatch class provides:

  • click and reset methods. Each click is recorded in a "race"; you store the current race and start a new race each time you call the reset method.
  • Named clicks. Choose your own labels, or let Stöpwatch auto-generate them for you.
  • Thread-safe "swimlanes". You can time code with a single Stopwatch instance via multiple threads, and rest assured the races for each thread don't step on each other. Although they run independently, they are collected into the same race history.
  • Isolation and collection by some factor other than per-thread; for example, to profile a multi-step operation across threads.
  • Total and average methods.
  • A customizable format method for easy log output.
  • Easy output to CSV files, including scaling and filtering, making graphs a snap with OpenOffice or MS Excel.
  • Attention to safety: when exceptions occur in Stöpwatch code, they are mitigated or explicitly silenced so as not to interfere with long-running systems.
  • Some thought given to memory footprint. Although at some point, I might replace the pervasive use of timedeltas with floats to make it even better.

The module itself can be found here: source:stopwatch.py

Example Stöpwatch session:

s = Stopwatch()
for i in range(3):
    s.click()
    do_stuff()
    s.click(u'stuff done')
    do_other()
    s.click(u'other done')
    log(s.format())
    s.reset()
print 'Columns:', s.columns
print 'Races:'
for r in  s.races:
    print r
print 'Averages:'
print s.format(s.average())
print 'CSV:'
for line in s.csv_gen():
    print line,

Log output:

STöPWATCH start: 2010-04-02 09:13:28.008463 clicks: [Point0=00:00:00][stuff done=00:00:06.234871][other done=00:00:03.000353] Σ: 00:00:09.235224
STöPWATCH start: 2010-04-02 09:13:37.200100 clicks: [Point0=00:00:00][stuff done=00:00:06.184777][other done=00:00:02.990274] Σ: 00:00:09.175051
STöPWATCH start: 2010-04-02 09:13:28.008463 clicks: [Point0=00:00:00][stuff done=00:00:06.330087][other done=00:00:03.001972] Σ: 00:00:09.332059

stdout:

Columns: ['Point 0', 'stuff done', 'other done']
Races:
[datetime.timedelta(0), datetime.timedelta(0, 6, 234871), datetime.timedelta(0, 3, 000353)]
[datetime.timedelta(0), datetime.timedelta(0, 6, 184777), datetime.timedelta(0, 2, 990274)]
[datetime.timedelta(0), datetime.timedelta(0, 6, 330087), datetime.timedelta(0, 3, 001972)]
Averages:
STöPWATCH start: 2010-04-02 09:13:28.008463 clicks: [Point0=00:00:00][stuff done=00:00:06.249911][other done=00:00:02.997533] Σ: 00:00:09.247434
CSV:
"Point 0","stuff done","other done"
0,6.234871,3.000353
0,6.184777,2.990274
0,6.330087,3.001972

Stöpwatch also provides automatic watches, which feature:

  • Automatic watching of each line of code within a individual function.
  • Automatic labels with the line number and text of each profiled line.
  • Add or remove watches for individual functions in a single line of code. A decorator is provided, or you can add watches while your program is running (if you have a REPL into it, or write some UI controls).
  • Automatic management of multiple autowatches--watch multiple functions at once with a single trace hook.
  • Easy sharing of watches between autowatched functions.
  • Minimal impact on other parts of the system. The trace hook is only set while the functions under test are executing.

Autowatch example:

@stopwatch.autowatch()
def f(a, b, c):
    ...

[f(1, 2, 3) for i in range(100)]
f.watch.write_csv('f.csv', scale=stopwatch.usec, minimum=0.1)