Dtrace Workshop - Teil 3: Der FBT-Provider und erste dtrace-Skripte

In Teil 1 angekündigt und in Teil 2 aufgeschoben will ich jetzt endlich zum FBT-Provider kommen. Hiermit kann man sich wie gesagt jede Funktion die es im Kernel gibt ausgeben lassen. Als Beispiel werden wir uns hier angucken was im Kernel passiert wenn wir bestimmte Systemcalls ausführen. Da unsere dtrace Anweisungen aber inzwischen immer komplexer werden, wird es langsam Zeit das wir uns damit befassen wie man dtrace Skripte schreibt.

Wie bereits mehrmals gesagt wurde handelt es sich bei D um eine eigene Programmiersprache handelt welche sich an AWK und C anlehnt. D ist eventgesteuert, das heißt das bei bestimmten Ereignissen etwas ausgeführt wird und der Code nicht einfach durchlaufen wird. Als ersten sehen wir und mal ein einfaches dtrace Skript an. Wir greifen dabei auf eine der ersten Lektionen zurück die wir hatten, nämlich wie man sich anzeigen läßt welcher Prozess gerade welchen Systemcall ausführt.

#!/usr/sbin/dtrace -s

syscall:::entry
{
   trace(execname);
}

Wir speichern das ganze unter syscall.d und machen es mit chmod +x syscall.d ausführbar. Das Resultat sieht dann wie folgt aus:

raichoo@itzkoatl:~# ./syscall.d
dtrace: script './syscall.d' matched 233 probes
CPU     ID                    FUNCTION:NAME
  0  68998                      ioctl:entry   dtrace
  0  68998                      ioctl:entry   dtrace
  0  69134                  sysconfig:entry   dtrace
  0  69134                  sysconfig:entry   dtrace
  0  69266                   schedctl:entry   dtrace
  0  69068                  sigaction:entry   dtrace
  0  69068                  sigaction:entry   dtrace
  0  69068                  sigaction:entry   dtrace
  0  69068                  sigaction:entry   dtrace
...

Voila, schon haben wir unsere "Mühe" permanent in ein Skript gepackt, immer wieder abrufbar :).

Wollen wir uns jetzt mal ein etwas komplexeres D Skript ansehen. Hier werden wir uns ansehen was beim mmap Syscall alles im Kernel passiert.

#!/usr/sbin/dtrace -s

syscall::mmap:entry
{
   self->verfolgen = 1;
}

fbt:::entry,
fbt:::return
/self->verfolgen/
{
}

syscall::mmap:return
{
   self->verfolgen = 0;
   exit(0);
}

Ok das ist jetzt etwas viel auf einmal. Besonders mysteriös ist hier die Zeile self->verfolgen = 1. Hierbei handelt es sich um eine theadlokale Variable. Ruft ein Thread mmap auf wird verfolgen für diesen Thread auf 1 gesetzt, das wird wichtig wenn wir die Bedingung für unsere FBT Probes ansehen, diese wird nämlich nur ausgeführt wenn self->verfolgen gesetzt ist. Erinnern wir uns: in Teil 1 haben wir festgestellt das D Events wie folgt aufgebaut sind:

probe-tupel
/Bedingung/
{
   Funktionskörper
}

Sobald der mmap Systemcall zurückkehrt (mit syscall::mmap:return) wird die Variabel auf 0 gesetzt und das Skript beendet. Gucken wir uns mal die Ausgabe dieses Skripts an:

raichoo@itzkoatl:~# ./mmap.d
dtrace: script './mmap.d' matched 66380 probes
CPU     ID                    FUNCTION:NAME
  0  31880                    smmap32:entry
  0  23175               smmap_common:entry
  0  27816               as_rangelock:entry
  0  27817              as_rangelock:return
  0  23173                       zmap:entry
  0  31698                choose_addr:entry
  0  21835                   map_addr:entry
...
  0  29853                    as_map:return
  0  23174                      zmap:return
  0  29415             as_rangeunlock:entry
  0  29952                  cv_signal:entry
  0  29953                 cv_signal:return
  0  29416            as_rangeunlock:return
  0  23176              smmap_common:return
  0  31881                   smmap32:return
  0  69093                      mmap:return

Ok das ist ein ziemlicher Rattenschwanz (natürlich habe ich die Ausgabe hier gekürzt ;) )und leider auch sehr unübersichtlich, aber das alles passiert innerhalb eines mmap Syscalls im Kernel. Es wäre aber doch viel schöner wenn man die Ausgabe etwas einrücken könnte und damit besser lesbar. Das erreichen wir durch eine zusätzliche Zeile in unserem Skript.

#!/usr/sbin/dtrace -s

#pragma D option flowindent

syscall::mmap:entry
{
   self->verfolgen = 1;
}

fbt:::entry,
fbt:::return
/self->verfolgen/
{
}

syscall::mmap:return
{
   self->verfolgen = 0;
   exit(0);
}

Durch die Anweisung #pragma D option flowindent veranlassen wir dtrace unsere Ausgabe je nach entry oder return einzurücken und somit sehr viel lesbarer zu machen.
Hier nochmal die gleiche Ausagebe mit flowindent:

raichoo@itzkoatl:~# ./mmap.d
dtrace: script './mmap.d' matched 66380 probes
CPU FUNCTION
  0  -> smmap32
  0    -> smmap_common
  0      -> as_rangelock
  0      <- as_rangelock
  0      -> zmap
  0        -> choose_addr
  0          -> map_addr
...
  0      <- zmap
  0      -> as_rangeunlock
  0        -> cv_signal
  0        <- cv_signal
  0      <- as_rangeunlock
  0    <- smmap_common
  0  <- smmap32
  0  <= mmap

Jetzt kann man sicher sagen: "Ok... das sagt mir zwar jetzt welche Funktionen ausgeführt werden, aber was passiert denn jetzt genau". Stimmt, ohne Code sagt uns das jetzt recht wenig. Sun hat allerdings unter http://src.opensolaris.org/source/ den gesamten veröffentlichen Code durchsuchbar gemacht. Wir brauchen uns also nur eine Funktion von Interesse aussuchen, ihren Namen unter Definition eingeben und schon kriegen wir die Datei angegeben in der sie definiert ist und können sie uns auch online ansehen. Zugegeben ist das keine leichte Kost, aber das ist Kernelcode eigentlich fast nie. Hier kann man ihn aber live in Aktion sehen was das Verständnis um einiges erleichtert. :)