[profiling] Add profiling instrumentation centered on the eval loop

[ericsnowcurrently]

Here are the key boundaries:

• outside _PyEval_EvalFrameDefault()
• between start of _PyEval_EvalFrameDefault() and top of loop (setting up)
• between top of loop and dispatch
• handling an opcode
• between dispatch and bottom of loop
• between bottom of loop and returning (cleaning up)

[markshannon]

This should mostly be part of the job of the interpreter generator, see #5, IMO.

Adding options to the interpreter generator to insert the instrumentation will be a lot more pleasant than dealing with C macros.

[ericsnowcurrently]

Disregarding how we instrument the code, are there any other significant boundaries we should consider?

[ericsnowcurrently]

As an exercise to better familiarize myself with the knowledge domain, I spent a little time adding some minimal instrumentation (and logging) to the eval loop, as well as a script to analyze the results. See my eval-loop-profiling branch.

The instrumentation generates a log file with a minimal format:

# python: /home/esnow/projects/work/cpython-perf/cpython/python
# argv: ./python -E ./setup.py build
# start time: 1617222445 s (since epoch)
# start clock: 17137493.663947837 s (on clock)
# end clock: 17137494.467647860 s (on clock)

17137493.664739837 0
# func: <module>
17137493.666522537 3
17137493.666523537 5
17137493.666523837 6
17137493.666524037 7
17137493.666524237 8
17137493.666524437 9 100
# func: _DeadlockError
17137493.666531637 3
17137493.666531937 5
17137493.666532137 6
17137493.666532337 7
17137493.666532437 8
17137493.666532637 9 101
17137493.666533537 13
# func: _DeadlockError
17137493.666533937 4
17137493.666534137 2
# func: _ModuleLock
17137493.666562437 3
...
17137494.445492862 13
# func: close
17137494.445493162 4
17137494.445493362 2
# func: release
17137494.445493862 3
17137494.445494062 5
17137494.445494162 6
17137494.445494362 7
17137494.445494562 8
17137494.445494662 9 124
17137494.445495162 13
# func: release
17137494.445495462 4
17137494.445495662 2
17137494.445496162 13
# func: shutdown
17137494.445496462 4
17137494.445496562 2
17137494.467615160 1

For reference, a Python script that has a total runtime of about a second generates roughly 16MB of trace data.

By default, the analysis script makes the log more human-friendly:

$ python3 Tools/scripts/analyze_trace.py
reading from ./eval_loop-1617222445.trace
(showing results in 'simple-indent' format)

# python:         /home/esnow/projects/work/cpython-perf/cpython/python
# argv:           ./python -E ./setup.py build
# start:          2021-03-31 20:27:25.663947 UTC
# end:            2021-03-31 20:27:26.467647 UTC
# elapsed:        803,700.0 µs

####################
# BEGIN TRACE
####################

1,782.7 µs      init
    1.0 µs      enter                                             # func: <module>
    0.3 µs      |  loop enter
    0.2 µs      |  loop slow
    0.2 µs      |  loop fast
    0.2 µs      |  dispatch
    7.2 µs      |  op                     LOAD_CONST (100)
    0.3 µs      |  enter                                          # func: _DeadlockError
    0.2 µs      |  |  loop enter
    0.2 µs      |  |  loop slow
    0.1 µs      |  |  loop fast
    0.2 µs      |  |  dispatch
    0.9 µs      |  |  op                  LOAD_NAME (101)
    0.4 µs      |  |  loop exit
    0.2 µs      |  exit                                           # func: _DeadlockError
   28.3 µs      |  runtime other
    0.2 µs      |  enter                                          # func: _ModuleLock
...
    0.3 µs      |  |  loop exit
    0.2 µs      |  exit                                           # func: close
    0.5 µs      |  runtime other
    0.2 µs      |  enter                                          # func: release
    0.1 µs      |  |  loop enter
    0.2 µs      |  |  loop slow
    0.2 µs      |  |  loop fast
    0.1 µs      |  |  dispatch
    0.5 µs      |  |  op                  LOAD_FAST (124)
    0.3 µs      |  |  loop exit
    0.2 µs      |  exit                                           # func: release
    0.5 µs      |  runtime other
    0.3 µs      |  loop exit
    0.1 µs      exit                                              # func: shutdown
22,118.5 µs     runtime other
                fini

####################
# END TRACE
####################

The script can also provide a summary:

Sorted by Count

$ python3 Tools/scripts/analyze_trace.py --format summary --sort count
reading from ./eval_loop-1617222445.trace
(showing results in 'summary' format)

python:    /home/esnow/projects/work/cpython-perf/cpython/python
argv:      ./python -E ./setup.py build
start:     2021-03-31 20:27:25.663947 UTC
end:       2021-03-31 20:27:26.467647 UTC
elapsed:   803,700.0 µs

events:

           name                count      mean elapsed
--------------------------- ------------ --------------
 dispatch                        94,807         0.1 µs
 op                              94,807         3.4 µs
 loop slow                       61,684         0.2 µs
 loop fast                       61,684         0.1 µs
 enter                           60,382         0.2 µs
 loop exit                       60,382         0.4 µs
 exit                            60,382         0.2 µs
 runtime other                   60,382         5.5 µs
 loop enter                      60,345         0.2 µs
 loop exception                   1,832         0.4 µs
 loop error                       1,821         0.4 µs
 loop exiting                       493         0.2 µs
 init                                 1     1,782.7 µs
 fini                                 1         0.0 µs
--------------------------- ------------ --------------
 total: 14/14

ops:

           name                count      mean elapsed
--------------------------- ------------ --------------
 LOAD_FAST                       24,094         2.0 µs
 POP_JUMP_IF_FALSE               21,937         0.5 µs
 LOAD_GLOBAL                     21,223         3.0 µs
 SETUP_FINALLY                    8,242        21.0 µs
 JUMP_ABSOLUTE                    5,117         0.6 µs
 LOAD_CONST                       2,841         1.6 µs
 BUILD_LIST                       2,640         1.1 µs
 POP_JUMP_IF_TRUE                 2,480         1.4 µs
 FOR_ITER                         1,997         0.7 µs
 POP_TOP                          1,545         0.4 µs
 DUP_TOP                          1,328         1.7 µs
 LOAD_NAME                          550         6.1 µs
 JUMP_FORWARD                       537         0.5 µs
 LOAD_DEREF                          56         1.5 µs
 JUMP_IF_NOT_EXC_MATCH               50         2.7 µs
 JUMP_IF_FALSE_OR_POP                50         1.1 µs
 JUMP_IF_TRUE_OR_POP                 35         2.6 µs
 LOAD_CLOSURE                        25         1.1 µs
 NOP                                 21         0.9 µs
 WITH_EXCEPT_START                   11         0.9 µs
 BUILD_MAP                           11         7.0 µs
 BUILD_SET                            5         4.9 µs
 YIELD_FROM                           4         0.4 µs
 EXTENDED_ARG                         4         0.2 µs
 BUILD_CONST_KEY_MAP                  3        21.4 µs
 SETUP_WITH                           1         9.7 µs
--------------------------- ------------ --------------
 total: 26/125

funcs: 1,025 called (by "simple" name)

Sorted by Average Elapsed Time

$ python3  Tools/scripts/analyze_trace.py --format summary --sort elapsed
reading from ./eval_loop-1617222445.trace
(showing results in 'summary' format)

python:    /home/esnow/projects/work/cpython-perf/cpython/python
argv:      ./python -E ./setup.py build
start:     2021-03-31 20:27:25.663947 UTC
end:       2021-03-31 20:27:26.467647 UTC
elapsed:   803,700.0 µs

events:

           name                count      mean elapsed
--------------------------- ------------ --------------
 init                                 1     1,782.7 µs
 runtime other                   60,382         5.5 µs
 op                              94,807         3.4 µs
 loop error                       1,821         0.4 µs
 loop exit                       60,382         0.4 µs
 loop exception                   1,832         0.4 µs
 enter                           60,382         0.2 µs
 loop exiting                       493         0.2 µs
 exit                            60,382         0.2 µs
 loop enter                      60,345         0.2 µs
 loop slow                       61,684         0.2 µs
 dispatch                        94,807         0.1 µs
 loop fast                       61,684         0.1 µs
 fini                                 1         0.0 µs
--------------------------- ------------ --------------
 total: 14/14

ops:

           name                count      mean elapsed
--------------------------- ------------ --------------
 BUILD_CONST_KEY_MAP                  3        21.4 µs
 SETUP_FINALLY                    8,242        21.0 µs
 SETUP_WITH                           1         9.7 µs
 BUILD_MAP                           11         7.0 µs
 LOAD_NAME                          550         6.1 µs
 BUILD_SET                            5         4.9 µs
 LOAD_GLOBAL                     21,223         3.0 µs
 JUMP_IF_NOT_EXC_MATCH               50         2.7 µs
 JUMP_IF_TRUE_OR_POP                 35         2.6 µs
 LOAD_FAST                       24,094         2.0 µs
 DUP_TOP                          1,328         1.7 µs
 LOAD_CONST                       2,841         1.6 µs
 LOAD_DEREF                          56         1.5 µs
 POP_JUMP_IF_TRUE                 2,480         1.4 µs
 BUILD_LIST                       2,640         1.1 µs
 LOAD_CLOSURE                        25         1.1 µs
 JUMP_IF_FALSE_OR_POP                50         1.1 µs
 WITH_EXCEPT_START                   11         0.9 µs
 NOP                                 21         0.9 µs
 FOR_ITER                         1,997         0.7 µs
 JUMP_ABSOLUTE                    5,117         0.6 µs
 POP_JUMP_IF_FALSE               21,937         0.5 µs
 JUMP_FORWARD                       537         0.5 µs
 YIELD_FROM                           4         0.4 µs
 POP_TOP                          1,545         0.4 µs
 EXTENDED_ARG                         4         0.2 µs
--------------------------- ------------ --------------
 total: 26/125

funcs: 1,025 called (by "simple" name)

[ericsnowcurrently]

This effort proved to be quite insightful for me. This isn't something to pursue further right now but will be worth revisiting later when we've added code generation for the eval loop.

[markshannon]

I think this is worth revisiting.
In order to direct our efforts we need to know where the virtual machine is spending its time.

This is relevant to both startup and general execution.

The text summary sounds useful, could we also get flamegraphs? I think they are a great way to visualize where time is being spent.

We should also generate results using perf or similar tool, to cross check that we are instrumenting the right things.

[ericsnowcurrently]

FWIW, I generated a flamegraph for ./python -c 'pass':

https://raw.githubusercontent.com/faster-cpython/ideas/main/flamegraphs/vm-freq999.svg

If you download the file locally you can interact with it in your browser.

---

The commands (after installing dependencies) look something like this:

#git clone https://github.com/brendangregg/FlameGraph ../FlameGraph

sample_rate_orig=$(cat /proc/sys/kernel/perf_event_max_sample_rate)
max_stack_orig=$(cat /proc/sys/kernel/perf_event_max_stack)
sudo sysctl -w kernel.perf_event_max_sample_rate=100000
sudo sysctl -w kernel.perf_event_max_stack=1000

sudo perf record -F max -a -g -- ./python -c 'pass'
sudo perf script > out.perf
../FlameGraph/stackcollapse-perf.pl out.perf > out.folded
../FlameGraph/flamegraph.pl out.folded > flamegraph.svg

sudo sysctl -w kernel.perf_event_max_sample_rate=$sample_rate_orig
sudo sysctl -w kernel.perf_event_max_stack=$max_stack_orig

See https://github.com/faster-cpython/tools/tree/main/scripts/run-perf.sh for the full operation, including installing dependencies.

[gvanrossum]

Greetings from the Central European Timezone. :-) Is there somewhere that describes what this particular flamegraph means? (I've seen explanations of flamegraphs in general, but I'm not familiar with the tool or methodology used to generate this particular one.)

[sweeneyde]

I ran what amounts to PyPerformance's bench_expand, bench_integrate, bench_sum, and bench_str benchmarks in a loop for about a minute with a PGO ("PGUpdate") build, and Visual Studio's Performance Profiler got me some results.

The hottest 15 functions:

Function Name	Total CPU [unit, %]	Self CPU [unit, %]
_PyEval_EvalFrameDefault	58793 (99.79%)	15770 (26.77%)
call_function	58793 (99.79%)	4045 (6.87%)
_Py_dict_lookup	3262 (5.54%)	3019 (5.12%)
initialize_locals	2329 (3.95%)	1468 (2.49%)
_PyUnicode_FromId	1422 (2.41%)	1422 (2.41%)
_PyFunction_Vectorcall	58793 (99.79%)	1299 (2.20%)
_PyObject_GenericGetAttrWithDict	24025 (40.78%)	1262 (2.14%)
_PyObject_Malloc	1314 (2.23%)	1219 (2.07%)
[External Call] vcruntime140.dll	1076 (1.83%)	1076 (1.83%)
_Py_DECREF	994 (1.69%)	994 (1.69%)
_PyObject_GetMethod	1521 (2.58%)	878 (1.49%)
tupledealloc	996 (1.69%)	878 (1.49%)
frame_dealloc	881 (1.50%)	726 (1.23%)
PyObject_GetAttr	25021 (42.47%)	711 (1.21%)
method_vectorcall	58513 (99.31%)	678 (1.15%)

I also got a Line-by-line-profile of _PyEval_EvalFrameDefault, and VS shows it like this:

I couldn't find a way to make VS dump the output as text, but here are 17 (low-quality, but at least mostly legible) screenshots of the results on the whole function
https://imgur.com/a/WEHwFkr