1.. highlight:: shell-session 2 3.. _instrumentation: 4 5=============================================== 6Instrumenting CPython with DTrace and SystemTap 7=============================================== 8 9:author: David Malcolm 10:author: Łukasz Langa 11 12DTrace and SystemTap are monitoring tools, each providing a way to inspect 13what the processes on a computer system are doing. They both use 14domain-specific languages allowing a user to write scripts which: 15 16- filter which processes are to be observed 17- gather data from the processes of interest 18- generate reports on the data 19 20As of Python 3.6, CPython can be built with embedded "markers", also 21known as "probes", that can be observed by a DTrace or SystemTap script, 22making it easier to monitor what the CPython processes on a system are 23doing. 24 25.. impl-detail:: 26 27 DTrace markers are implementation details of the CPython interpreter. 28 No guarantees are made about probe compatibility between versions of 29 CPython. DTrace scripts can stop working or work incorrectly without 30 warning when changing CPython versions. 31 32 33Enabling the static markers 34--------------------------- 35 36macOS comes with built-in support for DTrace. On Linux, in order to 37build CPython with the embedded markers for SystemTap, the SystemTap 38development tools must be installed. 39 40On a Linux machine, this can be done via:: 41 42 $ yum install systemtap-sdt-devel 43 44or:: 45 46 $ sudo apt-get install systemtap-sdt-dev 47 48 49CPython must then be :option:`configured with the --with-dtrace option 50<--with-dtrace>`: 51 52.. code-block:: none 53 54 checking for --with-dtrace... yes 55 56On macOS, you can list available DTrace probes by running a Python 57process in the background and listing all probes made available by the 58Python provider:: 59 60 $ python3.6 -q & 61 $ sudo dtrace -l -P python$! # or: dtrace -l -m python3.6 62 63 ID PROVIDER MODULE FUNCTION NAME 64 29564 python18035 python3.6 _PyEval_EvalFrameDefault function-entry 65 29565 python18035 python3.6 dtrace_function_entry function-entry 66 29566 python18035 python3.6 _PyEval_EvalFrameDefault function-return 67 29567 python18035 python3.6 dtrace_function_return function-return 68 29568 python18035 python3.6 collect gc-done 69 29569 python18035 python3.6 collect gc-start 70 29570 python18035 python3.6 _PyEval_EvalFrameDefault line 71 29571 python18035 python3.6 maybe_dtrace_line line 72 73On Linux, you can verify if the SystemTap static markers are present in 74the built binary by seeing if it contains a ".note.stapsdt" section. 75 76:: 77 78 $ readelf -S ./python | grep .note.stapsdt 79 [30] .note.stapsdt NOTE 0000000000000000 00308d78 80 81If you've built Python as a shared library 82(with the :option:`--enable-shared` configure option), you 83need to look instead within the shared library. For example:: 84 85 $ readelf -S libpython3.3dm.so.1.0 | grep .note.stapsdt 86 [29] .note.stapsdt NOTE 0000000000000000 00365b68 87 88Sufficiently modern readelf can print the metadata:: 89 90 $ readelf -n ./python 91 92 Displaying notes found at file offset 0x00000254 with length 0x00000020: 93 Owner Data size Description 94 GNU 0x00000010 NT_GNU_ABI_TAG (ABI version tag) 95 OS: Linux, ABI: 2.6.32 96 97 Displaying notes found at file offset 0x00000274 with length 0x00000024: 98 Owner Data size Description 99 GNU 0x00000014 NT_GNU_BUILD_ID (unique build ID bitstring) 100 Build ID: df924a2b08a7e89f6e11251d4602022977af2670 101 102 Displaying notes found at file offset 0x002d6c30 with length 0x00000144: 103 Owner Data size Description 104 stapsdt 0x00000031 NT_STAPSDT (SystemTap probe descriptors) 105 Provider: python 106 Name: gc__start 107 Location: 0x00000000004371c3, Base: 0x0000000000630ce2, Semaphore: 0x00000000008d6bf6 108 Arguments: -4@%ebx 109 stapsdt 0x00000030 NT_STAPSDT (SystemTap probe descriptors) 110 Provider: python 111 Name: gc__done 112 Location: 0x00000000004374e1, Base: 0x0000000000630ce2, Semaphore: 0x00000000008d6bf8 113 Arguments: -8@%rax 114 stapsdt 0x00000045 NT_STAPSDT (SystemTap probe descriptors) 115 Provider: python 116 Name: function__entry 117 Location: 0x000000000053db6c, Base: 0x0000000000630ce2, Semaphore: 0x00000000008d6be8 118 Arguments: 8@%rbp 8@%r12 -4@%eax 119 stapsdt 0x00000046 NT_STAPSDT (SystemTap probe descriptors) 120 Provider: python 121 Name: function__return 122 Location: 0x000000000053dba8, Base: 0x0000000000630ce2, Semaphore: 0x00000000008d6bea 123 Arguments: 8@%rbp 8@%r12 -4@%eax 124 125The above metadata contains information for SystemTap describing how it 126can patch strategically placed machine code instructions to enable the 127tracing hooks used by a SystemTap script. 128 129 130Static DTrace probes 131-------------------- 132 133The following example DTrace script can be used to show the call/return 134hierarchy of a Python script, only tracing within the invocation of 135a function called "start". In other words, import-time function 136invocations are not going to be listed: 137 138.. code-block:: none 139 140 self int indent; 141 142 python$target:::function-entry 143 /copyinstr(arg1) == "start"/ 144 { 145 self->trace = 1; 146 } 147 148 python$target:::function-entry 149 /self->trace/ 150 { 151 printf("%d\t%*s:", timestamp, 15, probename); 152 printf("%*s", self->indent, ""); 153 printf("%s:%s:%d\n", basename(copyinstr(arg0)), copyinstr(arg1), arg2); 154 self->indent++; 155 } 156 157 python$target:::function-return 158 /self->trace/ 159 { 160 self->indent--; 161 printf("%d\t%*s:", timestamp, 15, probename); 162 printf("%*s", self->indent, ""); 163 printf("%s:%s:%d\n", basename(copyinstr(arg0)), copyinstr(arg1), arg2); 164 } 165 166 python$target:::function-return 167 /copyinstr(arg1) == "start"/ 168 { 169 self->trace = 0; 170 } 171 172It can be invoked like this:: 173 174 $ sudo dtrace -q -s call_stack.d -c "python3.6 script.py" 175 176The output looks like this: 177 178.. code-block:: none 179 180 156641360502280 function-entry:call_stack.py:start:23 181 156641360518804 function-entry: call_stack.py:function_1:1 182 156641360532797 function-entry: call_stack.py:function_3:9 183 156641360546807 function-return: call_stack.py:function_3:10 184 156641360563367 function-return: call_stack.py:function_1:2 185 156641360578365 function-entry: call_stack.py:function_2:5 186 156641360591757 function-entry: call_stack.py:function_1:1 187 156641360605556 function-entry: call_stack.py:function_3:9 188 156641360617482 function-return: call_stack.py:function_3:10 189 156641360629814 function-return: call_stack.py:function_1:2 190 156641360642285 function-return: call_stack.py:function_2:6 191 156641360656770 function-entry: call_stack.py:function_3:9 192 156641360669707 function-return: call_stack.py:function_3:10 193 156641360687853 function-entry: call_stack.py:function_4:13 194 156641360700719 function-return: call_stack.py:function_4:14 195 156641360719640 function-entry: call_stack.py:function_5:18 196 156641360732567 function-return: call_stack.py:function_5:21 197 156641360747370 function-return:call_stack.py:start:28 198 199 200Static SystemTap markers 201------------------------ 202 203The low-level way to use the SystemTap integration is to use the static 204markers directly. This requires you to explicitly state the binary file 205containing them. 206 207For example, this SystemTap script can be used to show the call/return 208hierarchy of a Python script: 209 210.. code-block:: none 211 212 probe process("python").mark("function__entry") { 213 filename = user_string($arg1); 214 funcname = user_string($arg2); 215 lineno = $arg3; 216 217 printf("%s => %s in %s:%d\\n", 218 thread_indent(1), funcname, filename, lineno); 219 } 220 221 probe process("python").mark("function__return") { 222 filename = user_string($arg1); 223 funcname = user_string($arg2); 224 lineno = $arg3; 225 226 printf("%s <= %s in %s:%d\\n", 227 thread_indent(-1), funcname, filename, lineno); 228 } 229 230It can be invoked like this:: 231 232 $ stap \ 233 show-call-hierarchy.stp \ 234 -c "./python test.py" 235 236The output looks like this: 237 238.. code-block:: none 239 240 11408 python(8274): => __contains__ in Lib/_abcoll.py:362 241 11414 python(8274): => __getitem__ in Lib/os.py:425 242 11418 python(8274): => encode in Lib/os.py:490 243 11424 python(8274): <= encode in Lib/os.py:493 244 11428 python(8274): <= __getitem__ in Lib/os.py:426 245 11433 python(8274): <= __contains__ in Lib/_abcoll.py:366 246 247where the columns are: 248 249- time in microseconds since start of script 250- name of executable 251- PID of process 252 253and the remainder indicates the call/return hierarchy as the script executes. 254 255For a :option:`--enable-shared` build of CPython, the markers are contained within the 256libpython shared library, and the probe's dotted path needs to reflect this. For 257example, this line from the above example: 258 259.. code-block:: none 260 261 probe process("python").mark("function__entry") { 262 263should instead read: 264 265.. code-block:: none 266 267 probe process("python").library("libpython3.6dm.so.1.0").mark("function__entry") { 268 269(assuming a :ref:`debug build <debug-build>` of CPython 3.6) 270 271 272Available static markers 273------------------------ 274 275.. object:: function__entry(str filename, str funcname, int lineno) 276 277 This marker indicates that execution of a Python function has begun. 278 It is only triggered for pure-Python (bytecode) functions. 279 280 The filename, function name, and line number are provided back to the 281 tracing script as positional arguments, which must be accessed using 282 ``$arg1``, ``$arg2``, ``$arg3``: 283 284 * ``$arg1`` : ``(const char *)`` filename, accessible using ``user_string($arg1)`` 285 286 * ``$arg2`` : ``(const char *)`` function name, accessible using 287 ``user_string($arg2)`` 288 289 * ``$arg3`` : ``int`` line number 290 291.. object:: function__return(str filename, str funcname, int lineno) 292 293 This marker is the converse of :c:func:`!function__entry`, and indicates that 294 execution of a Python function has ended (either via ``return``, or via an 295 exception). It is only triggered for pure-Python (bytecode) functions. 296 297 The arguments are the same as for :c:func:`!function__entry` 298 299.. object:: line(str filename, str funcname, int lineno) 300 301 This marker indicates a Python line is about to be executed. It is 302 the equivalent of line-by-line tracing with a Python profiler. It is 303 not triggered within C functions. 304 305 The arguments are the same as for :c:func:`!function__entry`. 306 307.. object:: gc__start(int generation) 308 309 Fires when the Python interpreter starts a garbage collection cycle. 310 ``arg0`` is the generation to scan, like :func:`gc.collect`. 311 312.. object:: gc__done(long collected) 313 314 Fires when the Python interpreter finishes a garbage collection 315 cycle. ``arg0`` is the number of collected objects. 316 317.. object:: import__find__load__start(str modulename) 318 319 Fires before :mod:`importlib` attempts to find and load the module. 320 ``arg0`` is the module name. 321 322 .. versionadded:: 3.7 323 324.. object:: import__find__load__done(str modulename, int found) 325 326 Fires after :mod:`importlib`'s find_and_load function is called. 327 ``arg0`` is the module name, ``arg1`` indicates if module was 328 successfully loaded. 329 330 .. versionadded:: 3.7 331 332 333.. object:: audit(str event, void *tuple) 334 335 Fires when :func:`sys.audit` or :c:func:`PySys_Audit` is called. 336 ``arg0`` is the event name as C string, ``arg1`` is a :c:type:`PyObject` 337 pointer to a tuple object. 338 339 .. versionadded:: 3.8 340 341 342SystemTap Tapsets 343----------------- 344 345The higher-level way to use the SystemTap integration is to use a "tapset": 346SystemTap's equivalent of a library, which hides some of the lower-level 347details of the static markers. 348 349Here is a tapset file, based on a non-shared build of CPython: 350 351.. code-block:: none 352 353 /* 354 Provide a higher-level wrapping around the function__entry and 355 function__return markers: 356 \*/ 357 probe python.function.entry = process("python").mark("function__entry") 358 { 359 filename = user_string($arg1); 360 funcname = user_string($arg2); 361 lineno = $arg3; 362 frameptr = $arg4 363 } 364 probe python.function.return = process("python").mark("function__return") 365 { 366 filename = user_string($arg1); 367 funcname = user_string($arg2); 368 lineno = $arg3; 369 frameptr = $arg4 370 } 371 372If this file is installed in SystemTap's tapset directory (e.g. 373``/usr/share/systemtap/tapset``), then these additional probepoints become 374available: 375 376.. object:: python.function.entry(str filename, str funcname, int lineno, frameptr) 377 378 This probe point indicates that execution of a Python function has begun. 379 It is only triggered for pure-Python (bytecode) functions. 380 381.. object:: python.function.return(str filename, str funcname, int lineno, frameptr) 382 383 This probe point is the converse of ``python.function.return``, and 384 indicates that execution of a Python function has ended (either via 385 ``return``, or via an exception). It is only triggered for pure-Python 386 (bytecode) functions. 387 388 389Examples 390-------- 391This SystemTap script uses the tapset above to more cleanly implement the 392example given above of tracing the Python function-call hierarchy, without 393needing to directly name the static markers: 394 395.. code-block:: none 396 397 probe python.function.entry 398 { 399 printf("%s => %s in %s:%d\n", 400 thread_indent(1), funcname, filename, lineno); 401 } 402 403 probe python.function.return 404 { 405 printf("%s <= %s in %s:%d\n", 406 thread_indent(-1), funcname, filename, lineno); 407 } 408 409 410The following script uses the tapset above to provide a top-like view of all 411running CPython code, showing the top 20 most frequently entered bytecode 412frames, each second, across the whole system: 413 414.. code-block:: none 415 416 global fn_calls; 417 418 probe python.function.entry 419 { 420 fn_calls[pid(), filename, funcname, lineno] += 1; 421 } 422 423 probe timer.ms(1000) { 424 printf("\033[2J\033[1;1H") /* clear screen \*/ 425 printf("%6s %80s %6s %30s %6s\n", 426 "PID", "FILENAME", "LINE", "FUNCTION", "CALLS") 427 foreach ([pid, filename, funcname, lineno] in fn_calls- limit 20) { 428 printf("%6d %80s %6d %30s %6d\n", 429 pid, filename, lineno, funcname, 430 fn_calls[pid, filename, funcname, lineno]); 431 } 432 delete fn_calls; 433 } 434 435