ProbeVue: Praktische Einführung

Seit der Einführung von ProbeVue unter AIX 6.1 unterstützt IBM dynamisches Tracing unter AIX. ProbeVue ist dabei besonders geeignet für online Debugging und Troubleshooting von Problemen, sowie Performance Analyse und Monitoring. Dabei können sogenannte Proben Punkte im Kernel oder Benutzer-Programmen dynamisch aktiviert werden, um interessante Daten zu sammeln, die dann ausgewertet werden können. ProbeVue wurde so entwickelt, dass es sicher in der Ausführung ist und daher auch auf Produktionssystemen verwendet werden kann. In dieser Einführung soll ProbeVue kurz vorgestellt werden und gezeigt werden, wie man erste einfache (Vue) Programme schreiben und starten kann.

Arbeitsweise von ProbeVue

Für die Benutzung von ProbeVue benötigt man keine spezielle Debug-Version des Kernels und muss auch Applikationen nicht speziell anpassen. ProbeVue kann auf jedem AIX-Kernel ab AIX 6.1 und jedem beliebigen binären Programm eingesetzt werden. Solange an einem Proben Punkt keine Probe aktiviert ist, kostet ProbeVue keine einzige Machinen-Instruktion Overhead! Erst wenn ein Probe aktiviert wird, wird am Punkt der Probe der Maschinen Code geändert und zusätzlicher Code zum Sammeln von Daten hinzugefügt. Dies sei an einem kleinen Beispiel mit Hilfe des Kernel Debuggers (kdb) kurz gezeigt. Im Beispiel sind die ersten 8 Assembler Instruktionen aufgelistet, die im Kernel ausgeführt werden, wenn ein System Call gestartet wird. ProbeVue ist dabei zunächst nicht aktiv.

# echo "dc sc_entry_etrc_point 8" | kdb -script
read vscsi_scsi_ptrs OK, ptr = 0x0
(0)> dc sc_entry_etrc_point 8
Executing dc command
sc_entry_etrc_point+000000              ori    r0,r0,0
syscall+000244           bcctrl   
.sys_call_ret+000000              ori    r0,r0,0
sc_exit_etrc_point+000000              ori    r0,r0,0
.sys_call_ret+000008           mfsprg    r9,SPRG1
.sys_call_ret+00000C               mr    r31,r3
.sys_call_ret+000010               ld    r3,5020(0)          5020=legacy_amr+000010
.sys_call_ret+000014               li    r5,0

End of execution for dc command
(0)> Executing q command
#

Sobald ProveVue gestartet wird und mindestens einen System Call traced, wird der Code im Kernel dynamisch geändert:

# echo "dc sc_entry_etrc_point 8" | kdb -script
read vscsi_scsi_ptrs OK, ptr = 0x0
(0)> dc sc_entry_etrc_point 8
Executing dc command
sc_entry_etrc_point+000000                b    <.sc_entry_etrc_fixup>
syscall+000244           bcctrl   
.sys_call_ret+000000              ori    r0,r0,0
sc_exit_etrc_point+000000                b    <.sc_exit_etrc_fixup>
.sys_call_ret+000008           mfsprg    r9,SPRG1
.sys_call_ret+00000C               mr    r31,r3
.sys_call_ret+000010               ld    r3,5020(0)          5020=legacy_amr+000010
.sys_call_ret+000014               li    r5,0

End of execution for dc command
(0)> Executing q command
#

Man sieht, das die erste Instruktion sich von „ori  r0,r0,0“ (OR Immediate) geändert hat, auf „b <.sc_entry_etrc_fixup>“ (Branch). Durch den Sprung (Branch) wird zusätzlicher Code von ProbeVue ausgeführt, ist dieser abgearbeitet, wird zurück gesprungen und mit der nächsten Instruktion bcctrl (Branch Conditional to Count Register) weitergemacht.

Sobald ProbeVue keinen System Call mehr verfolgt, wird der Code im Kernel wieder auf den ursprünglichen Code zurück geändert, womit dann auch kein Overhead mehr durch ProbeVue entsteht. Overhead durch ProbeVue entsteht als nur an den Proben Punkten, die aktiviert werden! Werden nur wenige Proben aktiviert, dann sollte der Overhead durch ProbeVue extrem klein sein. Aktiviert man sehr viele Proben auf einem System, dann kann sich das in Form von Performance Problemen äußern. Man sollte also immer nur die Proben aktivieren, die wirklich interessant und notwendig für eine Untersuchung sind!

Bei der Verwendung von ProbeVue werden typischerweise kleine Skripte geschrieben, die dann mit dem Kommando probevue ausgeführt werden können. Hierzu benötigt man aber spezielle Berechtigungen, die standardmäßig nur der Benutzer root hat. Die Skripte werden in der ProbeVue eigenen Skript-Sprache Vue geschrieben und typischerweise in Dateien mit der Endung „.e“ abgespeichert.

Das erste ProbeVue Programm

Damit man ProbeVue verwenden kann, muß das Fileset bos.sysmgt.trace installiert sein. Das Kommando probevue ist Bestandteil dieses Filesets. Die zur Verfügung stehenden Proben Punkte gehören zu sogenannten Proben Managern, dies sind unter anderem syscall, syscallx und interval. Für die ersten Beispiele bleiben wir bei Proben des Managers syscall.

Welche Proben Punkte ein Proben Manager unterstützt, kann man sich mit Hilfe der Option „-l“ und dem Namen des Proben Managers anzeigen lassen, hier für den Manager syscall:

# probevue -l syscall
The syscall probe manager supports probes at the entry and exit of well-defined and documented base AIX system calls. List of Probes Supported by Syscall Probe Manager are:
absinterval
accept
bind
close
creat
execve
exit
fork
…
socket
socketpair
stat
waitpid
write
#

In einem Vue Skript, werden im einfachsten Fall sogenannte Klauseln (englisch clauses) aufgelistet. Wobei jede Klausel (clause) aus einem (oder mehreren Proben Punkten) und einem sogenannten Aktionsblock besteht. Ein Proben Punkt ist ein mit Doppelpunkt getrenntes Tupel von Feldern, wobei das erste Feld mit „@@“ und dem Namen des Managers der Probe beginnt. Die weiteren Felder hängen dann vom konkreten Manager ab. Für den Fall des syscall Proben Managers gibt es genau 4 Felder, hier zuerst ein paar Beispiele:

@@syscall:45678:open:entry
   Probe at entry of open system call in process with ID 45678.

@@syscall:*:write:exit
   Probe at exit of system call write. The asterisk indicates that the system call has to be traced for all processes.

Über das zweite Feld (PID oder „*“) kann man entscheiden ob alle Prozesse, oder nur ein bestimmter Prozeß überwacht werden soll. Über das dritte Feld kann der System Call angegeben werden, der von Interesse ist und letztlich kann über das vierte Feld ausgewählt werden, ob man eine Aktion beim Eintritt oder beim Austritt aus dem System Call durchführen möchte. Man kann natürlich auch beides machen.

Der Aktionsblock mit Anweisungen die auszuführen sind, wird durch eine geschweifte Klammer „{“ gestartet und durch eine geschweifte Klammer „}“ beendet. Eine der einfachsten und gleichzeitig nützlichsten Anweisungen ist die von ksh, awk und C bekannte Funktion printf(). Wir fassen dies in unserem ersten Vue-Skript zusammen:

# cat example1.e
@@syscall:*:open:entry
{
        printf("system call open was called\n");
}
#

Für alle Prozesse wird beim Eintritt in den System-Call open die printf()-Funktion gestartet, welche den Text „system call open was called“ gefolgt von einem New-Line ausgibt.

Das Vue-Skript kann über das Kommando probevue ganz einfach gestartet werden, indem man es als Argument angibt:

# probevue example1.e
system call open was called
system call open was called
system call open was called
system call open was called
system call open was called
system call open was called
system call open was called
system call open was called
system call open was called
system call open was called
system call open was called
system call open was called
system call open was called
system call open was called
system call open was called
system call open was called
system call open was called
system call open was called
system call open was called
system call open was called
^C
#

Das Programm läuft solange, bis es z.B. durch Verwendung von ControlC abgebrochen wird. Jedes Mal, wenn irgendein Prozeß den System-Call open verwendet, wird die Meldung „system call open was called“ ausgegeben.

Die Möglichkeit bei einem Skript den Interpreter über den speziellen Kommentar „#!“ in die erste Zeile des Skriptes einzutragen, funktioniert natürlich auch für Vue-Skripte:

# cat example1.e
#! /usr/bin/probevue

@@syscall:*:open:entry
{
        printf("system call open was called\n");
}
# chmod +x example1.e
#

Das Skript kann jetzt einfach über seinen Dateinamen gestartet werden:

# ./example1.e
system call open was called
system call open was called
system call open was called
system call open was called
^C
#

Skripte sollten dokumentiert werden

Zum guten Programmierstil gehört es, Programme mit Kommentaren zu versehen. Zum Einen könnte am Anfang des Skripts z.B. der Autor, Datum, Version und Beschreibung des Skriptes dokumentiert werden, zum Anderen sollten Programm-Stellen, die nicht leicht verständlich sind, mit Hilfe von Kommentaren erklärt werden. In Vue-Skripten dient, wie unter der Programmiersprache C, die Zeichenfolge „/*“ als Einleitung eines Kommentars. Der Kommentar erstreckt sich dann bis zum nächsten Vorkommen der Zeichenfolge „*/„.

Wir verbessern unser Skript durch Hinzufügen einiger Kommentarzeilen:

# cat example1.e
#! /usr/bin/probevue

/* Description: First Vue script to show usage of open system call.
   Version: 0.2  */

@@syscall:*:open:entry
{
        printf("system call open was called\n");
}

#

Alternativ ist auch eine Kommentierung im C++ Stil möglich, dabei wird ein Kommentar durch die Zeichenfolge „//“ eingeleitet und erstreckt sich bis zum Ende der Zeile.

Zeilen die mit dem Zeichen „#“ beginnen, werden ignoriert. IBM empfiehlt aber dies nicht für Kommentare zu verwenden!

Verwenden von Builtin-Variablen

Unser Programm ist bisher eher uninteressant. Es wird zwar ausgegeben das ein open System Call ausgeführt wurde, aber es werden keine weiteren Informationen dazu angegeben.

ProbeVue besitzt eine ganze Reihe von Builtin-Variablen, diese werden automatisch von ProbeVue mit Werten aus dem aktuellen Kontext einer Probe befüllt. So gibt es insbesondere die Builtin-Variablen __pid und __pname. In der Variablen __pid steht die PID des Prozesses der eine Probe ausgelöst hat, in unserem Falle also die PID des Prozesses der den open System-Call gestartet hat. In der Variablen __pname steht der zugehörige Name des Prozesses.

Mit Hilfe dieser beiden Builtin-Variablen lässt sich unser Skript erweitern und zusätzlich bei jedem Aufruf eines open System-Calls die PID und der Name des Prozesses ausgeben werden, der den System-Call gestartet hat. Wir erweitern unser Programm, indem wir diese zusätzlichen Informationen von printf() ausgeben lassen:

# cat example1.e
#! /usr/bin/probevue

/* Description: First Vue script to show usage of open system call.
   Version: 0.3  */

@@syscall:*:open:entry
{
        printf("%s (%lld) has called open\n",__pname,__pid);
}

#

Nach dem Starten des erweiterten Skriptes bekommt man schon deutlich mehr Informationen:

# ./example1.e
ovbbccb (12058768) has called open
ovbbccb (12058768) has called open
oacore (25165874) has called open
oacore (25165874) has called open
auditpr (12124312) has called open
db2fmcd (5570782) has called open
sh (31064148) has called open
db2sysc (18743362) has called open
db2sysc (18743362) has called open
…
^C
#

Zugriff auf Argumente eines System-Calls

Der System-Call open wird mit 2 oder 3 Argumenten aufgerufen, siehe „man open„:

int open (Path, OFlag [, Mode])

       const char *Path;

       int OFlag;

       mode_t Mode;

Das erste Argument ist die Adresse (Pointer) zu einer Zeichenkette mit dem Pfadnamen der zu öffnenden Datei. Der Proben Manager syscall weist beim Eintritt in einen System-Call den speziellen Builtin-Variablen __arg1, __arg2, usw die Argumente zu, mit denen ein System-Call aufgerufen wurde. D.h. wir haben über unser Vue-Skript theoretisch Zugriff auf das Argument mit dem Dateipfad beim System-Call open. Die Idee wäre den Dateipfad als zusätzliche Information ausgeben zu lassen.

Zunächst einmal muß man den Aufruf des System-Calls in Form eines Funktions-Prototypen deklarieren, wenn man Argumente des System-Calls benutzen möchte. Das ist notwendig, damit ProbeVue für die Argumente auch die zugehörigen Daten-Typen kennt (Integer-Wert, Floating-Point-Wert, Adresse). Dies geht ganz einfach, indem man den System-Call mit Rückgabe-Typ, Name und Argument-List in C-Form, noch vor der ersten Klausel (clause), aufführt, z.B. so:

int open( const char* Path , int OFlag );

Damit ist für ProbeVue erkennbar, das das erste Argument eine Adresse und das zweite Argument ein Integer-Wert ist. Das dritte, optionale, Argument haben wir weggelassen. Im Prinzip würde es hier sogar reichen nur das erste Argument anzugeben, da wir nur auf dieses zugreifen werden.

Leider gibt es eine weitere kleine Komplikation, die Adresse für den Dateipfad liegt nicht im Adreßraum des Vue-Skripts. Daher kann man die Adresse nicht direkt nutzen, sondern muß die dahinterliegenden Daten (Zeichenkette) in den Adreßraum des Vue-Skriptes kopieren. Hierfür gibt es die Vue-Funktion get_userstring():

String get_userstring( char* addr , int len )

Das erste Argument ist die Adresse an der die zu kopierenden Daten (Zeichenkette) stehen. Mit dem zweiten Argument wird angegeben wieviele Zeichen maximal kopiert werden sollen. Es kann auch der Wert -1 angegeben werden (nicht empfohlen), dann wird solange kopiert, bis das Zeichenketten-Ende Zeichen erreicht ist, oder das ProbeVue Skript abbricht.

Wir bauen die Deklaration von open und die Ausgabe des Dateinamens, unter Verwendung von get_userstring(), noch in unser Vue-Skript ein:

# cat example1.e
#! /usr/bin/probevue

/* Description: First Vue script to show usage of open system call.
   Version: 0.4  */

int open( const char *Path , int OFlag );

@@syscall:*:open:entry
{
        printf("%s (%lld) has called open for %s\n",__pname,__pid,get_userstring(__arg1,256));
}
#

Starten wir unser Skript jetzt erneut, bekommen wir bei jedem open System-Call nicht nur die PID und den Namen des Prozesses, sondern jetzt auch den Pfad der Datei, die geöffnet wird:

# ./example1.e
WRN-592: Line:12 Column:82 Incompatible argument, type mismatch in pointer assignment.
nimesis (15925642) has called open for /.nimesis_dbg_level
nimesis (15925642) has called open for /etc/objrepos/nim_attr
nimesis (15925642) has called open for /etc/objrepos/nim_attr.vc
sshd (20054452) has called open for /etc/passwd
sshd (20054452) has called open for /etc/security/passwd
sshd (20054452) has called open for /etc/security/login.cfg.idx
…
^C
#

Die Warnung in der ersten Zeile der Ausgabe kommt vom Aufruf von get_userstring(). Die Builtin-Variable __arg1 hat den Typ 64-Bit Integer-Wert, die Funktion get_userstring() erwartet aber eine Adresse (Pointer). Mit der Warnung signalisiert ProbeVue, das der Interger-Wert als Adresse interpretiert wird. In unserem Falle enthält __arg1 aber tatsächlich eine Adresse und man kann dies ProbeVue auch signalisieren, indem man einen sogenannten Cast verwendet:

(void*)__arg1

Damit teilt man ProbeVue mit, das der Integer-Wert als Adresse (Pointer) verwendet werden soll. Es kommt dann auch keine Warnung mehr von ProbeVue beim Starten des Skripts.

Überwachung von nur einem Prozeß

Das entwickelte Beispiel-Programm überwacht die open Aufrufe aller Prozesse. Manchmal ist man aber nur an einem bestimmten Prozeß interessiert. Kennt man die PID des betreffenden Prozesses, lässt sich das ganz einfach realisieren, anstelle des Wildcards „*“ im Proben Punkt, gibt man einfach die PID des Prozesses an:

# cat example1.e
#! /usr/bin/probevue

/* Description: First Vue script to show usage of open system call.
   Version: 0.5  */

int open( const char *Path , int OFlag );

@@syscall: 15925642:open:entry
{
        printf("%s (%lld) has called open for %s\n",__pname,__pid,get_userstring((void*)__arg1,256));
}

#

Es wird dann nur noch der Prozeß mit der PID 15925642 überwacht. Allerdings ist das etwas unpraktisch wenn man später einen anderen Prozeß überwachen möchte, man müsste dann immer die PID im Vue-Skript abändern. Eine Alternative bietet die Verwendung von Argumenten. Analog wie bei einer Shell, kann man bei Vue-Skripten über $1, $2 usw auf die Argumente zugreifen, mit denen das Skript aufgerufen wurde. Wir tragen daher anstelle der festen PID 15925642 das Argument $1 ein:

# cat example1.e
#! /usr/bin/probevue

/* Description: First Vue script to show usage of open system call.
   Version: 0.6  */

int open( const char *Path , int OFlag );

@@syscall: $1:open:entry
{
        printf("%s (%lld) has called open for %s\n",__pname,__pid,get_userstring((void*)__arg1,256));
}

#

Dem Skript muss jetzt beim Aufruf als Argument die PID des zu überwachenden Prozesses angegeben werden:

# ./example1.e 31130058
sshd (31130058) has called open for /dev/ptc
sshd (31130058) has called open for /dev/pts/1
sshd (31130058) has called open for /etc/group
sshd (31130058) has called open for /etc/group
sshd (31130058) has called open for /etc/group
sshd (31130058) has called open for /etc/group
sshd (31130058) has called open for /etc/passwd
sshd (31130058) has called open for /etc/security/passwd
sshd (31130058) has called open for /etc/passwd
^C
#

In einer Reihe von weiteren Artikeln werden wir weitere Möglichkeiten von ProbeVue zeigen.

Weitere Artikel zum Thema ProbeVue

ProveVue: Praktische Einführung II

ProbeVue in Action: Identifizieren eines Abstürzenden Prozesses

ProbeVue in Action: Überwachen der „Queue Depth“ von Platten