diff options
Diffstat (limited to 'Doc/howto/instrumentation.rst')
| -rw-r--r-- | Doc/howto/instrumentation.rst | 408 |
1 files changed, 408 insertions, 0 deletions
diff --git a/Doc/howto/instrumentation.rst b/Doc/howto/instrumentation.rst new file mode 100644 index 0000000000..7fca9aac7b --- /dev/null +++ b/Doc/howto/instrumentation.rst @@ -0,0 +1,408 @@ +.. highlight:: shell-session + +.. _instrumentation: + +=============================================== +Instrumenting CPython with DTrace and SystemTap +=============================================== + +:author: David Malcolm +:author: Łukasz Langa + +DTrace and SystemTap are monitoring tools, each providing a way to inspect +what the processes on a computer system are doing. They both use +domain-specific languages allowing a user to write scripts which: + + - filter which processes are to be observed + - gather data from the processes of interest + - generate reports on the data + +As of Python 3.6, CPython can be built with embedded "markers", also +known as "probes", that can be observed by a DTrace or SystemTap script, +making it easier to monitor what the CPython processes on a system are +doing. + +.. impl-detail:: + + DTrace markers are implementation details of the CPython interpreter. + No guarantees are made about probe compatibility between versions of + CPython. DTrace scripts can stop working or work incorrectly without + warning when changing CPython versions. + + +Enabling the static markers +--------------------------- + +macOS comes with built-in support for DTrace. On Linux, in order to +build CPython with the embedded markers for SystemTap, the SystemTap +development tools must be installed. + +On a Linux machine, this can be done via:: + + $ yum install systemtap-sdt-devel + +or:: + + $ sudo apt-get install systemtap-sdt-dev + + +CPython must then be configured ``--with-dtrace``: + +.. code-block:: none + + checking for --with-dtrace... yes + +On macOS, you can list available DTrace probes by running a Python +process in the background and listing all probes made available by the +Python provider:: + + $ python3.6 -q & + $ sudo dtrace -l -P python$! # or: dtrace -l -m python3.6 + + ID PROVIDER MODULE FUNCTION NAME + 29564 python18035 python3.6 _PyEval_EvalFrameDefault function-entry + 29565 python18035 python3.6 dtrace_function_entry function-entry + 29566 python18035 python3.6 _PyEval_EvalFrameDefault function-return + 29567 python18035 python3.6 dtrace_function_return function-return + 29568 python18035 python3.6 collect gc-done + 29569 python18035 python3.6 collect gc-start + 29570 python18035 python3.6 _PyEval_EvalFrameDefault line + 29571 python18035 python3.6 maybe_dtrace_line line + +On Linux, you can verify if the SystemTap static markers are present in +the built binary by seeing if it contains a ".note.stapsdt" section. + +:: + + $ readelf -S ./python | grep .note.stapsdt + [30] .note.stapsdt NOTE 0000000000000000 00308d78 + +If you've built Python as a shared library (with --enable-shared), you +need to look instead within the shared library. For example:: + + $ readelf -S libpython3.3dm.so.1.0 | grep .note.stapsdt + [29] .note.stapsdt NOTE 0000000000000000 00365b68 + +Sufficiently modern readelf can print the metadata:: + + $ readelf -n ./python + + Displaying notes found at file offset 0x00000254 with length 0x00000020: + Owner Data size Description + GNU 0x00000010 NT_GNU_ABI_TAG (ABI version tag) + OS: Linux, ABI: 2.6.32 + + Displaying notes found at file offset 0x00000274 with length 0x00000024: + Owner Data size Description + GNU 0x00000014 NT_GNU_BUILD_ID (unique build ID bitstring) + Build ID: df924a2b08a7e89f6e11251d4602022977af2670 + + Displaying notes found at file offset 0x002d6c30 with length 0x00000144: + Owner Data size Description + stapsdt 0x00000031 NT_STAPSDT (SystemTap probe descriptors) + Provider: python + Name: gc__start + Location: 0x00000000004371c3, Base: 0x0000000000630ce2, Semaphore: 0x00000000008d6bf6 + Arguments: -4@%ebx + stapsdt 0x00000030 NT_STAPSDT (SystemTap probe descriptors) + Provider: python + Name: gc__done + Location: 0x00000000004374e1, Base: 0x0000000000630ce2, Semaphore: 0x00000000008d6bf8 + Arguments: -8@%rax + stapsdt 0x00000045 NT_STAPSDT (SystemTap probe descriptors) + Provider: python + Name: function__entry + Location: 0x000000000053db6c, Base: 0x0000000000630ce2, Semaphore: 0x00000000008d6be8 + Arguments: 8@%rbp 8@%r12 -4@%eax + stapsdt 0x00000046 NT_STAPSDT (SystemTap probe descriptors) + Provider: python + Name: function__return + Location: 0x000000000053dba8, Base: 0x0000000000630ce2, Semaphore: 0x00000000008d6bea + Arguments: 8@%rbp 8@%r12 -4@%eax + +The above metadata contains information for SystemTap describing how it +can patch strategically-placed machine code instructions to enable the +tracing hooks used by a SystemTap script. + + +Static DTrace probes +-------------------- + +The following example DTrace script can be used to show the call/return +hierarchy of a Python script, only tracing within the invocation of +a function called "start". In other words, import-time function +invocations are not going to be listed: + +.. code-block:: none + + self int indent; + + python$target:::function-entry + /copyinstr(arg1) == "start"/ + { + self->trace = 1; + } + + python$target:::function-entry + /self->trace/ + { + printf("%d\t%*s:", timestamp, 15, probename); + printf("%*s", self->indent, ""); + printf("%s:%s:%d\n", basename(copyinstr(arg0)), copyinstr(arg1), arg2); + self->indent++; + } + + python$target:::function-return + /self->trace/ + { + self->indent--; + printf("%d\t%*s:", timestamp, 15, probename); + printf("%*s", self->indent, ""); + printf("%s:%s:%d\n", basename(copyinstr(arg0)), copyinstr(arg1), arg2); + } + + python$target:::function-return + /copyinstr(arg1) == "start"/ + { + self->trace = 0; + } + +It can be invoked like this:: + + $ sudo dtrace -q -s call_stack.d -c "python3.6 script.py" + +The output looks like this: + +.. code-block:: none + + 156641360502280 function-entry:call_stack.py:start:23 + 156641360518804 function-entry: call_stack.py:function_1:1 + 156641360532797 function-entry: call_stack.py:function_3:9 + 156641360546807 function-return: call_stack.py:function_3:10 + 156641360563367 function-return: call_stack.py:function_1:2 + 156641360578365 function-entry: call_stack.py:function_2:5 + 156641360591757 function-entry: call_stack.py:function_1:1 + 156641360605556 function-entry: call_stack.py:function_3:9 + 156641360617482 function-return: call_stack.py:function_3:10 + 156641360629814 function-return: call_stack.py:function_1:2 + 156641360642285 function-return: call_stack.py:function_2:6 + 156641360656770 function-entry: call_stack.py:function_3:9 + 156641360669707 function-return: call_stack.py:function_3:10 + 156641360687853 function-entry: call_stack.py:function_4:13 + 156641360700719 function-return: call_stack.py:function_4:14 + 156641360719640 function-entry: call_stack.py:function_5:18 + 156641360732567 function-return: call_stack.py:function_5:21 + 156641360747370 function-return:call_stack.py:start:28 + + +Static SystemTap markers +------------------------ + +The low-level way to use the SystemTap integration is to use the static +markers directly. This requires you to explicitly state the binary file +containing them. + +For example, this SystemTap script can be used to show the call/return +hierarchy of a Python script: + +.. code-block:: none + + probe process("python").mark("function__entry") { + filename = user_string($arg1); + funcname = user_string($arg2); + lineno = $arg3; + + printf("%s => %s in %s:%d\\n", + thread_indent(1), funcname, filename, lineno); + } + + probe process("python").mark("function__return") { + filename = user_string($arg1); + funcname = user_string($arg2); + lineno = $arg3; + + printf("%s <= %s in %s:%d\\n", + thread_indent(-1), funcname, filename, lineno); + } + +It can be invoked like this:: + + $ stap \ + show-call-hierarchy.stp \ + -c "./python test.py" + +The output looks like this: + +.. code-block:: none + + 11408 python(8274): => __contains__ in Lib/_abcoll.py:362 + 11414 python(8274): => __getitem__ in Lib/os.py:425 + 11418 python(8274): => encode in Lib/os.py:490 + 11424 python(8274): <= encode in Lib/os.py:493 + 11428 python(8274): <= __getitem__ in Lib/os.py:426 + 11433 python(8274): <= __contains__ in Lib/_abcoll.py:366 + +where the columns are: + + - time in microseconds since start of script + + - name of executable + + - PID of process + +and the remainder indicates the call/return hierarchy as the script executes. + +For a `--enable-shared` build of CPython, the markers are contained within the +libpython shared library, and the probe's dotted path needs to reflect this. For +example, this line from the above example:: + + probe process("python").mark("function__entry") { + +should instead read:: + + probe process("python").library("libpython3.6dm.so.1.0").mark("function__entry") { + +(assuming a debug build of CPython 3.6) + + +Available static markers +------------------------ + +.. I'm reusing the "c:function" type for markers + +.. c:function:: function__entry(str filename, str funcname, int lineno) + + This marker indicates that execution of a Python function has begun. + It is only triggered for pure-Python (bytecode) functions. + + The filename, function name, and line number are provided back to the + tracing script as positional arguments, which must be accessed using + ``$arg1``, ``$arg2``, ``$arg3``: + + * ``$arg1`` : ``(const char *)`` filename, accessible using ``user_string($arg1)`` + + * ``$arg2`` : ``(const char *)`` function name, accessible using + ``user_string($arg2)`` + + * ``$arg3`` : ``int`` line number + +.. c:function:: function__return(str filename, str funcname, int lineno) + + This marker is the converse of :c:func:`function__entry`, and indicates that + execution of a Python function has ended (either via ``return``, or via an + exception). It is only triggered for pure-Python (bytecode) functions. + + The arguments are the same as for :c:func:`function__entry` + +.. c:function:: line(str filename, str funcname, int lineno) + + This marker indicates a Python line is about to be executed. It is + the equivalent of line-by-line tracing with a Python profiler. It is + not triggered within C functions. + + The arguments are the same as for :c:func:`function__entry`. + +.. c:function:: gc__start(int generation) + + Fires when the Python interpreter starts a garbage collection cycle. + ``arg0`` is the generation to scan, like :func:`gc.collect()`. + +.. c:function:: gc__done(long collected) + + Fires when the Python interpreter finishes a garbage collection + cycle. ``arg0`` is the number of collected objects. + + +SystemTap Tapsets +----------------- + +The higher-level way to use the SystemTap integration is to use a "tapset": +SystemTap's equivalent of a library, which hides some of the lower-level +details of the static markers. + +Here is a tapset file, based on a non-shared build of CPython: + +.. code-block:: none + + /* + Provide a higher-level wrapping around the function__entry and + function__return markers: + \*/ + probe python.function.entry = process("python").mark("function__entry") + { + filename = user_string($arg1); + funcname = user_string($arg2); + lineno = $arg3; + frameptr = $arg4 + } + probe python.function.return = process("python").mark("function__return") + { + filename = user_string($arg1); + funcname = user_string($arg2); + lineno = $arg3; + frameptr = $arg4 + } + +If this file is installed in SystemTap's tapset directory (e.g. +``/usr/share/systemtap/tapset``), then these additional probepoints become +available: + +.. c:function:: python.function.entry(str filename, str funcname, int lineno, frameptr) + + This probe point indicates that execution of a Python function has begun. + It is only triggered for pure-python (bytecode) functions. + +.. c:function:: python.function.return(str filename, str funcname, int lineno, frameptr) + + This probe point is the converse of :c:func:`python.function.return`, and + indicates that execution of a Python function has ended (either via + ``return``, or via an exception). It is only triggered for pure-python + (bytecode) functions. + + +Examples +-------- +This SystemTap script uses the tapset above to more cleanly implement the +example given above of tracing the Python function-call hierarchy, without +needing to directly name the static markers: + +.. code-block:: none + + probe python.function.entry + { + printf("%s => %s in %s:%d\n", + thread_indent(1), funcname, filename, lineno); + } + + probe python.function.return + { + printf("%s <= %s in %s:%d\n", + thread_indent(-1), funcname, filename, lineno); + } + + +The following script uses the tapset above to provide a top-like view of all +running CPython code, showing the top 20 most frequently-entered bytecode +frames, each second, across the whole system: + +.. code-block:: none + + global fn_calls; + + probe python.function.entry + { + fn_calls[pid(), filename, funcname, lineno] += 1; + } + + probe timer.ms(1000) { + printf("\033[2J\033[1;1H") /* clear screen \*/ + printf("%6s %80s %6s %30s %6s\n", + "PID", "FILENAME", "LINE", "FUNCTION", "CALLS") + foreach ([pid, filename, funcname, lineno] in fn_calls- limit 20) { + printf("%6d %80s %6d %30s %6d\n", + pid, filename, lineno, funcname, + fn_calls[pid, filename, funcname, lineno]); + } + delete fn_calls; + } + |