.. DO NOT EDIT. .. THIS FILE WAS AUTOMATICALLY GENERATED BY SPHINX-GALLERY. .. TO MAKE CHANGES, EDIT THE SOURCE PYTHON FILE: .. "gyexamples/plot_profiling.py" .. LINE NUMBERS ARE GIVEN BELOW. .. only:: html .. note:: :class: sphx-glr-download-link-note :ref:`Go to the end ` to download the full example code .. rst-class:: sphx-glr-example-title .. _sphx_glr_gyexamples_plot_profiling.py: .. _l-example-event-profling: EventProfiler ============= .. index:: event, profiling, profiler Many profilers propose to see how long a program stays in a function (see :mod:`cProfile`, :epkg:`pyinstrument`, :epkg:`palanteer`). This one logs events. It merges function calls and memory allocations. We compare the insertion and the search of many elements. .. contents:: :local: The simple function to look at ++++++++++++++++++++++++++++++ .. GENERATED FROM PYTHON SOURCE LINES 23-52 .. code-block:: default 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() .. GENERATED FROM PYTHON SOURCE LINES 53-57 The profiling +++++++++++++ It works the same way. .. GENERATED FROM PYTHON SOURCE LINES 57-64 .. code-block:: default ev = EventProfiler() ev.start() f4() ev.stop() .. GENERATED FROM PYTHON SOURCE LINES 65-67 The report ++++++++++ .. GENERATED FROM PYTHON SOURCE LINES 67-76 .. code-block:: default def clean_name(name): return "/".join(name.replace("\\", "/").split('/')[-3:]) df = ev.retrieve_results(clean_file_name=clean_name) df .. raw:: html
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



.. GENERATED FROM PYTHON SOURCE LINES 77-79 Plotting ++++++++ .. GENERATED FROM PYTHON SOURCE LINES 79-90 .. code-block:: default 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) .. image-sg:: /gyexamples/images/sphx_glr_plot_profiling_001.png :alt: Number of events / time :srcset: /gyexamples/images/sphx_glr_plot_profiling_001.png :class: sphx-glr-single-img .. GENERATED FROM PYTHON SOURCE LINES 91-99 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. .. GENERATED FROM PYTHON SOURCE LINES 99-106 .. code-block:: default wev = WithEventProfiler(clean_file_name=clean_name) with wev: f4() wev.report .. raw:: html
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


.. GENERATED FROM PYTHON SOURCE LINES 107-113 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. .. GENERATED FROM PYTHON SOURCE LINES 113-158 .. code-block:: default 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')) .. rst-class:: sphx-glr-script-out .. code-block:: none python: 24.464197 microsecond pybind11: 14.071535 microsecond c: 4.781298 microsecond .. GENERATED FROM PYTHON SOURCE LINES 159-165 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 +++++++++++++++++++++++++++++++++++ .. GENERATED FROM PYTHON SOURCE LINES 165-171 .. code-block:: default wev = WithEventProfiler(clean_file_name=clean_name, impl='c') with wev: f4() wev.report .. raw:: html
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


.. rst-class:: sphx-glr-timing **Total running time of the script:** ( 0 minutes 8.690 seconds) .. _sphx_glr_download_gyexamples_plot_profiling.py: .. only:: html .. container:: sphx-glr-footer sphx-glr-footer-example .. container:: sphx-glr-download sphx-glr-download-python :download:`Download Python source code: plot_profiling.py ` .. container:: sphx-glr-download sphx-glr-download-jupyter :download:`Download Jupyter notebook: plot_profiling.ipynb ` .. only:: html .. rst-class:: sphx-glr-signature `Gallery generated by Sphinx-Gallery `_