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 *arg1, int arg2)

line()
void PyDTrace_FUNCTION_ENTRY(const char *arg0, const char *arg1, int arg2)

function__entry()
void PyDTrace_FUNCTION_RETURN(const char *arg0, const char *arg1, int arg2)

function__return()
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 *arg0)

import__find__load__start()
void PyDTrace_IMPORT_FIND_LOAD_DONE(const char *arg0, int arg1)

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