Problemerkennung mit Dtrace

Sun hat mit Dtrace ein Tracing-Framework in Solaris 10 eingeführt, das die einfache Problemerkennung während des Betriebs ermöglicht.

Artikel erschienen in Swiss IT Magazine 2008/03

Plötzlich wird ein Server unerträglich langsam. Die Netzlast hält sich laut Kollegen der Netzabteilung aber im grünen Bereich. Die Zahl der Plattenzugriffe ist zwar erhöht, aber auch nicht alarmierend. Welcher Prozess bremst das System aus? Oder warum stürzt ein gestern noch laufendes Programm bei bestimmten Operationen reproduzierbar nach 3 Minuten Laufzeit ab? Bei welcher Bibliothek wird ein Core File generiert?

Solche Fragen beschäftigen einen Systemadministrator regelmässig. Werkzeuge wie truss (Solaris), strace (Linux) oder ktrace (Mac OS, BSD) dienen dazu, sogenannte System Calls (Aufrufe von Systemprozeduren) zu verfolgen und einigermassen zu sehen, was ein Prozess macht. Leider ist es schwer, der erzeugten Datenflut Herr zu werden und das herauszufiltern, was wirklich interessant ist. Ausserdem verlangsamen diese Werkzeuge die Ausführung des Prozesses, welcher überwacht wird. Wer ganz tief ins System einsteigen möchte, kann auch auf Werkzeuge zum Kernel Debugging zurückgreifen. Dies führt aber meistens viel zu weit und erfordert ein wirklich tiefes Verständnis des jeweiligen Betriebssystems.

Architektur von Dtrace / Dtrace-Beispiel

Neuer Ansatz

Einen vollkommen neuen Ansatz zur Problemerkennung hat Sun mit Solaris 10 eingeführt. Unter dem Namen Dtrace wird ein Werkzeugkasten geliefert, welcher Systemadministratoren und Entwicklern gleichermassen die Arbeit erleichtern soll.

Im Wesentlichen besteht Dtrace aus sogenannten Providern und einer interpretierten Programmiersprache namens D, die aber nichts mit einer anderen, älteren, Programmiersprache namens D zu tun hat. Ein Provider ist eine Art Messpunkt im Kern, in den Bibliotheken oder in eigenen Programmen. Ein aktuelles Solaris-10-System hat rund 47’000 Provider, ein Mac OS X 10.5 knapp 23’000. Die Zahl der Provider variiert je nach installierter Software, Patches und Betriebssystemversion und erhöht sich stetig.

Ein D-Programm kommuniziert nun über die Bibliothek libdtrace mit den Messpunkten. Das Auslesen der Provider geschieht asynchron. Das bedeutet, dass der Kern oder die Bibliothek nicht warten muss, bis die ausgelesenen Werte im D-Programm angekommen sind. Dadurch hat Dtrace trotz Zugriff auf einen aktiven Provider kaum messbare Auswirkungen auf ein laufendes System. Nicht verwendete Provider, von denen es mehrere Tausend in einem System gibt, haben überhaupt keine Auswirkung auf die Leistung.

Ein Beispiel für so einen Provider ist syscall:::entry. Es markiert den Einsprung in einen Systemaufruf. Wie man sieht, hat ein Provider die Form Provider:Modul:Funktion:Name. «Modul» beschränkt die Abfrage auf ein bestimmtes Kernel-Modul, «Funktion» auf eine Funktion des Providers. Würde man hier als Beispiel fstat angeben, würde man nur Werte bekommen, die ein Systemaufruf von fstat erzeugt. Das letzte Argument ist der Messpunkt selbst. Im Beispiel wird also beim Aufruf (Einstieg) eines System Calls die Aktion ausgeführt. Andersherum würde sycall::open:return nur die Rückgabewerte des Systemaufrufs open zurückgeben.

Skripterei

Die Funktionsweise eines D-Scripts lässt sich am besten anhand eines Beispiels illustrieren (siehe Kasten «Dtrace-Beispiel»). Wie man sieht, besteht ein D-Skript aus einem oder mehreren Blöcken. Am Anfang jedes Blocks wird der Provider definiert, welcher durch zusätzliche Bedingungen eingeschränkt werden kann. Der erste Block im Beispiel verwendet den bereits erwähnten Provider syscall:::entry. Dieser würde nun alle Einsprung-Ereignisse in Systemaufrufen protokollieren. Da dies aber weder gewünscht noch praktikabel ist, wird die Protokollierung durch die Angabe einer Prozess-ID eingeschränkt. Die gewünschte Prozess-ID kann entweder im Script hart codiert oder per Umgebungsvariable $target referenziert werden. Die Umgebungsvariable steht aber nur zur Verfügung, wenn das zu überwachende Programm über Dtrace und das Kommandozeilenargument -c gestartet wird.

Im nächsten Teil des Blocks wird angegeben, was mit den vom Provider erhaltenen Daten gemacht werden soll. Im Beispiel werden diese auf den Bildschirm ausgegeben. Dazu verwenden wir die von C bekannte Syntax von printf. Ausgegeben werden der Name des Systemaufrufs und die Argumente.

Um unser Beispiel an die Ausgabe von truss weiter anzulehnen, geben wir auch noch das Ende des Systemaufrufs mit dem Exit Code aus. Dazu wird ein weiterer Block benötigt. Wieder definieren wir einen Provider mit denselben Einschränkungen, statt syscall:::entry wird einfach syscall:::return abgefragt.

Nebst $target steht noch eine Reihe von weiteren Makros zur Verfügung, mit denen sich ebenfalls Filter realisieren lassen: $pid für die Prozess-ID des Dtrace-Prozesses selbst, $gid für die Gruppen-ID oder $euid für die effektive User-ID. Neben diesen für einen Dtrace-Aufruf festen Variablen gibt es auch noch dynamische Variablen. Einige Beispiele wären $cwd, für das aktuelle Verzeichnis des Prozesses, $cpu für die Prozessor-ID, auf dem das Programm gerade läuft, $errno für die Fehlernummer des letzten Systemaufrufs oder $timestamp für relative Zeitmessungen.

Um die Überwachung zu beginnen, muss das Dtrace-Script gestartet werden. Dabei muss man beachten, dass der D-Compiler (/usr/sbin/Dtrace) spezielle Privilegien benötigt, die entweder als root oder für normale Anwender mit den passenden RBAC (Role Based Access Controls) gegeben sind.

Von C nach D

Wie das Beispiel zeigt, ist die Erstellung eines einfachen Scripts keine Hexerei. Auch sonst ist die zu Grunde liegende Sprache D nicht schwer zu erlernen. Kenntnisse in C sind aber hilfreich. Auch sollte man zumindest das fundemantalste Basiswissen über Prozess- und Kern-Architektur haben, um selber D- beziehungsweise Dtrace-Skripte zu schreiben. Hilfe erhält man auch im Web. Brendan Gregg stellt beispielsweise auf seiner Webseite (www.brendangregg.com/Dtrace.html) eine Auswahl von Dtrace-Einzeilern sowie ein nützliches Dtrace Toolkit zum Download bereit. Mit Hilfe dieses Toolkits kann man viele in der Praxis auftretenden Probleme analysieren, ohne gleich selbst Hand anlegen zu müssen. Mit folgendem Beispiel kann man die Anzahl der Systemaufrufe der laufenden Prozesse ausgeben:

dtrace -n 'syscall:::entry{ @[execname] = count(); }'

Bricht man das Skript nach einiger Zeit – etwa mit ^c – ab, bekommt man eine Auflistung, welcher Prozess wie viele Systemaufrufe ausgeführt hat:

dtrace: description 'syscall:::entry' matched 230 probes

svc.configd 1

svc.startd 1

sendmail 6

sshd 12

xntpd 20

dtrace 1734

Wer wissen möchte, welche Dateien ein Prozess – beispielsweise der SSH-Daemon – öffnet, könnte folgendes Skript dazu verwenden:

#!/usr/sbin/dtrace -qn

syscall::open*:entry

execname == 'sshd'

{

printf('%s\n',

copyinstr(arg0));

}

Problemerkennung

Dtrace ist aber nicht nur ein Ersatz für truss und Konsorten oder dazu geeignet, Statistiken auszugeben. Es vereinfacht tatsächlich die Analyse beziehungsweise die Suche von Problemen in einem System.
Ein Beispiel: Ein Server leidet unter einer relativ hohen Load. Zwar kann mit top oder prstat ermittelt werden, welcher Prozess die hohe Last verursacht, nicht aber, was deren Ursache ist. Mit Dtrace ist dies nun aber möglich.
Dazu benötigt man den Provider profile. Dieser kann als eine Art Taktgeber verwendet werden, der soundsooft pro Sekunde (in folgendem Beispiel 1000 Mal) eine Dtrace-Abfrage abfeuert. Diese ermittelt, welcher Prozess einen der im System vorhandenen Prozessor beansprucht und gibt aus, wie oft dies der Fall war:

# dtrace -n 'profile-1000 { @[execname] = count(); }'

dtrace: description 'profile-1000' matched 1 probe

samu 2

esd 4

dtrace 23

samfsrestore 40

fsflush 205

scp 395

sam-arcopy 577

sshd 1566

sched 7032

Wie man sieht, verbraucht der SSH-Daemon gleich nach dem System Scheduler am meisten Rechenzeit. Jetzt kann man anhand der Prozess-ID des SSH-Daemon weitere Analysen vornehmen. Im nächsten Beispiel wird untersucht, welche Systemaufrufe von diesem Prozess am meisten verwendet werden:

# dtrace -p 21853 -n 'pid$target:::entry{ @[probefunc] = count(); }'

dtrace: description 'pid$target:::entry' matched 10234 probes

debug2 30

do_log 30

[...]

memcpy 51998

memset 52247

AES_decrypt 146030

Damit weiss man nun, dass der Prozess die meiste Zeit beim Decodieren der mit AES verschlüsselten SSH-Verbindung verbraucht.