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 configured ``--with-dtrace``: 50 51.. code-block:: none 52 53 checking for --with-dtrace... yes 54 55On macOS, you can list available DTrace probes by running a Python 56process in the background and listing all probes made available by the 57Python provider:: 58 59 $ python3.6 -q & 60 $ sudo dtrace -l -P python$! # or: dtrace -l -m python3.6 61 62 ID PROVIDER MODULE FUNCTION NAME 63 29564 python18035 python3.6 _PyEval_EvalFrameDefault function-entry 64 29565 python18035 python3.6 dtrace_function_entry function-entry 65 29566 python18035 python3.6 _PyEval_EvalFrameDefault function-return 66 29567 python18035 python3.6 dtrace_function_return function-return 67 29568 python18035 python3.6 collect gc-done 68 29569 python18035 python3.6 collect gc-start 69 29570 python18035 python3.6 _PyEval_EvalFrameDefault line 70 29571 python18035 python3.6 maybe_dtrace_line line 71 72On Linux, you can verify if the SystemTap static markers are present in 73the built binary by seeing if it contains a ".note.stapsdt" section. 74 75:: 76 77 $ readelf -S ./python | grep .note.stapsdt 78 [30] .note.stapsdt NOTE 0000000000000000 00308d78 79 80If you've built Python as a shared library (with --enable-shared), you 81need to look instead within the shared library. For example:: 82 83 $ readelf -S libpython3.3dm.so.1.0 | grep .note.stapsdt 84 [29] .note.stapsdt NOTE 0000000000000000 00365b68 85 86Sufficiently modern readelf can print the metadata:: 87 88 $ readelf -n ./python 89 90 Displaying notes found at file offset 0x00000254 with length 0x00000020: 91 Owner Data size Description 92 GNU 0x00000010 NT_GNU_ABI_TAG (ABI version tag) 93 OS: Linux, ABI: 2.6.32 94 95 Displaying notes found at file offset 0x00000274 with length 0x00000024: 96 Owner Data size Description 97 GNU 0x00000014 NT_GNU_BUILD_ID (unique build ID bitstring) 98 Build ID: df924a2b08a7e89f6e11251d4602022977af2670 99 100 Displaying notes found at file offset 0x002d6c30 with length 0x00000144: 101 Owner Data size Description 102 stapsdt 0x00000031 NT_STAPSDT (SystemTap probe descriptors) 103 Provider: python 104 Name: gc__start 105 Location: 0x00000000004371c3, Base: 0x0000000000630ce2, Semaphore: 0x00000000008d6bf6 106 Arguments: -4@%ebx 107 stapsdt 0x00000030 NT_STAPSDT (SystemTap probe descriptors) 108 Provider: python 109 Name: gc__done 110 Location: 0x00000000004374e1, Base: 0x0000000000630ce2, Semaphore: 0x00000000008d6bf8 111 Arguments: -8@%rax 112 stapsdt 0x00000045 NT_STAPSDT (SystemTap probe descriptors) 113 Provider: python 114 Name: function__entry 115 Location: 0x000000000053db6c, Base: 0x0000000000630ce2, Semaphore: 0x00000000008d6be8 116 Arguments: 8@%rbp 8@%r12 -4@%eax 117 stapsdt 0x00000046 NT_STAPSDT (SystemTap probe descriptors) 118 Provider: python 119 Name: function__return 120 Location: 0x000000000053dba8, Base: 0x0000000000630ce2, Semaphore: 0x00000000008d6bea 121 Arguments: 8@%rbp 8@%r12 -4@%eax 122 123The above metadata contains information for SystemTap describing how it 124can patch strategically-placed machine code instructions to enable the 125tracing hooks used by a SystemTap script. 126 127 128Static DTrace probes 129-------------------- 130 131The following example DTrace script can be used to show the call/return 132hierarchy of a Python script, only tracing within the invocation of 133a function called "start". In other words, import-time function 134invocations are not going to be listed: 135 136.. code-block:: none 137 138 self int indent; 139 140 python$target:::function-entry 141 /copyinstr(arg1) == "start"/ 142 { 143 self->trace = 1; 144 } 145 146 python$target:::function-entry 147 /self->trace/ 148 { 149 printf("%d\t%*s:", timestamp, 15, probename); 150 printf("%*s", self->indent, ""); 151 printf("%s:%s:%d\n", basename(copyinstr(arg0)), copyinstr(arg1), arg2); 152 self->indent++; 153 } 154 155 python$target:::function-return 156 /self->trace/ 157 { 158 self->indent--; 159 printf("%d\t%*s:", timestamp, 15, probename); 160 printf("%*s", self->indent, ""); 161 printf("%s:%s:%d\n", basename(copyinstr(arg0)), copyinstr(arg1), arg2); 162 } 163 164 python$target:::function-return 165 /copyinstr(arg1) == "start"/ 166 { 167 self->trace = 0; 168 } 169 170It can be invoked like this:: 171 172 $ sudo dtrace -q -s call_stack.d -c "python3.6 script.py" 173 174The output looks like this: 175 176.. code-block:: none 177 178 156641360502280 function-entry:call_stack.py:start:23 179 156641360518804 function-entry: call_stack.py:function_1:1 180 156641360532797 function-entry: call_stack.py:function_3:9 181 156641360546807 function-return: call_stack.py:function_3:10 182 156641360563367 function-return: call_stack.py:function_1:2 183 156641360578365 function-entry: call_stack.py:function_2:5 184 156641360591757 function-entry: call_stack.py:function_1:1 185 156641360605556 function-entry: call_stack.py:function_3:9 186 156641360617482 function-return: call_stack.py:function_3:10 187 156641360629814 function-return: call_stack.py:function_1:2 188 156641360642285 function-return: call_stack.py:function_2:6 189 156641360656770 function-entry: call_stack.py:function_3:9 190 156641360669707 function-return: call_stack.py:function_3:10 191 156641360687853 function-entry: call_stack.py:function_4:13 192 156641360700719 function-return: call_stack.py:function_4:14 193 156641360719640 function-entry: call_stack.py:function_5:18 194 156641360732567 function-return: call_stack.py:function_5:21 195 156641360747370 function-return:call_stack.py:start:28 196 197 198Static SystemTap markers 199------------------------ 200 201The low-level way to use the SystemTap integration is to use the static 202markers directly. This requires you to explicitly state the binary file 203containing them. 204 205For example, this SystemTap script can be used to show the call/return 206hierarchy of a Python script: 207 208.. code-block:: none 209 210 probe process("python").mark("function__entry") { 211 filename = user_string($arg1); 212 funcname = user_string($arg2); 213 lineno = $arg3; 214 215 printf("%s => %s in %s:%d\\n", 216 thread_indent(1), funcname, filename, lineno); 217 } 218 219 probe process("python").mark("function__return") { 220 filename = user_string($arg1); 221 funcname = user_string($arg2); 222 lineno = $arg3; 223 224 printf("%s <= %s in %s:%d\\n", 225 thread_indent(-1), funcname, filename, lineno); 226 } 227 228It can be invoked like this:: 229 230 $ stap \ 231 show-call-hierarchy.stp \ 232 -c "./python test.py" 233 234The output looks like this: 235 236.. code-block:: none 237 238 11408 python(8274): => __contains__ in Lib/_abcoll.py:362 239 11414 python(8274): => __getitem__ in Lib/os.py:425 240 11418 python(8274): => encode in Lib/os.py:490 241 11424 python(8274): <= encode in Lib/os.py:493 242 11428 python(8274): <= __getitem__ in Lib/os.py:426 243 11433 python(8274): <= __contains__ in Lib/_abcoll.py:366 244 245where the columns are: 246 247 - time in microseconds since start of script 248 249 - name of executable 250 251 - PID of process 252 253and the remainder indicates the call/return hierarchy as the script executes. 254 255For a `--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 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