Tiefe Einblicke in Solaris 10 mit DTrace (Teil II):

Mit DTrace "Ecken ausleuchten"

In der ORDIX News 4/2005 sind wir in das Thema DTrace eingestiegen. Mit diesem Artikel wird ein Schritt mehr Vertrautheit im Umgang mit DTrace erreicht, indem wir verdeutlichen, welche Systemeigenschaften sich mit Providern analysieren lassen.

Der Hauptteil dieses Artikels wird sich mit Messpunkten befassen, beziehungsweise mit den Providern, die diese Messpunkte bereitstellen. Einleitend möchten wir deshalb eine ausgereifte Skriptsammlung darstellen: Das DTraceToolkit. In vielen Fällen reichen diese "fertigen" Skripte schon für eine Analyse aus.

DTraceToolkit

Mit über 80 Skripten ist das DTraceToolkit [1] sehr umfassend. Für eine flexiblere Handhabung sind die Skripte teilweise in Perl oder Shell geschrieben. Das eigentliche D-Skript wird darin definiert und kommt dann zur Ausführung.

Durch dieses Vorgehen ist es möglich, Parameter auszuwerten, die den genauen Aufbau des D-Skriptes und somit die Ausgabe beeinflussen. Außerdem finden sich unter [1] zu allen Skripten Man Pages, Beispiele und teilweise noch zusätzliche Erklärungen.

Provider

Für eine Analyse ist es notwendig, relevante Messpunkte zu aktivieren. Sobald ein Thread einen aktivierten Messpunkt durchläuft, "zündet" dieser (im Englischen: "the probe fires") und der zum Messpunkt gehörige Anweisungsblock wird ausgeführt.

Die Informationen des Messpunktes werden gesammelt und angezeigt. Von circa 20 unterschiedlichen Providern werden über 30.000 Messpunkte bereitgestellt. Im Folgenden stellen wir diese Provider vor und betrachten einige Beispiele.

Anfang und Ende
(dtrace-Provider)

Der dtrace-Provider stellt die Messpunkte dtrace::: BEGIN dtrace:::END und dtrace:::ERROR bereit. BEGIN wird vor allen anderen Messpunkten ausgewertet. Er kann genutzt werden, um notwendige Initialisierungen durchzuführen oder eine Überschrift zu erzeugen. END wird nach allen anderen Messpunkten durchlaufen. BEGIN und END entsprechen den namensgleichen Blöcken in awk.

In unserem Beispiel in Abbildung 1 werden die Read- und Write-Aktivitäten gezählt und jede Sekunde ausgegeben. Im BEGIN-Messpunkt dieses Beispiels wird die Überschrift erzeugt. Der END-Messpunkt wird dazu genutzt, um gesammelte (summierte) Informationen auszugeben.

1 #!/usr/bin/dtrace -qs
2 dtrace:::BEGIN
3 {
4 printf("%20s %7s %7s\n",
  "Time", "sread/s", "swrit/s");
5 }
6
7 sysinfo:::sysread { sread++; }
8 sysinfo:::syswrite { swrit++; }
9 profile:::tick-1sec
10 {
11 printf("%20Y %7d %7d\n", walltimestamp, sread, swrit);
12 sread = 0; swrit = 0;
13 }

Der ERROR-Messpunkt wird bei Laufzeitfehlern durchlaufen und dient der Fehlerbehandlung.

Metronom
(profile-Provider)

Der profile-Provider stellt Messpunkte bereit, die in regelmäßigen Intervallen zünden. Hochfrequente Intervallzeiten bis hin zu 200 Mikrosekunden sind möglich.

Die Intervalldauer wird an den Namen des Messpunktes mit der entsprechenden Einheit angehängt (z. B. profile:::profile-tick-10ns). Die möglichen Suffixe mit den entsprechenden Zeiteinheiten sind in Abbildung 2 dargestellt.

Die profile-<n> Messpunkte zünden regelmäßig auf allen CPUs. Es können somit z. B. Statistiken über die auf den CPUs laufenden Prozesse ermittelt werden. Die profile-tick-<n> Messpunkte zünden nur auf einer CPU. Sie dienen z. B. der Ausgabe von Informationen, die durch andere Messpunkte gesammelt wurden.

Es lässt sich somit z. B. das Verhalten von sar nachbauen, welches in regelmäßigen Intervallen die aktuelle Auslastung bzw. die Häufigkeit bestimmter Ereignisse darstellt.

In Abbildung 1 werden in Zeile 7 und 8 Lese- und Schreibereignisse gezählt. Jede Sekunde (Zeile 9) werden die Zähler zusammen mit dem aktuellen Zeitstempel (Zeile 11) ausgegeben. Nach einer
Ausgabe werden die Zähler wieder auf 0 zurückgesetzt (Zeile 12).

Truss+
(syscall-Provider)

Schon im ersten Teil der Artikelreihe, in der ORDIX News 4/2005, nutzten wir den syscall-Provider. Er stellt für jeden Systemcall einen Entry und einen Return-Messpunkt bereit. Diese Messpunkte erlauben es, z. B. truss nachzubauen.

Mit DTrace ist aber mehr denkbar: So können recht einfach Statistiken über die verwendeten Systemcalls erstellt werden, indem z. B. dargestellt wird, wie lange ein Systemcall gedauert hat. Dies wird erreicht, indem die Differenz der Zeitstempel beim Entry- und Return-Messpunkt gemessen wird.

Das Beispiel aus der letzten ORDIX News wurde in Abbildung 3 um die Zeilen 7, 13 und 14 ergänzt. In Zeile 7 wird für jeden Thread separat der aktuelle Zeitstempel (in Nanosekunden) festgehalten.

1 #!/usr/sbin/dtrace -qs
2
3 syscall:::entry
4 /pid == $target/
5 {
6     printf("%s(%d, 0x%x, %4d)", probefunc, arg0, arg1, arg2) ;
7     self->start = timestamp ;
8 }
9 syscall:::return
10 /pid == $target/
11 {
12    printf("\t\t = %d\t", arg1) ;
13    printf("Time: %d microsecs\n", (timestamp - self->start) /1000) ;
14    self->start = 0 ;
15 }

In Zeile 13 wird die verstrichene Zeit berechnet und das Ergebnis direkt ausgegeben. In Zeile 14 wird die nicht mehr benötigte Variable auf 0 gesetzt, da dies unter DTrace gleichzeitig den verwendeten Speicherplatz wieder freigibt.

Userlandtracing
(pid-Provider)

Der pid-Provider bietet für jeden Funktionsaufruf eines jeden Prozesses eigene Messpunkte. Bei der Angabe des Messpunktes wird die Prozess- ID des zu überwachenden Prozesses schon im Namen des Providers angegeben. Die Verwendung von Variablen ist möglich. Der Messpunkt in Zeile 2 der Abbildung 4 zündet bei allen libc-Aufrufen eines angegebenen Prozesses.

1 #!/usr/sbin/dtrace -s
2 pid$target:libc::entry
3 {
4  @[probefunc]=count()
5 }

Pauschal alle Funktionsaufrufe eines Prozesses durch DTrace zu analysieren, ist wenig sinnvoll. Das Ergebnis ist zu umfangreich und damit eher unbrauchbar. Der Aufruf von ls in einem kleinen Verzeichnis erzeugt in unserer Testumgebung insgesamt 5870 Funktionsaufrufe von 271 verschiedenen Funktionen.

Wann komme ich dran?
(sched-Provider)

Der sched-Provider bietet unter anderem Messpunkte, die zünden

• wenn ein Prozess seine Priorität verändert bekommt,
• wenn dieser einem Prozessor zugeteilt wird oder
• wenn er von einem wieder heruntergenommen wird.

Das Skript in Abbildung 5 stellt dar, wie lange welcher Prozess eine CPU zugeteilt bekam. Die beiden Messpunkte (Zeile 1 bzw. Zeile 5) zünden genau dann, wenn ein Thread die CPU zugeteilt bekommt beziehungsweise wenn er sie wieder verliert.

1 sched:::on-cpu
2 {
3 self->ts = timestamp;
4 }
5 sched:::off-cpu
6 /self->ts/
7 {
8  printf ( "%10s %d\n", execname, ( timestamp - self->ts ) ) ;
9  self->ts = 0;
10 }

Aggregatfunktionen ermöglichen es, die Ausgabe (siehe Abbildung 6) zu optimieren, doch möchten wir dieses Skript lieber einfach halten.

    sched 44475
     sshd 1391862
       sh 3235674
    xauth 13884316
    sched 33131
    xauth 252894
       sh 464464
    sched 9627974
    xauth 799826
    sched 61670
    sched 1380158
    sched 1641965
      ksh 12031592
  fsflush 707995
      ksh 4370410
      

Wer sperrt wann was?
(lockstat- und plockstat-Provider)

Bestimmte Zugriffe dürfen von unterschiedlichen Threads nicht gleichzeitig ausgeführt werden. Um solche gleichzeitigen Zugriffe zu verhindern, wird die entsprechende Ressource gesperrt (locking).

Das Locking-Verhalten im Kernel kann durch den lockstat-Provider erforscht werden. Auch das bisher unter Solaris vorhandene Unix-Kommando lockstat nutzt nun den lockstat-Provider, um entsprechende Daten anzuzeigen. Der plockstat-Provider bietet für Locking-Mechanismen im User-Land die entsprechenden Messpunkte.

Beide Provider bieten prinzipiell zwei Arten von Messpunkten:

Diese werden bei jedem Zugriff auf einen Sperrmechanismus durchlaufen. Allein die Kernel-Sperrmechanismen werden auf einem gut ausgelasteten Solaris-System in einer Größenordnung von mehreren Millionen mal pro Sekunde und CPU angefordert oder freigegeben. Die Aktivierung eines solchen Messpunktes kann somit durchaus die Performance des Gesamtsystems beeinflussen.

Sie werden nur gezündet, wenn ein Thread auf einen anderen warten muss. Diese Fälle sollten möglichst selten eintreten. Die Aktivierung eines contention-event-Messpunktes stellt somit keine Beeinflussung für das Gesamtsystem dar.

Von "Gabeln" und der "Exekutive" − fork and exec
(proc-Provider)

Das Entstehen eines neuen Prozesses durch fork und das meist anschließende überlagern mittels exec() kann durch Messpunkte des proc-Providers analysiert werden. Separate Messpunkte werden im Fehlerfall gezündet.

Auch das Beenden von Prozessen oder der Empfang von Signalen wird durch Messpunkte des proc-Providers greifbar. Das Beispiel in Abbildung 7 gibt aus, welcher Prozess von welchem anderen durch exec überlagert wurde.

1 #!/usr/sbin/dtrac –qs
2 proc:::exec
3 {
4     self->parent = execname;
5 }
6 proc:::exec-success
7 /self->parent != NULL/
8 {
9     @[self->parent, execname] = count();
10    self->parent = NULL;
11 }
12 proc:::exec-failure
13 /self->parent != NULL/
14 {
15    self->parent = NULL;
16 }
17 END
18 {
19    printf("%-20s %-20s %s\n", "WHO", "WHAT", "COUNT");
20    printa("%-20s %-20s %@d\n", @);
21 }

Aufgerufen wird exec von dem Prozess, der zunächst geklont wurde und nun überlagert werden soll (quasi beendet sich der geklonte Vater dadurch selbst). In den Zeilen 2 bis 5 wird der Prozessname in der Variablen self->parent (Zeile 4, execname) für den aktuellen Thread festgehalten. Ist exec erfolgreich abgeschlossen, so ist der Prozess überlagert und wir finden als Prozessname den neuen Prozess (Zeile 9, execname).

Wie oft das Wertepaar self->parent, execname auftritt, wird in Zeile 9 gezählt. Im END-Messpunkt werden eine Überschrift (Zeile 19) und alle bisher festgehaltenen Wertepaare mit dem aktuellen Zählerstand (Zeile 20) ausgegeben. Durch Zeile 10 und Zeile 15 werden nicht mehr benötigte Variablen auf Null gesetzt und somit freigegeben.

Selbstgebacken
(sdt-Provider)

Anwendungsentwickler können in ihren Anwendungen auch eigene Messpunkte definieren. Diese Messpunkte werden durch den sdt- Provider bereitgestellt. Auch im Kernel finden sich einige Messpunkte, die über den Statically Defined Tracing (sdt)-Provider bereitgestellt werden. In zukünftigen Solarisversionen können diese Messpunkte jedoch hinsichtlich des Namens und des Verhaltens verändert worden sein.

Statistiken
(sysinfo- und vminfo-Provider)

Der Kernel hält eigene Statistiken in der Sysund in der vm-Struktur bereit. In der erstgenannten wird z. B. die User-, Sys-, Wait-IO- oder Idle-Time der CPU nachgehalten. Bisher konnten diese Informationen nur mit den Unix-Kommandos mpstat, vmstat oder sar ausgewertet werden.

Für diese Kernel-Statistiken gibt es eigene Provider. Vor der Veränderung eines Wertes zündet der entsprechende Messpunkt des sysinfo- Providers bzw. des vminfo-Providers.

Statistiken II (io-Provider)

Engpässe bei der Ein- und Ausgabe sind häu- fig der Grund für Performance-Probleme. Der io-Provider stellt Messpunkte bezüglich Platten- IO bereit. Das Unix-Kommando iostat zeigt die Daten wie bisher an. Bei Veränderung der damit sichtbaren Daten zünden Messpunkte des io-Providers.

Rechnen oder Rechnen lassen
(fpuinfo-Provider)

Heutige Prozessoren bieten eine eigene Floating Point (FP)-Arithmetik. Nur wenige FP-Befehle müssen durch den Kernel simuliert werden. Welche Befehle das sind, hängt stark von dem tatsächlichen Microprozessor ab. Nutzt eine Applikation häufig einen simulierten Befehl, kann dies zu Performance-Einbußen führen.

Anzeigen lassen sich entsprechende Statistiken mit dem kstat- oder dem trapstat-Befehl. Der fpuinfo-Provider stellt die dazugehörigen Messpunkte bereit.

Spurensuche für Unentwegte
(fbt-Provider)

Die meisten Funktionen im Kernel können durch einen Entry- und einen Return-Messpunkt analysiert werden. Bereitgestellt werden diese Messpunkte durch den Function Boundary Tracing (fbt)-Provider. Dieser Provider liefert auf unserem System über 33.000 Messpunkte für 144 verschiedene Module.

Für ein gutes Verständnis dieses Providers sind Kernel-Architekturkenntnisse notwendig. In dem oben erwähnten DTraceToolKit werden diese Provider für die Netzwerkanalyse und für die Analyse des Pufferverhaltens bei Dateisystemzugriffen verwendet.

dtrace -n fbt:ufs::entry '{@a[probefunc] = count()}'

Fazit

Der Artikel stellte die unterschiedlichen Provider vor und zeigt einige Anwendungsbeispiele. Für eine aussagekräftige Analyse müssen die richtigen Messpunkte gefunden werden. Welche Provider für bestimmte Fragestellungen weiterhelfen können, wurde in diesem Artikel deutlich.

Neben der Kenntnis der Provider und damit dem Wissen von der Existenz der Messpunkte können weitere Eigenschaften der Programmiersprache D ergründet werden. Dies wird in einer der nächsten ORDIX News folgen.

Markus Schreier (info@ordix.de).

Seitenanfang

Seite drucken

Seite weiterempfehlen