CPython mit DTrace und SystemTap instrumentieren
************************************************

DTrace und SystemTap sind Überwachungswerkzeuge. Beide bieten einen
Weg, nachzusehen, was die Prozesse auf einem Rechnersystem tun. Beide
verwenden fachspezifische Sprachen, in denen man Skripte schreiben
kann, die:

* filtern, welche Prozesse beobachtet werden sollen

* Daten aus den interessierenden Prozessen sammeln

* Berichte über die Daten erzeugen

Seit Python 3.6 lässt sich CPython mit eingebetteten „Markern“ bauen,
auch „Probes“ genannt, die ein DTrace- oder SystemTap-Skript
beobachten kann. Damit lässt sich leichter überwachen, was die
CPython-Prozesse auf einem System tun.

DTrace-Marker sind Implementierungsdetails des CPython-Interpreters.
Es wird nicht zugesichert, dass Probes zwischen CPython-Versionen
kompatibel sind. DTrace-Skripte können beim Wechsel der CPython-
Version ohne Vorwarnung aufhören zu funktionieren oder falsch
arbeiten.


Die statischen Marker einschalten
=================================

macOS bringt eine eingebaute Unterstützung für DTrace mit. Um CPython
unter Linux mit den eingebetteten Markern für SystemTap zu bauen,
müssen die SystemTap-Entwicklungswerkzeuge installiert sein.

Auf einem Linux-Rechner geht das so:

   $ yum install systemtap-sdt-devel

oder:

   $ sudo apt-get install systemtap-sdt-dev

CPython muss dann "mit der Option --with-dtrace konfiguriert werden":

   checking for --with-dtrace... yes

Unter macOS kannst du die verfügbaren DTrace-Probes auflisten, indem
du einen Python-Prozess im Hintergrund laufen lässt und alle Probes
auflistest, die der Python-Anbieter bereitstellt:

   $ 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

Unter Linux kannst du prüfen, ob die statischen SystemTap-Marker in
der gebauten Programmdatei vorhanden sind, indem du nachsiehst, ob sie
einen Abschnitt „.note.stapsdt“ enthält.

   $ readelf -S ./python | grep .note.stapsdt
   [30] .note.stapsdt        NOTE         0000000000000000 00308d78

Hast du Python als dynamische Bibliothek gebaut (mit der configure-
Option "--enable-shared"), musst du stattdessen in der dynamischen
Bibliothek nachsehen. Zum Beispiel:

   $ readelf -S libpython3.3dm.so.1.0 | grep .note.stapsdt
   [29] .note.stapsdt        NOTE         0000000000000000 00365b68

Ein ausreichend modernes readelf kann die Metadaten ausgeben:

   $ 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

Die obigen Metadaten enthalten Informationen für SystemTap, die
beschreiben, wie es strategisch platzierte Maschinencodebefehle
umschreiben kann, um die von einem SystemTap-Skript verwendeten Trace-
Haken einzuschalten.


Statische DTrace-Probes
=======================

Mit dem folgenden Beispiel-DTrace-Skript lässt sich die Aufruf- und
Rücksprunghierarchie eines Python-Skripts zeigen, wobei nur innerhalb
des Aufrufs einer Funktion namens „start“ verfolgt wird. Anders
gesagt: Funktionsaufrufe zur Importzeit werden nicht aufgeführt:

   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;
   }

Aufrufen lässt es sich so:

   $ sudo dtrace -q -s call_stack.d -c "python3.6 script.py"

Die Ausgabe sieht so aus:

   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


Statische SystemTap-Marker
==========================

Der tiefere Weg, die SystemTap-Einbindung zu nutzen, ist die direkte
Verwendung der statischen Marker. Dazu musst du die Programmdatei, die
sie enthält, ausdrücklich angeben.

Mit diesem SystemTap-Skript lässt sich zum Beispiel die Aufruf- und
Rücksprunghierarchie eines Python-Skripts zeigen:

   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);
   }

Aufrufen lässt es sich so:

   $ stap \
     show-call-hierarchy.stp \
     -c "./python test.py"

Die Ausgabe sieht so aus:

   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

wobei die Spalten folgendes bedeuten:

* Zeit in Mikrosekunden seit dem Start des Skripts

* Name der Programmdatei

* PID des Prozesses

und der Rest zeigt die Aufruf- und Rücksprunghierarchie, während das
Skript läuft.

Bei einem "--enable-shared"-Build von CPython stecken die Marker in
der dynamischen Bibliothek libpython, und der Punktpfad der Probe muss
das widerspiegeln. Zum Beispiel diese Zeile aus dem obigen Beispiel:

   probe process("python").mark("function__entry") {

muss stattdessen so lauten:

   probe process("python").library("libpython3.6dm.so.1.0").mark("function__entry") {

(angenommen, es handelt sich um einen Debug-Build von CPython 3.6)


Verfügbare statische Marker
===========================

function__entry(str filename, str funcname, int lineno)

   Dieser Marker zeigt an, dass die Ausführung einer Python-Funktion
   begonnen hat. Er wird nur für reine Python-Funktionen (Bytecode)
   ausgelöst.

   Dateiname, Funktionsname und Zeilennummer werden dem Trace-Skript
   als positionelle Argumente zurückgegeben, auf die über "$arg1",
   "$arg2" und "$arg3" zugegriffen werden muss:

      * "$arg1" : "(const char *)" Dateiname, zugänglich über
        "user_string($arg1)"

      * "$arg2" : "(const char *)" Funktionsname, zugänglich über
        "user_string($arg2)"

      * "$arg3" : "int" Zeilennummer

function__return(str filename, str funcname, int lineno)

   Dieser Marker ist das Gegenstück zu "function__entry()" und zeigt
   an, dass die Ausführung einer Python-Funktion beendet ist (entweder
   über "return" oder über eine Ausnahme). Er wird nur für reine
   Python-Funktionen (Bytecode) ausgelöst.

   Die Argumente sind dieselben wie bei "function__entry()"

line(str filename, str funcname, int lineno)

   Dieser Marker zeigt an, dass eine Python-Zeile ausgeführt werden
   soll. Er entspricht dem zeilenweisen Verfolgen mit einem Python-
   Profiler. Innerhalb von C-Funktionen wird er nicht ausgelöst.

   Die Argumente sind dieselben wie bei "function__entry()".

gc__start(int generation)

   Wird ausgelöst, wenn der Python-Interpreter einen Durchgang der
   Speicherbereinigung beginnt. "arg0" ist die zu durchsuchende
   Generation, wie bei "gc.collect()".

gc__done(long collected)

   Wird ausgelöst, wenn der Python-Interpreter einen Durchgang der
   Speicherbereinigung beendet. "arg0" ist die Anzahl der
   eingesammelten Objekte.

import__find__load__start(str modulename)

   Wird ausgelöst, bevor "importlib" versucht, das Modul zu finden und
   zu laden. "arg0" ist der Modulname.

   Added in version 3.7.

import__find__load__done(str modulename, int found)

   Wird ausgelöst, nachdem die Funktion find_and_load von "importlib"
   aufgerufen wurde. "arg0" ist der Modulname, "arg1" zeigt an, ob das
   Modul erfolgreich geladen wurde.

   Added in version 3.7.

audit(str event, void *tuple)

   Wird ausgelöst, wenn "sys.audit()" oder "PySys_Audit()" aufgerufen
   wird. "arg0" ist der Ereignisname als C-Zeichenkette, "arg1" ist
   ein "PyObject"-Zeiger auf ein Tupelobjekt.

   Added in version 3.8.


C-Einsprungpunkte
-----------------

Um das Auslösen von DTrace-Markern zu erleichtern, bringt die C-API
von Python eine Reihe von Hilfsfunktionen mit, die jeden statischen
Marker widerspiegeln. In Python-Builds ohne eingeschaltetes DTrace tun
sie nichts.

Im Allgemeinen musst du sie nicht selbst aufrufen, weil Python das für
dich tut.

+----------------------------------------------------+---------------------------+---------------------------+
| C-API-Funktion                                     | Statischer Marker         | Anmerkungen               |
|====================================================|===========================|===========================|
| void PyDTrace_LINE(const char *arg0, const char    | "line()"                  |                           |
| *arg1, int arg2)                                   |                           |                           |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_FUNCTION_ENTRY(const char *arg0,     | "function__entry()"       |                           |
| const char *arg1, int arg2)                        |                           |                           |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_FUNCTION_RETURN(const char *arg0,    | "function__return()"      |                           |
| const char *arg1, int arg2)                        |                           |                           |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_GC_START(int arg0)                   | "gc__start()"             |                           |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_GC_DONE(Py_ssize_t arg0)             | "gc__done()"              |                           |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_INSTANCE_NEW_START(int arg0)         | "instance__new__start()"  | Von Python nicht          |
|                                                    |                           | verwendet                 |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_INSTANCE_NEW_DONE(int arg0)          | "instance__new__done()"   | Von Python nicht          |
|                                                    |                           | verwendet                 |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_INSTANCE_DELETE_START(int arg0)      | "instance__delete__start  | Von Python nicht          |
|                                                    | ()"                       | verwendet                 |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_INSTANCE_DELETE_DONE(int arg0)       | "instance__delete__done(  | Von Python nicht          |
|                                                    | )"                        | verwendet                 |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_IMPORT_FIND_LOAD_START(const char    | "import__find__load__sta  |                           |
| *arg0)                                             | rt()"                     |                           |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_IMPORT_FIND_LOAD_DONE(const char     | "import__find__load__don  |                           |
| *arg0, int arg1)                                   | e()"                      |                           |
+----------------------------------------------------+---------------------------+---------------------------+
| void PyDTrace_AUDIT(const char *arg0, void *arg1)  | "audit()"                 |                           |
+----------------------------------------------------+---------------------------+---------------------------+


Prüfungen für das Probing in C
------------------------------

int PyDTrace_LINE_ENABLED(void)

int PyDTrace_FUNCTION_ENTRY_ENABLED(void)

int PyDTrace_FUNCTION_RETURN_ENABLED(void)

int PyDTrace_GC_START_ENABLED(void)

int PyDTrace_GC_DONE_ENABLED(void)

int PyDTrace_INSTANCE_NEW_START_ENABLED(void)

int PyDTrace_INSTANCE_NEW_DONE_ENABLED(void)

int PyDTrace_INSTANCE_DELETE_START_ENABLED(void)

int PyDTrace_INSTANCE_DELETE_DONE_ENABLED(void)

int PyDTrace_IMPORT_FIND_LOAD_START_ENABLED(void)

int PyDTrace_IMPORT_FIND_LOAD_DONE_ENABLED(void)

int PyDTrace_AUDIT_ENABLED(void)

   Alle Aufrufe von "PyDTrace"-Funktionen müssen durch einen Aufruf
   einer dieser Funktionen abgesichert werden. Damit kann Python die
   Auswirkungen auf die Leistung bei abgeschaltetem Probing
   geringhalten.

   In Builds ohne eingeschaltetes DTrace tun diese Funktionen nichts
   und geben "0" zurück.


SystemTap-Tapsets
=================

Der höhere Weg, die SystemTap-Einbindung zu nutzen, ist ein „Tapset“:
das Gegenstück zu einer Bibliothek in SystemTap, das einige der
tieferliegenden Details der statischen Marker verbirgt.

Hier eine Tapset-Datei, ausgehend von einem nicht dynamischen Build
von CPython:

   /*
      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
   }

Ist diese Datei im Tapset-Verzeichnis von SystemTap installiert (etwa
"/usr/share/systemtap/tapset"), stehen diese zusätzlichen Probepoints
bereit:

python.function.entry(str filename, str funcname, int lineno, frameptr)

   Dieser Probepoint zeigt an, dass die Ausführung einer Python-
   Funktion begonnen hat. Er wird nur für reine Python-Funktionen
   (Bytecode) ausgelöst.

python.function.return(str filename, str funcname, int lineno, frameptr)

   Dieser Probepoint ist das Gegenstück zu "python.function.return"
   und zeigt an, dass die Ausführung einer Python-Funktion beendet ist
   (entweder über "return" oder über eine Ausnahme). Er wird nur für
   reine Python-Funktionen (Bytecode) ausgelöst.


Beispiele
=========

Dieses SystemTap-Skript nutzt das obige Tapset, um das oben gezeigte
Beispiel – das Verfolgen der Aufrufhierarchie von Python-Funktionen –
sauberer umzusetzen, ohne die statischen Marker direkt benennen zu
müssen:

   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);
   }

Das folgende Skript nutzt das obige Tapset, um eine Übersicht nach Art
von top über allen laufenden CPython-Code zu geben: Es zeigt jede
Sekunde die 20 am häufigsten betretenen Bytecode-Frames über das
gesamte System.

   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;
   }
