Tiefe Einblicke in Solaris 10 mit Dtrace (Teil III):

Geisterhafte Technik oder Technik, die begeistert?

Teil II der Serie zeigte auf, welche Dinge sich mit Dtrace ausleuchten lassen. Diesmal betrachten wir Dtrace selbst - auf der Grundlage des Skriptes dexplorer aus dem DtraceToolkit.

Aus dem ersten Teil der Reihe in Ausgabe 4/2005 kennen wir die prinzipielle Funktionsweise von DTrace und den rudimentären Aufbau eines D-Skriptes. So wurde unter anderem truss nachgebildet.

In Teil II (Ausgabe 1/2006) haben wir die vorhandenen Messpunkte kategorisiert und somit einen Überblick über mögliche Messungen erlangt. Im Folgenden wollen wir uns der Sprache D genauer widmen und dabei das DtraceToolkit kennenlernen.

Take the easy way

Dtrace bietet unzählige Analysemöglichkeiten, sofern entsprechende Skripte vorhanden sind. Der Aufwand, ein eigenes Analyseskript zu schreiben, lässt sich vermeiden, indem vorgefertigte Skripte genutzt werden.

Als wichtige Skriptsammlung ist das DtraceToolkit von Brendan Gregg zu nennen [1]. Es bietet etwa 70 verschiedene Skripte, womit Fragestellungen zu den unterschiedlichen Themen (Netzwerk, Prozesse, CPU, IO, ...) analysiert werden können.

dexplorer

Das Skript dexplorer sammelt die unterschiedlichen Messdaten. Jede Fragestellung wird in einer separaten Datei beantwortet und alle zusammen werden in ein Tar-Archiv gepackt. Tatsächlich ist dexplorer ein Shellskript, das nacheinander unterschiedliche D-Skripte zur Ausführung bringt. Diese einzelnen Skripte bieten sich an, um daran Dtrace-spezifische Einzelheiten aus dexplorer kennenzulernen. Das gesamte Skript und alle weiteren DtraceToolkit-Skripte finden sich unter [1] .

Externe Variablen

Um die Ausgaben der unterschiedlichen D-Skripte innerhalb von dexplorer mit einer einheitlichen Überschrift zu versehen, wird in der Shell-Variable header der Beginn der dtrace-Skripte inklusive Ausgabe der Überschrift definiert.

Abbildung 1 zeigt den Programmcode, während Abbildung 2 die dadurch entstehende Überschrift darstellt. Es wird deutlich, dass neben dem Datum (walltimestamp), der Betriebssystemname, der Rechnername, die Kernelversion und die Prozessorarchitektur dargestellt werden. Das Skript greift dazu auf Externe Variablen zu.

170  header='dtrace:::BEGIN {
171  printf("%Y, ", walltimestamp);
172  printf("%s %s %s %s %s, ", `utsname.sysname, `utsname.nodename,
173        `utsname.release, `utsname.version, `utsname.machine);
174  printf("%d secs\n",'$interval');
175  }
176  profile:::tick-'$interval'sec { exit(0); }
177  '

2006 May 18 23:48:56, SunOS jupiter 5.10 Generic_118844-26 i86pc, 5 secs

Externe Variablen sind Variablen des zu analysierenden Programms (z. B. des Kernels). Sie erhalten im Skript den Accent grave (`) als Präfix. Häufig kann in Header-Dateien die Definition der Variablen ermittelt werden. Der Aufbau der Struktur utsname ist z. B. in der Datei /usr/include//sys/utsname.h definiert.

Durch die Zeile 176 wird nach einem vordefinierten Messzeitraum das Programm beendet. Ist die Shellvariable $interval z. B mit dem Wert 5 belegt, so wird der Messpunkt profile:::tick-5sec nach 5 Sekunden exit 0 ausführen. Dies führt zur Beendigung der Messung, wobei ein möglicher dtrace:::END Messpunkt noch ausgeführt wird.

Aggregate

Dtrace kennt assoziative Arrays, worin, ähnlich wie bei AWK, Werte gespeichert werden können. Weitaus häufiger als Arrays werden so genannte Aggregate verwendet. Im Unterschied zu den Arrays, wird in einem Aggregat nicht ein einmalig aufgetretener Wert zu einem speziellen Index dargestellt, sondern meist eine Zusammenfassung häufig aufgetretener Werte zu einem bestimmten Index (z. B. der Mittelwert oder die Anzahl).

Gleich das erste Dtrace-Skript "Interrupts by CPU..." innerhalb dexplorer greift zu Aggregaten und ermittelt die Anzahl aufgetretener Interrupts pro CPU (Aggregat: Anzahl pro CPU).

In Abbildung 3 Zeile 244 wird das Aggregat @num[cpu] mit Hilfe der Aggregatsfunktion count() gefüllt. Das Aggregat wird durch das Präfix @ als solches kenntlich. Rechts vom Zuweisungszeichen = darf nur eine Aggregatsfunktion stehen. Einfache Aggregatsfunktionen sind in Abbildung 4 dargestellt.

242  dstatus "Interrupts by CPU..."
243  $dtrace -qn "$header"'
244   sdt:::interrupt-start { @num[cpu] =
245   dtrace:::END
246   {
247       printf("%-16s %16s\n", "CPU", "INTERRUPTS");
248       printa("%-16d %@16d\n", @num);
249   }
250  ' | $clean > Cpu/interrupt_by_cpu

Die Ausgabe eines Aggregats erfolgt implizit am Ende des Skriptes, ohne dafür eine Zeile Programmcode investieren zu müssen. Will der Skriptentwickler die Ausgabe bzw. das Ausgabeformat beeinflussen, so kann er dies mit der Funktion printa tun.

CPU          INTERRUPTS
0                   516

In Abbildung 3 wird in Zeile 248 das gesamte Aggregat mit allen gesammelten Werten ausgegeben. Die dadurch entstehende Ausgabe ist auf dem hier dargestellten Einprozessorsystem nicht sonderlich spektakulär. Sie ist in Abbildung 5 dargestellt und zeigt, wie erwähnt, die Anzahl der aufgetretenen Interrupts pro CPU.

Lokale Variablen und bedingte Zuweisung

Schon das nächste Skript "Interrupt times ..." nutzt alle bisher kennengelernten Techniken und noch weitere. Da Interrupts durch Geräte verursacht werden, soll pro Gerät die Dauer der Interrupt-Behandlung ermittelt werden.

In Zeile 254 wird die Zeit zu Beginn der Interrupt-Bearbeitung mittels vtimestamp ermittelt (Abbildung 6). In Zeile 262 wird die verstrichene Zeit der Interrupt-Bearbeitung durch Subtraktion ermittelt und in einem Aggregat festgehalten.

252  dstatus "Interrupt times..."
253  $dtrace -qn "$header"'
254  sdt:::interrupt-start { self->ts =
255  sdt:::interrupt-complete
256  /self->ts && arg0 != 0/
257  {
258    this->devi = (struct dev_info *)
259    self->name = this->devi != 0 ?
260    stringof('devnamesp[this->devi->.dn_name) : "?";
261    this->inst = this->devi != 0 ?->devi_instance : 0;
262    @num[self->name, this->inst] = (vtimestamp - self->ts);
263    self->name = 0;
264  }
265  sdt:::interrupt-complete { self->
266  dtrace:::END
267  {
268  printf("%11s %16s\n", "DEVICE", "
269  printa("%10s%-3d %@16d\n", @num);
270  }
271  ' | $clean > Cpu/interrupt_time

Damit die Interrupt-Bearbeitung unterschiedlicher Threads unabhängig voneinander analysiert werden kann, wird die Startzeit durch Angabe des Präfixes self-> als Threadlokaler Wert, und damit unabhängig von allen anderen Threads, gespeichert. Die Messwerte sind somit eindeutig getrennt.

Über das Argument arg0 in Zeile 258, welches durch den Messpunkt sdt:::interrupt-complete bereitgestellt wird, wird auf eine externe Struktur zugegriffen und in der Variablen this->-devi hinterlegt. In Zeile 260 wird die Majornumber des Interruptauslösenden Gerätes genutzt, um letztlich den Treibernamen zu ermitteln. Dieser wird in der Variablen self->name hinterlegt.

Für den genauen Aufbau der hier verwendeten Strukturen müssen wiederum die entsprechenden Header-Dateien ermittelt und analysiert werden.

Bitte beachten Sie, dass die Zuweisungen in Zeile 259, 260 und in Zeile 261 bedingte Zuweisungen sind. Zeile 261 meint: Wenn die Variable this->devi nicht den Wert 0 hat, dann nutze den Wert this->devi->devi_instance, sonst nutze den Wert 0. Auf diese Weise werden Treibername und Instanzname als 0 angenommen, wenn die entsprechenden Parameter nicht vorhanden sind.

DEVICE TIME (ns)
ata1                1342875
ata0                9300243

Nun sind alle Parameter bekannt, um sich der Zeile 262 zu widmen. Die verstrichene Zeit wird berechnet und in einem Aggregat festgehalten, welches die Gesamtzeit der Interrupt-Bearbeitung in Abhängigkeit vom Treibernamen (self->name) und vom Instanznamen (this->inst) ermittelt.

Durch die Zuordnung des Wertes 0 in Zeile 263 wird in der Sprache D der Speicher für die Variable self->name deallockiert. Die Ausgabe wird durch die Zeilen 268 und 269 erzeugt und ist in Abbildung 7 dargestellt.

273  dstatus "Dispatcher queue length by CPU..."
274  $dtrace -qn "$header"'
275     profile:::profile-1000
276     {
277     this->num = curthread->t_cpu->cpu_disp->disp_nrunnable;
278     @length[cpu] = lquantize(this->num, 0, 100, 1);
279     }
280   dtrace:::END { printa(" CPU %d%@d\n", @length);}
281  ' | $clean > Cpu/dispqlen_by_cpu

Histogramme

Das nächste Skript "Dispatcher queue length by CPU ..." ist wieder etwas kürzer, bietet jedoch ein Highlight. In Zeile 277 (Abbildung 8) wird über die Dtrace-Built-In Struktur cur-thread die Anzahl wartender Threads für eine CPU ermittelt. Das Aggregat @length[cpu] wird in Zeile 278 mit diesem Wert durch die Aggregatsfunktion lquantize gefüllt. Dadurch wird bei der Ausgabe pro CPU ein Histogramm erstellt.

CPU 0
value ------- Distribution ------- count
< 0 |                                0
0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4829
1 |                                  54
2 |                                  8
3 |                                  1
4 |                                  1
5 |                                  1
6 |                                  0

In Abbildung 9 sehen wir, dass während des Messzeitraums 4829 mal 0 Threads auf CPU-Zeit gewartet haben. 54 mal war genau ein Thread in der Warteschlange des Prozessors 0. 8 mal warteten 2 Threads. Einmal warteten 3, einmal 4 und einmal 5 Threads. 6 oder mehr Threads und weniger als 0 Threads warteten nie auf die CPU 0. Da es sich bei dem fraglichen System um eine Einprozessormaschine handelt, werden keine weiteren Histogramme angezeigt.

Beim Aufruf der Funktion lquantize() in Zeile 278 wurde neben dem zu messenden Wert noch der Bereich (0 bis 100) und die Stufenweite (1) angegeben. Die Funktion quantize liefert demgegenüber ein logarithmisches Histogramm. Die Angabe der Schrittweite beziehungsweise der Bereichsgrenzen ist dabei nicht notwendig (siehe Abbildung 10).

Die weiteren D-Skripte

Die weiteren D-Skripte innerhalb von dexplorer sind ähnlich aufgebaut und bieten uns keine grundlegend neuen Erkenntnisse. Für die detaillierte Analyse der verwendeten Kernelstrukturen müssen häufig der "Solaris Dynamic Tracing Guide" und die Header-Dateien im Verzeichnis /usr/include als Informationsquelle herangezogen werden.

Fazit

Es wird deutlich, wie mächtig Dtrace ist und welche Techniken zur Analyse angewendet werden können. Ein Blick auf das DtraceToolkit lohnt sich, denn auch die weiteren Skripte sind lesenswert und ermöglichen Erkenntnisse über das System, die sich ohne Dtrace wahrscheinlich nur vermuten ließen.

Markus Schreier (info@ordix.de).

Seitenanfang

Seite drucken

Seite weiterempfehlen