1 .. highlight:: shell-session 2 3 .. _instrumentation: 4 5 =============================================== 6 Instrumenting CPython with DTrace and SystemTap 7 =============================================== 8 9 :author: David Malcolm 10 :author: ukasz Langa 11 12 DTrace and SystemTap are monitoring tools, each providing a way to inspect 13 what the processes on a computer system are doing. They both use 14 domain-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 20 As of Python 3.6, CPython can be built with embedded "markers", also 21 known as "probes", that can be observed by a DTrace or SystemTap script, 22 making it easier to monitor what the CPython processes on a system are 23 doing. 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 33 Enabling the static markers 34 --------------------------- 35 36 macOS comes with built-in support for DTrace. On Linux, in order to 37 build CPython with the embedded markers for SystemTap, the SystemTap 38 development tools must be installed. 39 40 On a Linux machine, this can be done via:: 41 42 $ yum install systemtap-sdt-devel 43 44 or:: 45 46 $ sudo apt-get install systemtap-sdt-dev 47 48 49 CPython must then be configured ``--with-dtrace``: 50 51 .. code-block:: none 52 53 checking for --with-dtrace... yes 54 55 On macOS, you can list available DTrace probes by running a Python 56 process in the background and listing all probes made available by the 57 Python 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 72 On Linux, you can verify if the SystemTap static markers are present in 73 the 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 80 If you've built Python as a shared library (with --enable-shared), you 81 need 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 86 Sufficiently 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 123 The above metadata contains information for SystemTap describing how it 124 can patch strategically-placed machine code instructions to enable the 125 tracing hooks used by a SystemTap script. 126 127 128 Static DTrace probes 129 -------------------- 130 131 The following example DTrace script can be used to show the call/return 132 hierarchy of a Python script, only tracing within the invocation of 133 a function called "start". In other words, import-time function 134 invocations 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 170 It can be invoked like this:: 171 172 $ sudo dtrace -q -s call_stack.d -c "python3.6 script.py" 173 174 The 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 198 Static SystemTap markers 199 ------------------------ 200 201 The low-level way to use the SystemTap integration is to use the static 202 markers directly. This requires you to explicitly state the binary file 203 containing them. 204 205 For example, this SystemTap script can be used to show the call/return 206 hierarchy 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 228 It can be invoked like this:: 229 230 $ stap \ 231 show-call-hierarchy.stp \ 232 -c "./python test.py" 233 234 The 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 245 where the columns are: 246 247 - time in microseconds since start of script 248 249 - name of executable 250 251 - PID of process 252 253 and the remainder indicates the call/return hierarchy as the script executes. 254 255 For a `--enable-shared` build of CPython, the markers are contained within the 256 libpython shared library, and the probe's dotted path needs to reflect this. For 257 example, this line from the above example: 258 259 .. code-block:: none 260 261 probe process("python").mark("function__entry") { 262 263 should 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 272 Available static markers 273 ------------------------ 274 275 .. I'm reusing the "c:function" type for markers 276 277 .. c:function:: 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 .. c:function:: 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 .. c:function:: 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 .. c:function:: 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 .. c:function:: 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 .. c:function:: 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 .. c:function:: 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 SystemTap Tapsets 336 ----------------- 337 338 The higher-level way to use the SystemTap integration is to use a "tapset": 339 SystemTap's equivalent of a library, which hides some of the lower-level 340 details of the static markers. 341 342 Here is a tapset file, based on a non-shared build of CPython: 343 344 .. code-block:: none 345 346 /* 347 Provide a higher-level wrapping around the function__entry and 348 function__return markers: 349 \*/ 350 probe python.function.entry = process("python").mark("function__entry") 351 { 352 filename = user_string($arg1); 353 funcname = user_string($arg2); 354 lineno = $arg3; 355 frameptr = $arg4 356 } 357 probe python.function.return = process("python").mark("function__return") 358 { 359 filename = user_string($arg1); 360 funcname = user_string($arg2); 361 lineno = $arg3; 362 frameptr = $arg4 363 } 364 365 If this file is installed in SystemTap's tapset directory (e.g. 366 ``/usr/share/systemtap/tapset``), then these additional probepoints become 367 available: 368 369 .. c:function:: python.function.entry(str filename, str funcname, int lineno, frameptr) 370 371 This probe point indicates that execution of a Python function has begun. 372 It is only triggered for pure-Python (bytecode) functions. 373 374 .. c:function:: python.function.return(str filename, str funcname, int lineno, frameptr) 375 376 This probe point is the converse of :c:func:`python.function.return`, and 377 indicates that execution of a Python function has ended (either via 378 ``return``, or via an exception). It is only triggered for pure-Python 379 (bytecode) functions. 380 381 382 Examples 383 -------- 384 This SystemTap script uses the tapset above to more cleanly implement the 385 example given above of tracing the Python function-call hierarchy, without 386 needing to directly name the static markers: 387 388 .. code-block:: none 389 390 probe python.function.entry 391 { 392 printf("%s => %s in %s:%d\n", 393 thread_indent(1), funcname, filename, lineno); 394 } 395 396 probe python.function.return 397 { 398 printf("%s <= %s in %s:%d\n", 399 thread_indent(-1), funcname, filename, lineno); 400 } 401 402 403 The following script uses the tapset above to provide a top-like view of all 404 running CPython code, showing the top 20 most frequently-entered bytecode 405 frames, each second, across the whole system: 406 407 .. code-block:: none 408 409 global fn_calls; 410 411 probe python.function.entry 412 { 413 fn_calls[pid(), filename, funcname, lineno] += 1; 414 } 415 416 probe timer.ms(1000) { 417 printf("\033[2J\033[1;1H") /* clear screen \*/ 418 printf("%6s %80s %6s %30s %6s\n", 419 "PID", "FILENAME", "LINE", "FUNCTION", "CALLS") 420 foreach ([pid, filename, funcname, lineno] in fn_calls- limit 20) { 421 printf("%6d %80s %6d %30s %6d\n", 422 pid, filename, lineno, funcname, 423 fn_calls[pid, filename, funcname, lineno]); 424 } 425 delete fn_calls; 426 } 427 428
