CPython mit DTrace und SystemTap instrumentieren

Autor:

David Malcolm

Autor:

Łukasz Langa

DTrace und SystemTap sind Überwachungswerkzeuge, die jeweils eine Möglichkeit bieten, zu inspizieren, was die Prozesse auf einem Computersystem tun. Beide verwenden domänenspezifische Sprachen, die es einem Benutzer ermöglichen, Skripte zu schreiben, die

  • filtern, welche Prozesse beobachtet werden sollen

  • Daten von den interessierenden Prozessen sammeln

  • Berichte über die Daten generieren

Seit Python 3.6 kann CPython mit eingebetteten „Markern“, auch „Probes“ genannt, erstellt werden, die von einem DTrace- oder SystemTap-Skript beobachtet werden können. Dies erleichtert die Überwachung, was CPython-Prozesse auf einem System tun.

CPython Implementierungsdetail: DTrace-Marker sind Implementierungsdetails des CPython-Interpreters. Es werden keine Garantien für die Probenkompatibilität zwischen CPython-Versionen übernommen. DTrace-Skripte können beim Wechseln der CPython-Versionen ohne Vorwarnung nicht mehr funktionieren oder falsch funktionieren.

Statische Marker aktivieren

macOS verfügt über integrierte Unterstützung für DTrace. Unter Linux müssen die SystemTap-Entwicklungswerkzeuge installiert sein, um CPython mit den eingebetteten Markern für SystemTap zu erstellen.

Auf einem Linux-Computer kann dies erfolgen über

$ 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 können Sie verfügbare DTrace-Probes auflisten, indem Sie einen Python-Prozess im Hintergrund ausführen und alle vom Python-Anbieter bereitgestellten Probes auflisten.

$ 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 können Sie überprüfen, ob die statischen SystemTap-Marker im erstellten Binärprogramm vorhanden sind, indem Sie prüfen, ob es einen Abschnitt „.note.stapsdt“ enthält.

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

Wenn Sie Python als gemeinsam genutzte Bibliothek erstellt haben (mit der Konfigurationsoption --enable-shared), müssen Sie stattdessen in der gemeinsam genutzten Bibliothek nachsehen. Zum Beispiel

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

Hinreichend 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 strategisch platzierte Maschinencode-Instruktionen gepatcht werden können, um die von einem SystemTap-Skript verwendeten Tracing-Hooks zu aktivieren.

Statische DTrace-Probes

Das folgende Beispiel-DTrace-Skript kann verwendet werden, um die Aufruf-/Rückrufhierarchie eines Python-Skripts anzuzeigen, wobei nur die Aufrufe einer Funktion namens „start“ verfolgt werden. Mit anderen Worten, Funktionsaufrufe zur Importzeit werden nicht aufgelistet.

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

Es kann wie folgt aufgerufen werden:

$ 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 Low-Level-Weg zur Nutzung der SystemTap-Integration ist die direkte Verwendung der statischen Marker. Dies erfordert, dass Sie die Binärdatei, die sie enthält, explizit angeben.

Zum Beispiel kann das folgende SystemTap-Skript verwendet werden, um die Aufruf-/Rückrufhierarchie eines Python-Skripts anzuzeigen:

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

Es kann wie folgt aufgerufen werden:

$ 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 sind

  • Zeit in Mikrosekunden seit Beginn des Skripts

  • Name der ausführbaren Datei

  • PID des Prozesses

und der Rest die Aufruf-/Rückrufhierarchie während der Ausführung des Skripts angibt.

Für eine `--enable-shared`-Build von CPython befinden sich die Marker in der gemeinsam genutzten Bibliothek libpython, und der gepunktete Pfad der Probe muss dies widerspiegeln. Zum Beispiel muss diese Zeile aus dem obigen Beispiel

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

stattdessen lauten:

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

(unter der Annahme eines Debug-Builds 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.

Der Dateiname, der Funktionsname und die Zeilennummer werden dem Tracing-Skript als positionelle Argumente zurückgegeben, auf die über $arg1, $arg2, $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 Gegenteil von function__entry() und zeigt an, dass die Ausführung einer Python-Funktion beendet wurde (entweder über return oder über eine Ausnahme). Er wird nur für reine Python-Funktionen (Bytecode) ausgelöst.

Die Argumente sind die gleichen wie für function__entry().

line(str filename, str funcname, int lineno)

Dieser Marker zeigt an, dass eine Python-Zeile ausgeführt wird. Er ist das Äquivalent der zeilenweisen Verfolgung mit einem Python-Profiler. Er wird nicht innerhalb von C-Funktionen ausgelöst.

Die Argumente sind die gleichen wie für function__entry().

gc__start(int generation)

Wird ausgelöst, wenn der Python-Interpreter einen Garbage-Collection-Zyklus startet. arg0 ist die zu scannende Generation, wie bei gc.collect().

gc__done(long collected)

Wird ausgelöst, wenn der Python-Interpreter einen Garbage-Collection-Zyklus abschließt. arg0 ist die Anzahl der gesammelten Objekte.

import__find__load__start(str modulename)

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

Hinzugefügt 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 gibt an, ob das Modul erfolgreich geladen wurde.

Hinzugefügt 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-String, arg1 ist ein Zeiger auf PyObject auf ein Tupelobjekt.

Hinzugefügt in Version 3.8.

SystemTap Tapsets

Der höherstufige Weg zur Nutzung der SystemTap-Integration ist die Verwendung eines „Tapsets“: Das Äquivalent einer Bibliothek von SystemTap, das einige der Low-Level-Details der statischen Marker verbirgt.

Hier ist eine Tapset-Datei, basierend auf einem Nicht-Shared-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
}

Wenn diese Datei im Tapset-Verzeichnis von SystemTap (z. B. /usr/share/systemtap/tapset) installiert ist, werden die folgenden zusätzlichen Probenpunkte verfügbar:

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

Dieser Probenpunkt 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 Probenpunkt ist das Gegenteil von python.function.return und zeigt an, dass die Ausführung einer Python-Funktion beendet wurde (entweder über return oder über eine Ausnahme). Er wird nur für reine Python-Funktionen (Bytecode) ausgelöst.

Beispiele

Dieses SystemTap-Skript verwendet das obige Tapset, um das obige Beispiel der Verfolgung der Python-Funktionsaufrufhierarchie sauberer zu implementieren, 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 verwendet das obige Tapset, um eine Top-ähnliche Ansicht aller laufenden CPython-Codes bereitzustellen, die die Top 20 der am häufigsten aufgerufenen Bytecode-Frames pro Sekunde im gesamten System anzeigt.

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