EventProfiler

Many profilers propose to see how long a program stays in a function (see cProfile, pyinstrument, palanteer). This one logs events. It merges function calls and memory allocations. We compare the insertion and the search of many elements.

The simple function to look at

import time
import inspect
from cpyquickhelper.profiling import (
    EventProfiler, WithEventProfiler)
from cpyquickhelper.profiling.event_profiler import EventProfilerDebug
from cpyquickhelper.profiling._event_profiler_c import (
    _profiling_start, _profiling_stop,
    _profiling_log_event, _profiling_delete)


def f1(t):
    time.sleep(t)


def f2():
    f1(0.1)


def f3():
    li = [0 for i in range(0, 100)]
    f1(0.2)
    return li


def f4():
    f2()
    f3()

The profiling

It works the same way.

ev = EventProfiler()
ev.start()
f4()
ev.stop()

The report

def clean_name(name):
    return "/".join(name.replace("\\", "/").split('/')[-3:])


df = ev.retrieve_results(clean_file_name=clean_name)
df
time value1 value2 event name mod lineno from_name from_mod from_line
0 1688096092390937219 0 0 return _setup_profiler cpyquickhelper/profiling/event_profiler.py 153 start cpyquickhelper/profiling/event_profiler.py 126
1 1688096092390948739 0 0 profiler_start __init__ cpyquickhelper/profiling/event_profiler.py 77 <module> _doc/examples/plot_profiling.py 61
2 1688096092390967509 0 0 return start cpyquickhelper/profiling/event_profiler.py 109 <module> _doc/examples/plot_profiling.py 61
3 1688096092390983048 0 0 call f4 _doc/examples/plot_profiling.py 48 <module> _doc/examples/plot_profiling.py 61
4 1688096092390998198 0 0 call f2 _doc/examples/plot_profiling.py 38 f4 _doc/examples/plot_profiling.py 50
... ... ... ... ... ... ... ... ... ... ...
290 1688096092695811836 0 0 call <module> _doc/examples/plot_profiling.py 62 __call__ site-packages/sphinx_gallery/gen_rst.py 650
291 1688096092695830626 0 0 call stop cpyquickhelper/profiling/event_profiler.py 128 <module> _doc/examples/plot_profiling.py 1
292 1688096092695858806 0 0 call _restore_profiler cpyquickhelper/profiling/event_profiler.py 168 stop cpyquickhelper/profiling/event_profiler.py 151
293 1688096092695872996 0 0 c_call setprofile sys 168 setprofile cpyquickhelper/profiling/event_profiler.py 151
294 1688096092695890215 0 0 profiler_sort __init__ cpyquickhelper/profiling/event_profiler.py 77 <module> _doc/examples/plot_profiling.py 61

295 rows × 10 columns



Plotting

df['cst'] = 1
df['nev'] = df['cst'].cumsum()
ax = df[['time', 'nev']].plot(
    x='time', y='nev', title="Number of events / time")
for i in range(1, df.shape[0]):
    x = (df.loc[i - 1, 'time'] + df.loc[i, 'time']) / 2
    y = df.loc[i, 'nev']
    ax.text(x, y, df.loc[i - 1, 'name'], rotation=90, fontsize=8)
Number of events / time

If the code raises an exception

The program crashes if the profiled code raises an exception because the memory profiler is not restored before python extracts the call stack. New allocations still get logged into an object with was deleted. The exception must be caught or another syntax can be used.

wev = WithEventProfiler(clean_file_name=clean_name)
with wev:
    f4()

wev.report
time value1 value2 event name mod lineno from_name from_mod from_line
0 1688096094681186875 0 0 return _setup_profiler cpyquickhelper/profiling/event_profiler.py 153 start cpyquickhelper/profiling/event_profiler.py 126
1 1688096094681198025 0 0 profiler_start __init__ cpyquickhelper/profiling/event_profiler.py 77 __enter__ cpyquickhelper/profiling/event_profiler.py 361
2 1688096094681216365 0 0 return start cpyquickhelper/profiling/event_profiler.py 109 __enter__ cpyquickhelper/profiling/event_profiler.py 361
3 1688096094681229975 0 0 return __enter__ cpyquickhelper/profiling/event_profiler.py 359 <module> _doc/examples/plot_profiling.py 102
4 1688096094681249135 0 0 call f4 _doc/examples/plot_profiling.py 48 <module> _doc/examples/plot_profiling.py 102
5 1688096094681263704 0 0 call f2 _doc/examples/plot_profiling.py 38 f4 _doc/examples/plot_profiling.py 50
6 1688096094681279524 0 0 call f1 _doc/examples/plot_profiling.py 34 f2 _doc/examples/plot_profiling.py 39
7 1688096094681294434 0 0 c_call sleep time 34 sleep _doc/examples/plot_profiling.py 39
8 1688096094781475805 0 0 c_return sleep time 34 sleep _doc/examples/plot_profiling.py 39
9 1688096094781490075 0 0 return f1 _doc/examples/plot_profiling.py 34 f2 _doc/examples/plot_profiling.py 39
10 1688096094781502245 0 0 return f2 _doc/examples/plot_profiling.py 38 f4 _doc/examples/plot_profiling.py 50
11 1688096094781531814 0 0 call f3 _doc/examples/plot_profiling.py 42 f4 _doc/examples/plot_profiling.py 50
12 1688096094781558224 0 0 call <listcomp> _doc/examples/plot_profiling.py 43 f3 _doc/examples/plot_profiling.py 45
13 1688096094781573984 94842261879392 608 malloc start cpyquickhelper/profiling/event_profiler.py 109 __enter__ cpyquickhelper/profiling/event_profiler.py 361
14 1688096094781577534 94842261879392 -608 realloc_free start cpyquickhelper/profiling/event_profiler.py 109 __enter__ cpyquickhelper/profiling/event_profiler.py 361
15 1688096094781577684 94842261879392 736 realloc start cpyquickhelper/profiling/event_profiler.py 109 __enter__ cpyquickhelper/profiling/event_profiler.py 361
16 1688096094781579454 94842261879392 -736 realloc_free start cpyquickhelper/profiling/event_profiler.py 109 __enter__ cpyquickhelper/profiling/event_profiler.py 361
17 1688096094781579584 94842261879392 864 realloc start cpyquickhelper/profiling/event_profiler.py 109 __enter__ cpyquickhelper/profiling/event_profiler.py 361
18 1688096094781591574 0 0 return <listcomp> _doc/examples/plot_profiling.py 43 f3 _doc/examples/plot_profiling.py 45
19 1688096094781601324 94842258139520 576 malloc start cpyquickhelper/profiling/event_profiler.py 109 __enter__ cpyquickhelper/profiling/event_profiler.py 361
20 1688096094781609653 0 0 call f1 _doc/examples/plot_profiling.py 34 f3 _doc/examples/plot_profiling.py 45
21 1688096094781622793 0 0 c_call sleep time 34 sleep _doc/examples/plot_profiling.py 45
22 1688096094981924145 0 0 c_return sleep time 34 sleep _doc/examples/plot_profiling.py 45
23 1688096094981942345 0 0 return f1 _doc/examples/plot_profiling.py 34 f3 _doc/examples/plot_profiling.py 45
24 1688096094981957145 0 0 return f3 _doc/examples/plot_profiling.py 42 f4 _doc/examples/plot_profiling.py 50
25 1688096094981969435 0 0 return f4 _doc/examples/plot_profiling.py 48 <module> _doc/examples/plot_profiling.py 102
26 1688096094981987695 0 0 call __exit__ cpyquickhelper/profiling/event_profiler.py 363 <module> _doc/examples/plot_profiling.py 102
27 1688096094982010414 0 0 call stop cpyquickhelper/profiling/event_profiler.py 128 __exit__ cpyquickhelper/profiling/event_profiler.py 365
28 1688096094982027424 0 0 call _restore_profiler cpyquickhelper/profiling/event_profiler.py 168 stop cpyquickhelper/profiling/event_profiler.py 151
29 1688096094982041424 0 0 c_call setprofile sys 168 setprofile cpyquickhelper/profiling/event_profiler.py 151
30 1688096094982057674 0 0 profiler_sort __init__ cpyquickhelper/profiling/event_profiler.py 77 __enter__ cpyquickhelper/profiling/event_profiler.py 361


Profiling cost

Logging an events takes a few microseconds so A class not profiling but still logging is available to measure the cost of the profiling.

def measure_implementation(impl):
    N = 100000

    if impl == 'python':
        ev = EventProfilerDebug(impl=impl)
        ev.start()
        begin = time.perf_counter()
        for _ in range(N):
            ev.log_event(inspect.currentframe(), 'call', None)
            ev.log_event(inspect.currentframe(), 'return', None)
        end = time.perf_counter()
        ev.stop()
    elif impl == 'c':
        _profiling_start(10000000, True)
        begin = time.perf_counter()
        for _ in range(N):
            _profiling_log_event(inspect.currentframe(), 'call', None)
            _profiling_log_event(inspect.currentframe(), 'return', None)
        end = time.perf_counter()
        _profiling_delete()
        _profiling_stop()
    else:
        ev = EventProfilerDebug(impl=impl)
        ev.start()
        begin = time.perf_counter()
        for _ in range(N):
            ev._buffer.c_log_event(
                inspect.currentframe(), 'call', None)
            ev._buffer.c_log_event(
                inspect.currentframe(), 'return', None)
        end = time.perf_counter()
        ev.stop()

    duration = end - begin
    msg = f"{impl}: {duration / N * 1000000.0:1.6f} microsecond"
    return msg


print(measure_implementation('python'))
print(measure_implementation('pybind11'))
print(measure_implementation('c'))
python: 24.464197 microsecond
pybind11: 14.071535 microsecond
c: 4.781298 microsecond

The fastest implementation uses Python C API and can be enabled by using EventProfiler(impl=’c’). This implementation relies on function from l-api-c-profiler.

EventProfiler with C implementation

wev = WithEventProfiler(clean_file_name=clean_name, impl='c')
with wev:
    f4()

wev.report
time value1 value2 event name mod lineno from_name from_mod from_line
0 1688096100009888526 0 0 return _setup_profiler cpyquickhelper/profiling/event_profiler.py 153 start cpyquickhelper/profiling/event_profiler.py 126
1 1688096100009897186 0 0 c_call _profiling_register_pyinstance cpyquickhelper.profiling._event_profiler_c 109 _profiling_register_pyinstance cpyquickhelper/profiling/event_profiler.py 361
2 1688096100009902926 0 0 c_return _profiling_register_pyinstance cpyquickhelper.profiling._event_profiler_c 109 _profiling_register_pyinstance cpyquickhelper/profiling/event_profiler.py 361
3 1688096100009904886 0 0 return start cpyquickhelper/profiling/event_profiler.py 109 __enter__ cpyquickhelper/profiling/event_profiler.py 361
4 1688096100009908736 0 0 return __enter__ cpyquickhelper/profiling/event_profiler.py 359 <module> _doc/examples/plot_profiling.py 168
5 1688096100009918456 0 0 call f4 _doc/examples/plot_profiling.py 48 <module> _doc/examples/plot_profiling.py 168
6 1688096100009921366 0 0 call f2 _doc/examples/plot_profiling.py 38 f4 _doc/examples/plot_profiling.py 50
7 1688096100009925866 0 0 call f1 _doc/examples/plot_profiling.py 34 f2 _doc/examples/plot_profiling.py 39
8 1688096100009930596 0 0 c_call sleep time 34 sleep _doc/examples/plot_profiling.py 39
9 1688096100110098966 0 0 c_return sleep time 34 sleep _doc/examples/plot_profiling.py 39
10 1688096100110101686 0 0 return f1 _doc/examples/plot_profiling.py 34 f2 _doc/examples/plot_profiling.py 39
11 1688096100110103366 0 0 return f2 _doc/examples/plot_profiling.py 38 f4 _doc/examples/plot_profiling.py 50
12 1688096100110111606 0 0 call f3 _doc/examples/plot_profiling.py 42 f4 _doc/examples/plot_profiling.py 50
13 1688096100110131386 0 0 call <listcomp> _doc/examples/plot_profiling.py 43 f3 _doc/examples/plot_profiling.py 45
14 1688096100110145946 94842260633568 608 malloc start cpyquickhelper/profiling/event_profiler.py 109 __enter__ cpyquickhelper/profiling/event_profiler.py 361
15 1688096100110150776 94842260633568 -608 realloc_free start cpyquickhelper/profiling/event_profiler.py 109 __enter__ cpyquickhelper/profiling/event_profiler.py 361
16 1688096100110151026 94842260623040 736 realloc start cpyquickhelper/profiling/event_profiler.py 109 __enter__ cpyquickhelper/profiling/event_profiler.py 361
17 1688096100110152906 94842260623040 -736 realloc_free start cpyquickhelper/profiling/event_profiler.py 109 __enter__ cpyquickhelper/profiling/event_profiler.py 361
18 1688096100110153046 94842260623040 864 realloc start cpyquickhelper/profiling/event_profiler.py 109 __enter__ cpyquickhelper/profiling/event_profiler.py 361
19 1688096100110155906 0 0 return list builtins 43 list _doc/examples/plot_profiling.py 45
20 1688096100110161436 0 0 call f1 _doc/examples/plot_profiling.py 34 f3 _doc/examples/plot_profiling.py 45
21 1688096100110164706 0 0 c_call sleep time 34 sleep _doc/examples/plot_profiling.py 45
22 1688096100310445338 0 0 c_return sleep time 34 sleep _doc/examples/plot_profiling.py 45
23 1688096100310450778 0 0 return f1 _doc/examples/plot_profiling.py 34 f3 _doc/examples/plot_profiling.py 45
24 1688096100310454848 0 0 return list builtins 42 list _doc/examples/plot_profiling.py 50
25 1688096100310457018 0 0 return f4 _doc/examples/plot_profiling.py 48 <module> _doc/examples/plot_profiling.py 168
26 1688096100310467208 0 0 call __exit__ cpyquickhelper/profiling/event_profiler.py 363 <module> _doc/examples/plot_profiling.py 168
27 1688096100310482457 0 0 call stop cpyquickhelper/profiling/event_profiler.py 128 __exit__ cpyquickhelper/profiling/event_profiler.py 365
28 1688096100310489507 0 0 call _restore_profiler cpyquickhelper/profiling/event_profiler.py 168 stop cpyquickhelper/profiling/event_profiler.py 151
29 1688096100310494117 0 0 c_call setprofile sys 168 setprofile cpyquickhelper/profiling/event_profiler.py 151
30 1688096100310506497 94842261880272 576 malloc start cpyquickhelper/profiling/event_profiler.py 109 __enter__ cpyquickhelper/profiling/event_profiler.py 361


Total running time of the script: ( 0 minutes 8.690 seconds)

Gallery generated by Sphinx-Gallery