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 251 - name of executable 252 253 - PID of process 254 255and the remainder indicates the call/return hierarchy as the script executes. 256 257For a :option:`--enable-shared` build of CPython, the markers are contained within the 258libpython shared library, and the probe's dotted path needs to reflect this. For 259example, this line from the above example: 260 261.. code-block:: none 262 263 probe process("python").mark("function__entry") { 264 265should instead read: 266 267.. code-block:: none 268 269 probe process("python").library("libpython3.6dm.so.1.0").mark("function__entry") { 270 271(assuming a :ref:`debug build <debug-build>` of CPython 3.6) 272 273 274Available static markers 275------------------------ 276 277.. object:: function__entry(str filename, str funcname, int lineno) 278 279 This marker indicates that execution of a Python function has begun. 280 It is only triggered for pure-Python (bytecode) functions. 281 282 The filename, function name, and line number are provided back to the 283 tracing script as positional arguments, which must be accessed using 284 ``$arg1``, ``$arg2``, ``$arg3``: 285 286 * ``$arg1`` : ``(const char *)`` filename, accessible using ``user_string($arg1)`` 287 288 * ``$arg2`` : ``(const char *)`` function name, accessible using 289 ``user_string($arg2)`` 290 291 * ``$arg3`` : ``int`` line number 292 293.. object:: function__return(str filename, str funcname, int lineno) 294 295 This marker is the converse of :c:func:`function__entry`, and indicates that 296 execution of a Python function has ended (either via ``return``, or via an 297 exception). It is only triggered for pure-Python (bytecode) functions. 298 299 The arguments are the same as for :c:func:`function__entry` 300 301.. object:: line(str filename, str funcname, int lineno) 302 303 This marker indicates a Python line is about to be executed. It is 304 the equivalent of line-by-line tracing with a Python profiler. It is 305 not triggered within C functions. 306 307 The arguments are the same as for :c:func:`function__entry`. 308 309.. object:: gc__start(int generation) 310 311 Fires when the Python interpreter starts a garbage collection cycle. 312 ``arg0`` is the generation to scan, like :func:`gc.collect()`. 313 314.. object:: gc__done(long collected) 315 316 Fires when the Python interpreter finishes a garbage collection 317 cycle. ``arg0`` is the number of collected objects. 318 319.. object:: import__find__load__start(str modulename) 320 321 Fires before :mod:`importlib` attempts to find and load the module. 322 ``arg0`` is the module name. 323 324 .. versionadded:: 3.7 325 326.. object:: import__find__load__done(str modulename, int found) 327 328 Fires after :mod:`importlib`'s find_and_load function is called. 329 ``arg0`` is the module name, ``arg1`` indicates if module was 330 successfully loaded. 331 332 .. versionadded:: 3.7 333 334 335.. object:: audit(str event, void *tuple) 336 337 Fires when :func:`sys.audit` or :c:func:`PySys_Audit` is called. 338 ``arg0`` is the event name as C string, ``arg1`` is a :c:type:`PyObject` 339 pointer to a tuple object. 340 341 .. versionadded:: 3.8 342 343 344SystemTap Tapsets 345----------------- 346 347The higher-level way to use the SystemTap integration is to use a "tapset": 348SystemTap's equivalent of a library, which hides some of the lower-level 349details of the static markers. 350 351Here is a tapset file, based on a non-shared build of CPython: 352 353.. code-block:: none 354 355 /* 356 Provide a higher-level wrapping around the function__entry and 357 function__return markers: 358 \*/ 359 probe python.function.entry = process("python").mark("function__entry") 360 { 361 filename = user_string($arg1); 362 funcname = user_string($arg2); 363 lineno = $arg3; 364 frameptr = $arg4 365 } 366 probe python.function.return = process("python").mark("function__return") 367 { 368 filename = user_string($arg1); 369 funcname = user_string($arg2); 370 lineno = $arg3; 371 frameptr = $arg4 372 } 373 374If this file is installed in SystemTap's tapset directory (e.g. 375``/usr/share/systemtap/tapset``), then these additional probepoints become 376available: 377 378.. object:: python.function.entry(str filename, str funcname, int lineno, frameptr) 379 380 This probe point indicates that execution of a Python function has begun. 381 It is only triggered for pure-Python (bytecode) functions. 382 383.. object:: python.function.return(str filename, str funcname, int lineno, frameptr) 384 385 This probe point is the converse of ``python.function.return``, and 386 indicates that execution of a Python function has ended (either via 387 ``return``, or via an exception). It is only triggered for pure-Python 388 (bytecode) functions. 389 390 391Examples 392-------- 393This SystemTap script uses the tapset above to more cleanly implement the 394example given above of tracing the Python function-call hierarchy, without 395needing to directly name the static markers: 396 397.. code-block:: none 398 399 probe python.function.entry 400 { 401 printf("%s => %s in %s:%d\n", 402 thread_indent(1), funcname, filename, lineno); 403 } 404 405 probe python.function.return 406 { 407 printf("%s <= %s in %s:%d\n", 408 thread_indent(-1), funcname, filename, lineno); 409 } 410 411 412The following script uses the tapset above to provide a top-like view of all 413running CPython code, showing the top 20 most frequently-entered bytecode 414frames, each second, across the whole system: 415 416.. code-block:: none 417 418 global fn_calls; 419 420 probe python.function.entry 421 { 422 fn_calls[pid(), filename, funcname, lineno] += 1; 423 } 424 425 probe timer.ms(1000) { 426 printf("\033[2J\033[1;1H") /* clear screen \*/ 427 printf("%6s %80s %6s %30s %6s\n", 428 "PID", "FILENAME", "LINE", "FUNCTION", "CALLS") 429 foreach ([pid, filename, funcname, lineno] in fn_calls- limit 20) { 430 printf("%6d %80s %6d %30s %6d\n", 431 pid, filename, lineno, funcname, 432 fn_calls[pid, filename, funcname, lineno]); 433 } 434 delete fn_calls; 435 } 436 437