Dtrace Workshop - Teil 2: Probeargumente und Aufzählungen

In Teil 1 dieses Workshops haben wir uns mit grundlegenden Funktionen von dtrace befasst. Heute will ich mich mit Probeargumenten und Aufzählungen befassen.

Wie ich letztes mal schon festgestellt habe, arbeitet man bei dtrace mit der Programmiersprache D. Diese Sprache verfügt unter anderem über Datentypen. Ein besonderer Datentyp ist die Aufzählung. Ich will hier mal in einem kleinen Beispiel zeigen wie das funktioniert indem ich dtrace Systemcalls aufzählen lasse.

raichoo@itzkoatl:~# dtrace -n 'syscall:::entry{@[probefunc] = count();}'
dtrace: description 'syscall:::entry' matched 233 probes
^C

  fstat64                                                           1
  mmap                                                              1
  schedctl                                                          1
  sigpending                                                        1
  nanosleep                                                         2
  stat64                                                            2
  pset                                                              3
  sysconfig                                                         3
  c2audit                                                           4
  dup                                                               4
  fcntl                                                             4
  open                                                              4
  sigaction                                                         4
  brk                                                               6
  close                                                             8
  gtime                                                            10
  clock_gettime                                                    11
  writev                                                           12
  setcontext                                                       13
  lwp_sigmask                                                      15
  setitimer                                                        25
  p_online                                                         32
  portfs                                                           84
  write                                                           133
  getpid                                                          169
  read                                                            171
  doorfs                                                          252
  lwp_park                                                        320
  pollsys                                                         496
  ioctl                                                           648

Wollen wir mal der Aufzählung auseinandernehmen:
Mit dem @ zeigen wir an das wir etwas aufzählen wollen. Was das genau ist geben wir in eckigen Klammern an, in diesem Fall ist das die Probefunktion. probefunc ist eine vordefinierte Variable die uns sagt welche Probe "gefeuert" hat. Kommen wir nun zum = count(). Dieser Teil sagt uns WIE wir aufzählen wollen. count() zählt einfach nur wie oft ein Ereignis eingetreten ist. Später werden wir uns genauer unterschiedlichen Aufzählungsarten befassen.
Als Anmerkung bleibt wohl noch zu sagen das dtrace während der Ausführung nichts ausgibt sondern erst wenn wir es mit Strg-C beenden.

Als nächstes wollen wir uns zur Vertiefung noch einen dtrace-Aufruf ansehen der uns anzeigt welche Programme den mmap Systemcall aufrufen und wie oft.

raichoo@itzkoatl:~# dtrace -n 'syscall::mmap:entry{@[execname] = count();}'
dtrace: description 'syscall::mmap:entry' matched 1 probe
^C

  dtrace                                                            1
  hostname                                                         16
  utmp_update                                                      16
  bash                                                             33

Hier zählen wir nicht nach probefunc sondern nach execname auf. Außerdem haben wir das Probetupel genauer spezifiziert.

Wir wollen uns jetzt mal genauer angucken was ein Systemcall so macht. Als Beispiel nehme ich hier den open Systemcall. Gucken wir uns die Funktionsdefinition in der dazugehörigen Manpage an:

int open(const char *path, int oflag, /* mode_t mode */);

Diese Informationen werden an den open Syscall übergeben und wenn man ehrlich ist, würde man da eigentlich auch ganz gerne drankommen wenn man dtrace benutzt. Und das geht auch. Wir haben mit execname und probefunc bereits 2 vordefinierte Variablen kennengelernt, jetzt kommen die Variablen arg0 bis arg9 hinzu. Jede gibt uns Zugang zu einem Argument der jeweiligen Probe.
Als Beisiel konstruieren wir hier mal einen dtrace Aufruf der uns anzeigt welche Dateien unser System gerade öffnet.

raichoo@itzkoatl:~# dtrace -n 'syscall::open:entry{printf("%s",copyinstr(arg0));}'
dtrace: description 'syscall::open:entry' matched 1 probe
CPU     ID                    FUNCTION:NAME
  0  69268                       open:entry /export/home/raichoo/.icons/Neutral_Plus_Inv/cursors/xterm
  0  69268                       open:entry /export/home/raichoo/.icons/Neutral_Plus_Inv/index.theme
  0  69268                       open:entry /usr/share/icons/Neutral_Plus_Inv/cursors/xterm
  0  69268                       open:entry /export/home/raichoo/.icons/Neutral_Plus_Inv/cursors/xterm
  0  69268                       open:entry /export/home/raichoo/.icons/Neutral_Plus_Inv/index.theme
  0  69268                       open:entry /usr/share/icons/Neutral_Plus_Inv/cursors/xterm
  0  69268                       open:entry /export/home/raichoo/.icons/Neutral_Plus_Inv/cursors/xterm
  0  69268                       open:entry /export/home/raichoo/.icons/Neutral_Plus_Inv/index.theme
  0  69268                       open:entry /usr/share/icons/Neutral_Plus_Inv/cursors/xterm
  0  69268                       open:entry /export/home/raichoo/.icons/Neutral_Plus_Inv/cursors/xterm
  0  69268                       open:entry /export/home/raichoo/.icons/Neutral_Plus_Inv/index.theme
  0  69268                       open:entry /usr/share/icons/Neutral_Plus_Inv/cursors/xterm
  0  69268                       open:entry /export/home/raichoo/.icons/Neutral_Plus_Inv/cursors/xterm

Zu printf werde ich hier nicht viel verlieren sondern auf die C Manpage verweisen, da sich die dtrace Funktion genauso verhält. Wir wollen und das erste Argument der Probe ansehen, wie wir oben schon gesehen haben ist das erste Argument const char *path der Pfad der zur öffnenden Datei. Um dieses auszulesen benutzen wir das Probeargument arg0. Da wir uns in einem Systemcall befinden müssen wir die Informationen aus dem Kerneladressraum in den Userspaceaddressraum kopieren, dazu ist die copyinstr() Funktion da.

Eigentlich wollte ich noch etwas auf den FBT-Provider eingehen, aber ich glaube das ist erstmal genug Input für heute, also werde ich mir das für später aufbewahren.

Dtrace Workshop - Teil 1: Einführung

Nachdem ich ja immer so viel von dtrace schwärme möchte ich den Menschen auch gerne mal dieses extrem praktische Tool nahe bringen. Das dieses Thema extrem umfangreich ist werde ich es in verschiedene Sektionen aufteilen und von Zeit zu Zeit immer mal wieder etwas dazu posten.

Was ist dtrace überhaupt? Der beste Vergleich den ich kenne ist wie folgt:
Stell dir vor du hast Probleme mit deinem Auto. Es macht komische Geräusche wenn du schnell fährst. Und nun stell dir vor du fährst auf die Autobahn, beschleunigst auf 200 Sachen und steigst gemütlich aus, öffnest die Motorhaube und baust die Kiste auseinander ohne das diese aufhört zu arbeiten. Du kannst dir jede Schraube jeden Schlauch und jedes noch so komplexe Teil ansehen und herausfinden wo es Probleme gibt. Genau das macht Dtrace mit deinem Betriebssystem und alle Programmen die darauf laufen.

Jetzt kann man sicherlich sagen. Naja in meine Programme konnte ich aber schon immer mit einem Debugger reingucken. Klar konnte man das, aber nur in einzelne Prozesse. Dtrace ermöglicht systemweites Debuggen ohne das man das System in ein großes Performanceloch schmeißt wie das mit Tools wie strace und truss z.B. der Fall ist.

Wie funktioniert das Ganze? Dtrace verfügt über sogenannte Provider, welche in der Lage sind das System zu "instrumentalisieren". Das heißt: Sie kennen Punkte im System an dem sie Messungen durchführen können.

Listen wir erst mal unsere Messpunkte auf:

raichoo@itzkoatl:~# dtrace -l
   ID   PROVIDER            MODULE                          FUNCTION NAME
    1     dtrace                                                     BEGIN
    2     dtrace                                                     END
    3     dtrace                                                     ERROR
    4        fbt              fcsm         fcsm_job_cache_destructor entry
    5        fbt              fcsm         fcsm_job_cache_destructor return
    6        fbt              fcsm        fcsm_job_cache_constructor entry
    7        fbt              fcsm        fcsm_job_cache_constructor return
    8        fbt              fcsm                      fcsm_display entry
    9        fbt              fcsm                      fcsm_display return
...
69649   lockstat           genunix                   lock_clear_splx spin-release
69650   lockstat           genunix                      CLOCK_UNLOCK spin-release
69651   lockstat           genunix                          rw_enter rw-acquire
69652   lockstat           genunix                          rw_enter rw-block
69653   lockstat           genunix                           rw_exit rw-release
69654   lockstat           genunix                       rw_tryenter rw-acquire
69655   lockstat           genunix                     rw_tryupgrade rw-upgrade
69656   lockstat           genunix                      rw_downgrade rw-downgrade
69657   lockstat           genunix                       thread_lock thread-spin
69658   lockstat           genunix                  thread_lock_high thread-spin

Ok, hier wurden wir gerade mit verdammt vielen Messpunkten oder auch Probes erschlagen. Wie man sieht ist jede Probe einem Provider, einem Modul, einer Funktion und einem Namen zugeordnet. Mit diesen Tupeln sind wir in der Lage jeden Messpunkt zu spezifizieren und damit anzusprechen. Gucken wir einfach mal wie viele Probes uns unser System so zur Verfügung stellt.

raichoo@itzkoatl:~# uname -a
SunOS itzkoatl 5.11 snv_95 i86pc i386 i86pc
raichoo@itzkoatl:~# dtrace -l | wc -l
   69659

Alleine auf meinem System stehen mir fast 70.000 Probes zur Verfügung. Und das sind noch lange nicht alle, es gibt noch ein paar spezielle Provider (z.B. den PID-Provider und auch Provider für so ziemlich jedes Skriptsprache z.B. Python, Ruby, PHP, JavaScript und und und) die einem noch mehr Transparenz geben.

Ok, jetzt da wir wissen das wir wirklich viel messen können wollen wir mal loslegen! Als Einführungsbeispiel will ich hier den Syscallprovider vorstellen. Dieser Provider weiß wie man Systemcalls instrumentalisiert. Systemcalls sind Funktionen bei deren Ausführung ein Programm ein Aufgabe an den Kernel abgibt z.B. öffne eine Datei, mappe mir etwas in den virtuellen Speicher, schicke ein Signal an einen anderen Prozess.

Als erstes wollen wir erst mal jeden Syscall-Entry anzeigen lassen.

raichoo@itzkoatl:~# dtrace -n syscall:::entry
...
  0  69480                    pollsys:entry
  0  69166                      write:entry
  0  69450                lwp_sigmask:entry
  0  69450                lwp_sigmask:entry
  0  69164                       read:entry
  0  69480                    pollsys:entry
  0  69450                lwp_sigmask:entry
  0  69450                lwp_sigmask:entry
  0  69166                      write:entry
  0  69480                    pollsys:entry
  0  69166                      write:entry
  0  69450                lwp_sigmask:entry
  0  69450                lwp_sigmask:entry
  0  69164                       read:entry
  0  69480                    pollsys:entry
  0  69450                lwp_sigmask:entry
  0  69450                lwp_sigmask:entry
  0  69166                      write:entry

Jetzt werden uns in Echtzeit alle Systemcall-Entrys auf dem System gezeigt ohne das das System ausgebremst wird. Diese Information ist allerdings eher unspannend. Wir wollen ja auch wissen WER das macht, also erweitern wir unser Kommando:

raichoo@itzkoatl:~# dtrace -n 'syscall:::entry{trace(execname);}'
...
  0  69258                      ioctl:entry   dtrace
  0  69258                      ioctl:entry   dtrace
  0  69258                      ioctl:entry   dtrace
  0  69258                      ioctl:entry   dtrace
  0  69258                      ioctl:entry   dtrace
  0  69258                      ioctl:entry   dtrace
  0  69258                      ioctl:entry   dtrace
  0  69258                      ioctl:entry   dtrace
  0  69258                      ioctl:entry   dtrace
  0  69258                      ioctl:entry   dtrace
  0  69352                       mmap:entry   dtrace
  0  69286                   lwp_park:entry   dtrace
  0  69450                lwp_sigmask:entry   sshd
  0  69450                lwp_sigmask:entry   sshd
  0  69164                       read:entry   sshd
  0  69480                    pollsys:entry   sshd
  0  69450                lwp_sigmask:entry   sshd
  0  69450                lwp_sigmask:entry   sshd
  0  69166                      write:entry   sshd
  0  69480                    pollsys:entry   sshd
  0  69450                lwp_sigmask:entry   sshd
  0  69450                lwp_sigmask:entry   sshd
  0  69164                       read:entry   sshd
  0  69480                    pollsys:entry   sshd
  0  69450                lwp_sigmask:entry   sshd
  0  69450                lwp_sigmask:entry   sshd
  0  69166                      write:entry   sshd
  0  69480                    pollsys:entry   sshd
  0  69330                 sigpending:entry   dtrace
  0  69450                lwp_sigmask:entry   dtrace
  0  69332                 setcontext:entry   dtrace
  0  69166                      write:entry   dtrace
  0  69450                lwp_sigmask:entry   sshd
  0  69450                lwp_sigmask:entry   sshd
  0  69164                       read:entry   sshd
  0  69480                    pollsys:entry   sshd
  0  69450                lwp_sigmask:entry   sshd
  0  69450                lwp_sigmask:entry   sshd
  0  69166                      write:entry   sshd
  0  69480                    pollsys:entry   sshd
  0  69258                      ioctl:entry   dtrace

Mit trace(execname) geben wir an das wir uns für das Programm interessieren das den Systemcall tätigt. execname ist eine vordefinierte Variable von der es eine ganze Menge gibt.

Aber was genau sehen wir da jetzt? Einige werden es sicher schon ahnen. Ich bin über SSH mit meinem Solarisrechner verbunden und alles was wir jetzt sehen sind die Systemcalls die das System braucht um all die Informationen für mich sichtbar zu machen. Wir gucken also dem System zu wie es uns sagt das es etwas sagt.

Wollen wir also unsere "Observation" weiter einschränken. Wir können ein Bedingung angeben die uns nur in bestimmeten Fällen einen Messwert liefert. Das geht wie folgt.

raichoo@itzkoatl:~# dtrace -n 'syscall:::entry/execname == "gdm-binary"/{}'
dtrace: description 'syscall:::entry' matched 233 probes
CPU     ID                    FUNCTION:NAME
  0  69164                       read:entry
  0  69164                       read:entry
  0  69164                       read:entry
  0  69166                      write:entry
  0  69412                      yield:entry
  0  69164                       read:entry
  0  69164                       read:entry
  0  69486                    c2audit:entry
  0  69368                      xstat:entry
  0  69312                   readlink:entry
  0  69486                    c2audit:entry
  0  69450                lwp_sigmask:entry
  0  69450                lwp_sigmask:entry
  0  69450                lwp_sigmask:entry
  0  69450                lwp_sigmask:entry
  0  69356                     munmap:entry
  0  69356                     munmap:entry
...

Hier werden uns nur Informationen ausgegeben wenn das ausführende Programm gdm-binary ist.

Unsere Abfrage ist also wie folgt aufgebaut:

dtrace -n probe-tupel
/Bedingung/
{
    Funktionskörper
}

Wie man sieht stellt dtrace eine kleine Programmiersprache zur Verfügung. Diese Sprache hat den Namen D und ist stark mit AWK und C verwand.

Das war nur ein extrem kleiner Einblick in das was dtrace kann. Als nächstes werde ich mich mit Probe-Argumenten, dem FBT-Provider (welcher jede Funktion im Kernel tracen kann) und dtrace-Skripten befassen. Wer bis dahin nicht warten kann, kann sich auch den Vortrag von Brian Cantrill über dtrace ansehen (SEHR SEHENSWERT!) oder einfach mal im Dtrace User's Guide schmöckern.

Dtrace kann man auch auf der OpenSolaris LiveCD benutzen. Als Anmerkung gilt zu sagen das man root-Rechte braucht (oder bestimmte RBAC-Rechte auf einem Produktivsystem)

Pimp my Blog

Nachdem es irgendwie recht defaultmässig auf meinem Blog zugegangen ist hab ich mir mal ein paar zusätzliche Einstellungen gegönnt im das gute Stück hier etwas persönlicher und auch übersichtlicher zu gestallten. :)

Der widerspenstigen Zähmung

Da vi/vim unter manchen Systemen die nervige Angewohnheit hat im Insert-Mode etwas eigensinnig mit den Pfeiltasten umzugehen, hier ein kleiner Patch um dem guten Stück Beine zu machen:

Wir schreiben folgendes in unsere .exrc und .vimrc:

set t_ku=[strg-v][pfeil-hoch]
set t_kd=[strg-v][pfeil-runter]
set t_kr=[strg-v][pfeil-rechts]
set t_kl=[strg-v][pfeil-links]

(Anmerkung: Das was in den eckigen Klammern steht nicht abtippen sondern machen ;) )

Um das ganze im Nachhinein noch etwas aufzupeppen kann man auch noch "set showmode" und "syntax on" hinzufügen um den aktuellen Mode anzeigen zu lassen und das Syntaxhighlighting zu aktivieren.

Dtrace überall

In den letzten Jahren hat dtrace, das dynamische Tracingtool von OpenSolaris, für eine Menge aufsehen gesorgt und inzwischen findet es auf immer mehr Plattformen ein zuhause. Ports existieren bereits für Mac OS X und QNX. Derzeit werden auch vom FreeBSD (man munkelt auch über einen NetBSD Port) Team Anstrengungen unternommen es zu portieren und vor einigen Monaten wurde der erste Code in den CURRENT Zweig commited.
Unter Linux gab es allerdings Probleme da die CDDL-Lizenz, unter der dtrace steht, nicht kompatibel zur GPL ist. Es wurden zwar mit systemtap Ansätze unternommen dtrace zu kopieren, doch ist es in keiner Weise vergleichbar da es unter anderem nicht in der Lage ist Userspace Prozesse zu tracen und die Stabilität des Systems beeinträchtigt da unter anderem das "Skripten" welches fast C ähnlich ist, völlig über das Ziel hinausschiesst und gefährlichen Code ermöglicht. Inzwischen ist das ftrace-Framework im Gespräch welches aber im Gegensatz zu dtrace und systemtap nicht skriptbar ist und damit extrem an Flexibilität einbüßt. Alles in allem eher spärliche Aussichten. Für ein Licht am Ende des Tunnels sorgt Paul Fox der sich daran gemacht hat dtrace auf Linux zu portieren. Ob es letztendlich möglich sein wird Linux Distributionen mit dtrace auszuliefern kann ich derzeit leider nicht sagen (da mir der ganze Lizenzkram langsam eh zu undurchschaubar wird), aber es bleibt die Hoffnung das es wenigstens ein Patchset geben wird das dieses unglaublich mächtige Tool in die Linuxwelt bringen wird.

Der Solaris Kerneldebugger: Ein Beispiel

Mein Notebook hat die unangenehme Angewohnheit das es unter Solaris gerne einen NMI produziert (Non Maskable Interrupts sind etwas unangenehme Zeitgenossen die z.b. bei Hardwarefehlern auftreten). Nach ein bisschen schmökern im Sourcecode von Solaris ist mir dann aufgefallen das es dort folgende Varibale im pcie Modul gibt:

uint32_t pcie_serr_disable_flag = 0;    /* Disable SERR */

In einem Kommentar wird erwähnt das bei aktiviertem SERR eventuell ein NMI entsteht (welcher aber nicht behandelt wird). Jetzt wollen wir den Inhalt dieser Variable also auf 1 haben damit SERR deaktiviert wird und wir den NMI los sind. Dazu nehmen wir den Kerneldebugger. Durch einfaches Anhängen von -kd im Kerneleintrag von Grub landet man gleich zu Anfang am Debugprompt. Wir wollen jetzt zu dem Punkt springen an dem unser pcie Modul geladen wird, das erreichen wir indem wir dem Debugger sagen das es an diesem Punkt halten soll.

::bp pcie`_init
::cont

Damit wird ein so genannter Breakpoint gesetzt. Wird dieser erreicht halten wir an und gelangen wieder an den Prompt. ::cont sagt dem Debugger einfach
das das Programm weiterlaufen soll.

Wir erreichen nun unseren Breakpoint. Jetzt können wir den Inhalt unserer Variable einfach mit

pcie_serr_disable_flag/W 1

auf 1 setzen und mit ::cont weiterbooten ohne das der NMI auftaucht.

Praktische Sache oder? ;)

Spaß mit DLL-Injection

Heute will ich mich mal mit einer sehr interessanten Debug-Technik befassen: der DLL-Injektion.
Jeder der schon mal in C++ oder ähnlichem gecodet hat kennt sicherlich das Konzept des Überladen von Funktionen. Die Frage ist jetzt: Kann man das ganze auch noch machen wenn ein Programm schon fertig gebacken ist? Otto würde jetzt sagen "Yiiiaaaaaaaaaah ih ih ih ih" *rumhüpf*

Als Beispiel werde ich hier mal etwas fehlerhaften C-Code kompilieren und im Nachhinein die verantwortliche Funktion mit etwas harmlosen überladen.

Hier erst mal unser fehlerhafter code

#include <unistd.h>
#include <stdio.h>

int main()
{
        char buffer[256];
        vscanf("%s",buffer);
        return 0;
}

Das Ganze segelt in einem herrlichen Segfault ab ^^. Ok, jetzt wollen wir einfach mal die Funktion vscanf mit etwas harmlosen "überschreiben". Dazu werden wir eine Dummy-lib schreiben und diese mit LD_PRELOAD dynamisch in unser Programm linken.

Der Code für unser Lib sieht erst mal so aus:

#include <unistd.h>
#include <stdio.h>

int vscanf(const char* format,va_list ap)
{
        printf("override\n");
        return 0;
}

Voila, wir haben die Zutaten. Jetzt wird es Zeit für das Rezept:

[raichoo@tessaiga ~]$ gcc test.c -o karpott
[raichoo@tessaiga ~]$ ./karpott
test
Segmentation fault: 11 (core dumped)
[raichoo@tessaiga ~]$ gcc -shared -o override.so override.c
[raichoo@tessaiga ~]$ LD_PRELOAD=./override.so ./karpott
override

Guten Appetit!