Über unsMediaKontaktImpressum
Dr. Harald Däubler & Thomas Nau 14. Juli 2015

DTrace – The hidden treasure

Die Echtzeit-Analyse sowohl von Anwendungen, als auch des Kernels gewinnt – besonders durch die weiterhin stark zunehmende Virtualisierung – noch mehr an Bedeutung als schon in den vergangenen Jahren. Hierbei stehen im Zeitalter von großen multitenant Wirtsystemen und Big Data vor allem die weitreichenden Wechselwirkungen zwischen einer Vielzahl unterschiedlichster virtualisierter Gastsysteme, deren Anwendungen und den Kernel Subsystemen, die wesentliche Aufgaben zu erfüllen haben, im Vordergrund. In der genannten Umgebung sind dies in erster Linie das IO-Subsystem und der Netzwerk-Stack. Die Überwachung von CPU-Performance-Charakteristiken hat hier oft geringere Priorität.

Seit ihrem Erscheinen in Solaris 10 in 2005 hat die dynamic tracing facility (DTrace) neue Maßstäbe im Bereich der Echtzeitanalyse von UNIX-Systemen gesetzt und ist auch heute noch das Tool, an dem sich andere Werkzeuge messen lassen müssen. Darüber hinaus wird es im Solaris-Umfeld von Oracle aktiv weiter ausgebaut und insbesondere an die Weiterentwicklungen im Solaris-Kernel – etwa dem in Version 11 komplett überarbeiteten Netzwerk-Stack – angepasst. DTrace ist heute auch in FreeBSD und MacOS verfügbar wenngleich nicht im selben Funktionsumfang wie in Solaris [1].

Zu unrecht gehen jedoch auch heute viele Systemadministratoren, Anwender und auch Entwickler immer noch fälschlicherweise davon aus, dass DTrace nur für Kernel-Hacker zu bedienen und zu nutzen ist. Dem ist mitnichten so, wobei ein Grundverständnis für die Funktionalität von UNIX-Kerneln allerdings hilfreich ist. Belegt wird dies durch zahlreiche Beispiele aus den Bereichen Performance-Analyse und Systemadministration aber auch aus der Anwendungsentwicklung. Oft reichen wenige Zeilen D – der Programmiersprache von DTrace – um eine Vielfalt an Informationen zu gewinnen, die anderweitig nicht zugänglich wären. Durch die Berücksichtigung des Gesamtsystems erreichen Entwickler zudem eine höhere Qualität bei der Ermittlung von Performancedaten ihrer Anwendung.

Historie

Die Erfassung von System- und insbesondere Performance-Daten, ist für die Planung und zur Analyse von Problem- und Fehlerfällen unerlässlich für den Betrieb einer zentralen IT-Infrastruktur. Entsprechende Tools sind daher – wenngleich in unterschiedlicher Qualität – seit jeher Bestandteil der zum Einsatz kommenden Betriebssysteme bzw. deren Distributionen. Diese Tools lassen sich, charakterisiert durch die zu Grunde liegende Technik, in folgende Gruppen einteilen:

Statistische Tools

Anwendungen dieser Gruppe, etwa iostat(1m) und netstat(1m), liefern statistische Aussagen, wie Mittelwerte für Zeitintervalle, basierend auf exakt ermittelten Werten wie etwa der Anzahl übertragener Bytes. Im Solaris Umfeld ist kstat(1m) ein wenig bekanntes, jedoch sehr mächtiges Tool dieser Gattung, das den Zugriff auf alle statistischen Daten des Solaris Kernels über eine C-API, perl-Module oder mittels Kommandozeile ermöglicht. Das Beispiel demonstriert den einfachen Zugriff auf die aktuelle Größe des ZFS ARC Caches.

neo# kstat -p ::arcstats:data_size ::arcstats:c 5 
zfs:0:arcstats:data_size        28731798784
zfs:0:arcstats:c                34324350096

zfs:0:arcstats:data_size        28676683008
zfs:0:arcstats:c                34209666896

Auch Mike Harsch's arcstat.pl-Tool verwendet die perl-kstat-Schnittelle [2].

neo# arcstat.pl 5
Time      read miss miss% dmis dm% pmis pm% mmis mm% arcsz    c  
12:01:12    2G  92M     3  30M   1  61M  76  70M   3   31G  31G  
12:01:17   331    2     0    1   0    1   1    0   0   31G  31G
...

Vorteilhaft ist die Tatsache, dass sich mit dieser Gruppe von Tools sehr schnell ein grober Überblick über den Zustand einzelner Kernelkomponenten verschaffen lässt. Gravierend ist jedoch, dass sich kritische Werte nicht Anwendungen oder Nutzern zuordnen lassen.

Sampling Tools

Die beiden bekanntesten Vertreter, top(1) und prstat(1m), unterliegen wie alle anderen Vertreter dieser Gruppe den Beschränkungen ähnlich denen des Nyquist-Shannon Abtasttheorems [3]. Das gezielte periodische sampling erlaubt die Erfassung einer Vielzahl von Parametern und deren Korrelation beispielsweise mit Anwendungen oder Nutzern. Kurzlebige Spitzenlasten sind jedoch mit dieser Gruppe von Tools im Allgemeinen nicht erfassbar, da typische Samplingraten nahezu immer mehrere Größenordnungen über der Dauer einzelner Events liegen können. Abb.1 verdeutlicht die Diskrepanz zwischen aufaddierter CPU-Zeit und der Last des Systems im Sinne des load-Parameters.

Eventbasierte Tools

Zu diesen gehören neben Debuggern auch Tools wie truss(1), strace(1) aber insbesondere auch die moderneren dtrace(1) und perf(1). Allen gemeinsam ist die Instrumentierung von Anwendungen und ggf. auch des Kernels dahingehend, dass bestimmte Ereignisse eine Monitoring-Funktion auslösen. Im Falle der beiden erstgenannten beschränkt sich dies auf System- oder Funktionsaufrufe in Bibliotheken. Erschwerend kommt hinzu, dass für das Auslesen einiger Prozessdaten dieser gestoppt und anschließend fortgesetzt werden muss. Das hat erheblichen Einfluss auf das zeitliche Verhalten einer Anwendung und kann die Erkennung von transienten Fehlern oder Störungen unmöglich machen. Auch die Korrelation von Daten unterschiedlicher Prozesse ist hierbei nur mangelhaft möglich. Die beiden letztgenannten Tools hingegen haben diese Schwachstellen nicht, sondern bieten viel weitreichendere Möglichkeiten.

Die Lösung: DTrace

A process cannot be understood by stopping it. Understanding must move with the flow of the process, must join it and flow with it. [4]

Durch seine dynamische Struktur bietet DTrace in den allermeisten Fällen eine Lösung für die im vorherigen Abschnitt beschriebenen Probleme und erlaubt eine kombinierte Sicht auf Anwendung und Kernel.

Probes

Erreicht wird dies durch sogenannte probes – Triggerpunkte –, die dynamisch im Kernel, seinen Modulen, aber auch der Anwendung und gelinkten Bibliotheken zur Laufzeit (de)aktiviert werden können. Die Aktivierung hat im Allgemeinen nur einen zu vernachlässigenden Einfluss auf die Performance des Systems. 

Wird im Programmfluss eine aktivierte probe ausgelöst, sind vielfältige Aktionen möglich. Diese reichen von der einfachen Sammlung bzw. Ausgabe von Werten bis hin zur Manipulation derselben.

Abb.2 zeigt die Grobstruktur der DTrace-Integration in den Solaris-Kernel. Vergleichbares gilt auch für FreeBSD oder MacOS. Erwähnenswert ist, dass die Nutzung vieler DTrace-Techniken ohne root-Rechte möglich ist. Die Autorisierung geschieht im Falle von Solaris über privileges bei gleichzeitiger Einschränkung des sichtbaren scope.

Provider

Provider – DTrace-Kernkomponenten mit dedizierten Aufgaben – stellen bei Solaris 11-Systemen 100.000 und mehr probes zur Verfügung und gruppieren diese funktionell. Etwa 90% dieser probes sind dem function boundary trace provider (FBT) zuzuordnen, der die Einsprung- und Rückkehrpunkte der Solaris Kernel Routinen widerspiegelt.

Die wichtigste Aufgabe der provider ist jedoch die Bereitstellung der Daten in aufbereiteter Form. Etwa stehen IP-Adressen als string und nicht in Binärform zur Verfügung. Neben den üblichen Datenstrukturen lassen sich auch User- und Kernel-Stacks sowie ganze Speicherbereiche sichern. Dies geschieht pro CPU – im Sinne des Kernels – in Datenbereichen innerhalb des Kernels. Deren Größe und Organisation, etwa als Ringpuffer, ist individuell zur Laufzeit konfigurierbar. DTrace stellt auch die notwendigen Funktionen zur Verfügung, um Daten zwischen den Adressbereichen des Kernels und der Anwendung zu kopieren. Ein schreibender Zugriff auf Datenstrukturen ist nur in Einzelfällen möglich, um die Sicherheitsfunktionen und die Datenintegrität des Kernels nicht zu unterlaufen.

Neue provider werden im Rahmen von major-releases eingeführt. Hier lohnt ein Blick in die release notes. In Solaris 11 waren dies u. a. die ip-, tcp-, udp- und iscsi-provider. Neu ist auch der Zugriff auf die Hardware performance-counter moderner CPUs mit Hilfe des cpc-providers. Die hardwarenahe Natur bringt allerdings auch einige Randbedingungen hinsichtlich der Verfügbarkeit von probes mit sich.

Name Funktion
io Liefert detaillierte Informationen über IO-Operationen auf Platten, Bändern und NFS-Servern, darunter File- und Gerätenamen sowie Größe und Richtung der Datenübertragung.
ip Liefert aufbereitete Daten auf Basis des IP-headers, v4 und v6 und stellt ein mächtiges Werkzeug zur Server- oder Client-seitigen Analyse der Netzlast dar. Ergänzt snoop(1m), tcpdump(1) und wireshark(1m), deren Schwerpunkt auf der weitgehenden Protokoll-Analyse liegt.
syscall Stellt probes für Einsprung- und Rückkehrpunkte von Systemaufrufen bereit und bietet Zugriff auf die in beide Richtungen übergebenen Daten.
proc Der proc-provider erfasst alle Informationen bezüglich der Erzeugung von Prozessen und Threads sowie der Abarbeitung von Signalen. Dies ermöglicht u. a. die Analyse von Prozessketten wie sie beispielsweise bei Login-Vorgängen auftreten.
sched Die probes des sched-providers dienen häufig als Ergänzung zu den Daten des proc-providers, da sie Informationen über das Laufzeitverhalten aus Sicht des Kerns enthalten. Dazu gehören das CPU-Scheduling-Verhalten, aber auch Thread-Synchronisationsmechanismen.
profile Kein provider im herkömmlichen Sinn, gestattet dieser jedoch DTrace-Anwendungen die periodische Ausführung von Aktionen und erlaubt damit die Nachbildung von sampling und die regelmäßige Ausgabe von Daten à la prstat(1m).

Consumer

Für das asynchrone Lesen der Daten aus den Puffern des Kernels sind consumer, etwa auch das dtrace(1m)-Tool, verantwortlich. Die Schnittstelle zum Kern bilden wie in UNIX üblich Gerätetreiber und die Routinen der libdtrace-Bibliothek. Durch den asychronen Zugriff und die begrenzte Größe der Puffer sind Überläufe möglich. Diese werden vom System gemeldet und können meist durch die Anpassung von Parametern im D-Skript behoben werden. Abb.2 verdeutlicht, dass immer mehr Tools auf der DTrace-Technik aufsetzen, Tendenz steigend.

"D", die Skriptsprache von DTrace

DTrace bedient sich zur Steuerung einer einfachen an "C" angelehnten Sprache namens "D". Das Compilieren und Laden des erzeugten Codes in den Kernel wird vom Kommando dtrace(1m) übernommen. Dieses tritt auch gleichzeitig als consumer für das Skript auf. Sprungbefehle stehen ebenso wenig zur Verfügung wie Schleifenkonstrukte da diese unter Umständen – etwa durch Endlos-Schleifen – die Stabilität des Systems gefährden würden. Ansonsten sind alle von "C" bekannten Operatoren und Typen verfügbar wenngleich wie im Falle von uintptr_t gelegentlich unter einer anderen Bezeichnung. Ergänzend bietet "D" eine integrierte limitierte String-Verarbeitung, assoziative Arrays – vergleichbar mit perl-Hashes – und vor allem Aggregationen, eines der mächtigsten DTrace-Features.

Variable
Vordefinierte Variable bieten einen einfachen Zugriff auf Prozess- und Thread-IDs, Credentials, Kernel-Variablen, Timer und vieles mehr. Das fds[]-array hat sich als sehr hilfreich erwiesen, da es die zu einem file-descriptor zugehörigen Daten der fileinfo_t-Struktur bereitstellt. Dadurch ist bei read(2)- und write(2)-Zugriffen einfach der zugehörige Dateiname zu ermitteln.

typedef struct fileinfo {
    string fi_name;       /* name (basename of fi_pathname)     */
    string fi_dirname;    /* directory (dirname of fi_pathname) */
    string fi_pathname;   /* full pathname                      */
    offset_t fi_offset;   /* offset within file                 */
    string fi_fs;         /* filesystem                         */
    string fi_mount;      /* mount point of file system         */
} fileinfo_t;

Struktur
"D"-Skripte bestehen aus Code-Blöcken, die eher im Sinne von Funktionen agieren, die bei der Auslösung einer probe aufgerufen werden. Der Aufruf mehrerer Blöcke – dann von oben nach unten – durch einen event ist möglich. Im einzelnen setzen sich die Blöcke jeweils durch eine probe-Definition, einer optionalen Bedingung, sowie den Aktionen zusammen. Das nachfolgende Code-Segment, eine if-then-else-Nachbildung, macht dies deutlich.

probe1, probe2, …    /* if Zweig */
/ Bedingung /
{
    Aktionen
}

probe1, probe2, …    /* else Zweig */
/ ! (Bedingung) /
{
    Aktionen
}

probe-Syntax
Die Namens-Syntax zur Definition von probes folgt dem Schema

provider:module:function:name

wobei "*", "?" und "[…]" in der gewohnten Weise als Platzhalter verwendet werden können. Ein Komma hat die Bedeutung eines "oder".

sysinfo:genunix:pread64:readch
profile:::tick-5s
syscall::open*:
syscall:*:open*:*
syscall::open: , syscall::open64:

Die verfügbaren probes – diese hängen u. a. von den geladenen Kernel-Modulen wie nfs, ... ab – liefert dtrace -l dessen Ausgabe sich mit weiteren Optionen filtern lässt.

# dtrace -l -f opendir 
   ID   PROVIDER     MODULE         FUNCTION NAME
25340        fbt       unix         opendir entry
25341        fbt       unix         opendir return

Ausgabe von Daten
Generell obliegt die Ausgabe der Daten dem jeweiligen consumer. Die jeweiligen provider stellen die Daten lediglich in den angesprochenen Puffern bereit. Die beiden einfachsten Funktionen, trace() und tracemem(), kopieren hierbei lediglich einfache Ausdrücke oder Speicherbereiche unformatiert. stack(), ustack() und jstack() stellen die call-stacks im Addressbereich des Kernels, eines Prozesses oder für Java-Anwendungen zur Verfügung. Die Auflösung der Adressen ist hierbei Aufgabe des consumers und ist nicht unter allen Umständen erfolgreich durchführbar. Durch den asynchronen Ansatz von DTrace kann z. B. ein Prozess beendend sein, bevor der consumer die gesammelten Daten auswertet. Ein Zugriff auf Symboltabellen ist damit unmöglich. Wege, dies zu umgehen finden sich im DTrace User Guide1.

Die formatierte Ausgabe von Werten ist mit printf() möglich. Die Formatierungsoptionen sind die aus "C" bekannten, um einige nützliche erweitert. So wandelt etwa %a einen Zeiger in den Namen eines Kernel-Symbols um. Äußerst hilfreich ist %S für die formatierte Ausgabe von Zeichenketten da hier nicht-druckbare Zeichen durch eine \-Quotierung dargestellt werden.

Ein erstes D-Skript
Die bisher vorgestellten Möglichkeiten sind bereits für ein einfaches Skript ausreichend. Dieses listet alle Lesezugriffe im gesamten System auf, die der Nutzer root ausführt.

# dtrace -q -n 'syscall::read*:entry
/ uid == 0 /
{
    printf("%-12s %10s %s\n",
        execname, probefunc, fds[arg0].fi_pathname );
}'

sshd               read /zones/andromeda/root/dev/ptmx
init               read /etc/inittab
init               read /etc/inittab
init               read /etc/inittab
init               read /etc/inittab
sshd               read /zones/andromeda/root/etc/hosts.allow
sshd               read /zones/andromeda/root/proc/6808/psinfo

Da mehrere Systemaufrufe – neben read() auch readlinkat() und readv() – dem Muster entsprechen, wird die von DTrace definierte Variable probefunc mit ausgegeben. Diese enthält neben probeprov, probemod und probename eine Komponente des vollständigen Namens der probe, die für den event verantwortlich zeichnet. Um den Code innerhalb eines Skriptes mit Parametern verwenden zu können, ist nur eine minimale Änderung notwendig. Hierbei soll jetzt nicht auf eine UID sondern auf den Namen der Anwendung gefiltert werden.

# cat example_reads.d 
#!/usr/sbin/dtrace -s

#pragma D option quiet

syscall::read*:entry
/ execname == $$1 /    /* filter based on argument passed in */
{
    printf("%-16s %10s %s\n",
        execname, probefunc, fds[arg0].fi_pathname);
}

# ./example_reads.d httpd
httpd  read /www/cms/fileadmin/img/.htaccess
httpd  read /www/cms/fileadmin/img/.htaccess
httpd  read /www/cms/typo3temp/llxml/xml_ed2fec5f68.en.utf-8.cache
httpd  read /www/cms/typo3temp/llxml/xml_ed2fec5f68.en.utf-8.cache
httpd  read /www/cms/typo3temp/llxml/xml_ed2fec5f68.en.utf-8.cache

Der Name der Anwendung (hier httpd) kann jetzt als Kommandozeilen Argument übergeben werden. Im Skript selber ist jedoch eine Maskierung ($$1) notwendig.

Das verwendete Pragma quiet verbessert die Lesbarkeit, da es die Ausgaben von dtrace(1m) auf die print- bzw. trace-Befehle im Skript beschränkt. Mit Hilfe weiterer Pragmas lassen sich u. a. auch die in Abschnitt Consumer angesprochenen Puffer konfigurieren.

Neben dem Storage-Bereich ist insbesondere der Netzwerk-Bereich von herkömmlichen Tools bestenfalls statistisch erfassbar. DTrace stellt in Solaris 11.2 einige spezifische provider für diesen Bereich bereit, nämlich ip, tcp, udp, iscsi, nfsv3, nfsv4 und srp. Die Frage, welcher Klient gerade welche Dateien vom NFS-Server liest, ist damit einfach zu beantworten, hier während eines login via ssh.

# dtrace -q -n 'nfsv4:::op-read-start {
    printf("%-16s %6d %s\n",
        args[0]->ci_remote,
        args[2]->count,
        args[1]->noi_curpath);
}'

134.60.1.143       8192 /pool1/home/kiz/nau/.bashrc
134.60.1.143       8192 /pool1/home/kiz/nau/.ssh/authorized_keys
134.60.1.143       8192 /pool1/home/kiz/nau/.bash_profile
134.60.1.143       8192 /pool1/home/kiz/nau/.profile
134.60.1.143       8192 /pool1/home/kiz/nau/.bash_history
134.60.1.143      24576 /pool1/home/kiz/nau/.bash_history

Das Beispiel demonstriert die Vorteile der durch die provider aufbereiteten Daten die in Form von Zeigern auf Strukturen übergeben werden. So zeigt z. B. das erste Argument – Index 0 – auf die zur Verbindung gehörende conninfo_t-Struktur:

typedef struct conninfo {
        string ci_local;        /* local host address */
        string ci_remote;       /* remote host address */
        string ci_protocol;     /* protocol (ipv4, ipv6, etc) */
} conninfo_t;

Neben dieser Datenaufbereitung sind besonders die im folgenden Abschnitt beschrieben aggregations von zentraler Bedeutung.

Aggregations

Allen Aggregationsfunktionen ist eine mathematische Eigenschaft gemeinsam. Diese besteht darin, dass die Funktion angewendet auf Teilmengen der Daten im ersten Schritt und auf die Zwischenergebnisse im zweiten Schritt das identische Ergebnis liefert wie die Anwendung auf die Gesamtmenge aller Daten in einem Zug. Beispiele hierfür sind Minima und Maxima, aber auch die Summen-Funktion (s.Abb.3).

Die Verwendung von aggregations reduziert den Speicherbedarf erheblich und verbessert damit die Skalierung bezüglich der potentiellen Menge an Daten. Ein dem Namen vorangestellte "@"-Zeichen definiert eine aggregation. Vergleichbar mit hashes in perl(1) unterstützt DTrace nahezu beliebige, auch mehrfache, Indizes wie etwa call-stacks und ist nicht auf numerische Werte oder Strings beschränkt. Beispielsweise zählt

@name[ustack()] = count();

die Anzahl der events pro user-stack also in Abhängigkeit des Programmflusses. In Solaris 11.2 sind derzeit folgende aggregations verfügbar:

Name Funktion
count zählt die Zahl der Aufrufe
sum Gesamtsumme der Ausdrücke
min, max kleinster und größter Wert der Ausdrücke
avg, stddev arithmetisches Mittel und Standardabweichung
lquantize lineare Verteilung mit vorgegebenem Intervall und Grenzen
quantize 2n-Verteilung
llquantize log-lineare Verteilung

Aufgaben wie Latenz- oder Größenanalysen lassen sich mit den Verteilungsfunktionen ideal lösen. Die Sortierung der Ausgabe – voreingestellt ist "nach Wert" – lässt sich durch

setopt("aggsortkey", true)

auf die Sortierung nach den Indizes umstellen. Sofern mehrere verwendet werden, kann die Option aggsortkeypos auf die Nummer des Indexes gesetzt werden, nach dem sortiert werden soll.

setopt("aggsortrev", true);

kehrt die Reihenfolge um. Da DTrace auch die gleichzeitige Ausgabe mehrerer aggregations durch printa() (Ausgabe von aggregations) unterstützt, ist ggf. das Setzen der Option aggsortpos auf die Position der aggregation, die als Sortierbasis dienen soll, notwendig.

Hilfsfunktionen für aggregations

Funktion Aufgabe
trunc( @aggr [, n] ) Löscht eine aggregation vollständig, bzw. Teile dieser
n > 0 erhält die obersten n-Einträge
n < 0 erhält die untersten n-Einträge
clear( @aggr ) Setzt alle Werte auf Null, Indizes bleiben erhalten
normalize( @aggr, fac) Setzt einen "Normalisierungsfaktor", jedoch ohne die Werte zu verändern
denormalize( @aggr ) Macht die Normalisierung rückgängig

Ausgabe von aggregations
Analog zu printf() (Ausgabe von Daten) dient printa() der Ausgabe von aggregations. Es erweitert hierzu die Funktionalität durch eingebaute Iteration über alle verwendeten Indizes, da DTrace ja selbst keine Schleifen-Konstrukte bereitstellt. Dabei ist es nicht zwingend für jeden Index, ein Format-Argument anzugeben, jedoch sind keine Lücken möglich. Die Formatierung der Werte der aggregation wird durch den speziellen Format-Operator %@ eingeleitet. Dieser kann mehrfach vorkommen. Die Ergebnisse der Quantisierungs-aggregations werden als ASCII-Tabelle dargestellt.

Darüber hinaus versteht sich printa() auf die Verknüpfung mehrerer aggregations bei der Ausgabe über die gemeinsamen Indizes und auf die Ausgabe von Verteilungen. Das folgende Code-Beispiel nutzt viele der Funktionen, um ein einfaches iostat(1m) unter Berücksichtigung der Anwendung nachzubilden.

#!/usr/sbin/dtrace -s 

#pragma D option quiet

BEGIN {
    setopt("aggsortkey", "true");     /* sort by dev or app */
    setopt("aggsortkeypos", "1");     /* sort by dev */
    ts = timestamp;
}

io:::start     /* trace physical read-IO */
/ args[0]->b_flags & B_READ /
{
    @r[execname, args[1]->dev_statname] = sum(args[0]->b_bcount);
}

io:::start     /* trace physical write-IO /*
/ args[0]->b_flags & B_WRITE /
{
    @w[execname, args[1]->dev_statname] = sum(args[0]->b_bcount);
}

/* tick-provider fires on single CPU to trigger
 * output of data; makes use of passed argument
 * to set rate
 */
tick-$1 {
        /* normalize to seconds and kilo-bytes */
    fact = 1024 * (timestamp - ts) / 1000000000;
    normalize(@r, fact);
    normalize(@w, fact);

        /* print header, data and reset counters/timestamp */
    printf("\n%-16s %-10s %16s %16s\n",
        "executable", "device", "read[kb/s]", "write[kb/s]");
    printa("%-16s %-10s %@16d %@16d\n", @r, @w);
    clear(@r);
    clear(@w);
    ts = timestamp;
}

Da die Zeitperiode als Argument mit Einheit an das Skript übergeben wird, muss der Normalisierungsfaktor aus der vergangenen Zeit – DTrace-Timer liefern Nanosekunden – berechnet werden. Damit erhält man folgende Ausgabe:

# ./iostat_demo.d 5s 

executable   device       read[kb/s]  write[kb/s]
zpool-rpool  sd1                   0          158
zpool-rpool  sd2                   0          158
httpd        sd4                  32            0
imapd        sd4                  70            0
zpool-mail   sd4                   0         4423
zpool-mail   sd5                   0         4423
imapd        sd6                   0            0
smmapd       sd6                   0            0

Mit den probes io:::start und io:::done lassen sich auch einfach Latenz-Profile erstellen. Die printa()-Ausgabe einer 2n liefert beispielsweise

    value  ------- Distribution ------- count 
     4096 |                             0
     8192 |                             3
    16384 |                             3
    32768 |                             0
    65536 |                             3
   131072 |@@@@@@@                      46
   262144 |@@@@@@@@                     48
   524288 |                             1
  1048576 |                             0
  2097152 |                             1
  4194304 |@                            6
  8388608 |@@@@@@@@@@                   61
 16777216 |@@@@@@@@@                    59
 33554432 |@@                           14
 67108864 |@                            9
134217728 |                             2

Gute erkennbar sind die beiden Latenz-Maxima, die rund zwei Größenordnungen auseinander liegen. Erklärt werden sie durch das Layout des zu Grunde liegenden ZFS-Pools. Neben Festplatten – einem Zugriff auf diese entspricht das Maximum mit den höheren Werten – kommen SSDs als L2ARC cache devices zum Einsatz. Diese erfüllen Lesewünsche deutlich zügiger.

DTrace für Entwickler

DTrace ist mitnichten ein Tool das sich nur an SysAdmins richtet. Analyse von Anwendungen ist damit auch ohne Zugriff auf die Quellen oder einen Debugger möglich.

Der pid-provider
Dieser provider nimmt insofern eine Sonderstellung ein, als dass seine probes nicht vordefiniert sind, sondern erst zur Laufzeit eines Programms dynamisch erzeugt werden. Damit werden sie auch von dtrace -l nicht erfasst. Ob ein Programm unter DTrace-Kontrolle neu gestartet wird oder bereits läuft, ist unerheblich. Die Verfolgung des Codes ist bis auf die Ebene von Assembler-Befehlen möglich, was eine erhöhte Vorsicht bei der Spezifikation nötig macht, um unerwünschte Nebenwirkungen zu vermeiden. So löst

pid10000:libc.so.1:str*:entry

Aktionen beim Aufruf einer String-Funktion der libc aus, sofern dies vom Prozess mit der pid 10000 geschieht. An Stelle von entry kann auch return oder ein numerischer Wert im Sinne eines Befehls-Offset verwendet werden. Da die Prozess-ID im Vorfeld nicht immer bekannt ist, stellt DTrace das Makro $target bereit. Sein Wert wird zur Zeit des Aufrufs durch die Prozess-ID ersetzt, die via -p an dtrace(1m) übergeben wurde oder die zu dem mit -c neu erzeugten Prozess gehört. Damit lässt sich das Beispiel allgemeingültig so schreiben:

pid$target:libc.so.1:str*:entry

Natürlich können auch Teile der Definition via Kommandozeile angepasst werden. In

pid$target:libc.so.1:$1:entry

wird die zu überwachende Funktion dynamisch beim Start des Skriptes übergeben.

"DTrace-ready"

Um die Standardfunktionen um essentielle Daten aus der eigenen Anwendung zu ergänzen, bietet DTrace einfache Möglichkeiten, eigene Anwendungsprovider zu erstellen. Dies wurde bereits für perl, den Apache Web-Server, MySQL, PostgreSQL und andere Anwendungen umgesetzt. Dazu sind lediglich die provider-Definition, das Einbinden einer zusätzlichen Header-Datei, die Nutzung der dort definierten Makros, sowie kleine Änderungen im build-Prozess notwendig. Die folgende Anwendung liest einzelne Zeichen von stdin und stellt diese DTrace über den keypress-provider zur Verfügung.

# cat keypress.c

#include <stdio.h>
#include <sys/sdt.h>

int main (int argc, char *argv[]) {
    int c;
    while ((c = getchar()) != EOF) {
        DTRACE_PROBE1(kp, read, c);
        /* more application code */
    }
}



# cat keypress_d.d

provider kp {
    probe read(int);
};

Übersetzen und Aufruf

# cc -O -c keypress.c 
# dtrace -32 -G -s keypress_d.d keypress.o
# cc -O -o keypress keypress_d.o keypress.o -ldtrace

# cat keypress_d.d keypress.c |
      dtrace -q -c ./keypress -n '
          kp$target:::read { @ = lquantize(arg0, 0, 255, 32); }'

  value  ------------- Distribution ------------- count  
    < 0 |                                         0
      0 |@@@@                                     22
     32 |@@@@@@@@@@@@                             70
     64 |@@@                                      17
     96 |@@@@@@@@@@@@@@@@@@@@@                    120
    128 |                                         0

Das Ergebnis zeigt die Verteilung der ASCII-Codes der beiden Dateien in Gruppen zu je 32 Bytes. Deutlich sichtbar ist die Häufung der Kleinbuchstaben ab dem Wert 96.

Casestudy

Problem

Bei pre-production-Tests einer neuen, in der Zwischenzeit an der Universität Ulm eingeführten, Backup-Software, traten erhebliche Abweichungen zwischen der erwarteten und der gemessenen Datentransferrate disk-to-tape auf. In Einzelmessungen erreichen die Bandlaufwerke (IBM 3592-E07) ihre nominelle Transferrate von 250 MB/s für nicht komprimierbare Daten. Der auf 60 SAS2 Platten aufgebaute RAIDZ2 zpool erzielt mit filebench gemessene Datenraten von über 3,5 GB/s sowohl lesend als auch schreibend. Dahinter bleibt die durchschnittliche Datenrate von nur 61 MB/s für die Migration von 6TB an Daten deutlich zurück und ist nur wenig besser als die Datenübertragung direkt vom Klienten.

Analyse

Die Vermutung, die CPU wäre – etwa auch durch die aktivierte ZFS Komprimierung – für den Engpass verantwortlich, ließ sich einfach durch ein hot-spot-sampling [5] des Kernels widerlegen. Dabei wird mit DTrace mehr als 1.000mal pro Sekunde für jede CPU die derzeit aktive Kernelroutine bestimmt. Der zu Grunde liegende Code ist gewohnt einfach:

profile:::profile-1001hz
/arg0/
{
  @pc[arg0] = count();
}

dtrace:::END
{
    trunc(@pc, 5);
    printa("%a %@d\n", @pc);
}

Das Ergebnis:

Routine                                 calls   prct.
SPARC-T4`copyin                          8630    0.2%
zfs`fletcher_4_native                   10902    0.3% zfs`vdev_raidz_generate_parity_pq       19815    0.5% zfs`lzjb_compress                      234676    5.9%
unix`cpu_halt                         3670636   91.8%

Da hier klar die CPU als Quelle des Problems verworfen werden konnte, wurde im nächsten Schritt das IO-Verhalten mittels IO-Provider untersucht. Eine quantize()-Auswertung der Blockgrößen – b_bcount-Feld der bufinfo_t-Struktur auf die vom provider ein Zeiger bereitgestellt wird – zeigt die der Konfiguration entsprechenden IO-Größen von 256 kB. Allerdings zeigt der zeitliche Verlauf der Transferrate im 15-Sekunden-Durchschnitt (hier die ersten beiden Stunden in Abb.4) ein unerwartetes Verhalten.

Gleichzeitig ließ sich aus den Daten ablesen, dass die durchschnittliche Dauer einer IO-Operation konstant blieb. Im Umkehrschluss bedeutet dies, dass die Anwendung zwischen IO-Operationen zunehmend mehr Zeit benötigt. Mit Hilfe des hot-spot-sampling – diesmal der Anwendung und nicht des Kernels – konnte die Routine schnell identifiziert und ihr CPU-Bedarf aufgezeichnet werden (Abb.5). Sie benötigt bereits nach 6 Stunden Laufzeit das Doppelte an CPU-Zeit wie zu Beginn. Die Verwendung von ustack() im DTrace-Skript lieferte den Entwicklern dann noch weitere Hinweise auf den eigentlichen Auslöser des Problems, das dadurch innerhalb weniger Tage mit einer neuen Version behoben werden konnte.

Quellen
  1. B. Gregg, J. Mauro, P. Hall (2011): DTrace
  2. Mike Harsch's arcstat.pl-Tool 
  3. Wikipedia: Nyquist-Shannon-Abtasttheorem
  4. "Erste Regel von Mentat" aus "Dune – Der Wüstenplanet"
  5. hot-spot-sampling

Autoren

Thomas Nau

Thomas Nau ist seit mehr als 30 Jahren im IT-Umfeld tätig und leitet derzeit die "Abteilung Infrastruktur" des Kommunikations- und Informationszentrum (kiz) an der Universität Ulm. Das kiz, dessen stellvertretender Leiter Thomas...
>> Weiterlesen

Dr. Harald Däubler

Dr. Harald Däubler ist in der "Abteilung Infrastruktur" des Kommunikations- und Informationszentrum (kiz) an der Universität Ulm beschäftigt. Er leitet das Team „Rechnerbetrieb“ und zeichnet damit für viele der zentralen Server...
>> Weiterlesen
botMessage_toctoc_comments_9210