ProveVue: Praktische Einführung II

Im zweiten Teil der praktischen Einführung von ProbeVue soll die Verwendung des Intervall Proben Managers und der speziellen BEGIN Klausel (clause) vorgestellt werden. Zur Illustrierung soll als durchgängiges Beispiel ein kleines Monitoring Tool entwickelt werden, der Prozeß Aktivitäts Reporter (Vue Skript par.e). Dieser soll für einen ausgewählten Prozeß in 1 Sekunden Intervallen die Anzahl der read und write System-Calls und der dabei übertragenen Daten in KB/s ausgeben.

Der Intervall Proben Manager

Mit Hilfe einer Probe des Proben Managers interval, kann in regelmäßigen Abständen ein beliebiger Aktionsblock ausgeführt werden. Ein Proben Punkt des Intervall Managers hat dabei die folgende Form:

interval:*:clock:<number of milli seconds>

Wir wählen ein 1000 ms (1 Sekunde) Intervall und lassen zum Start erst einmal jede Sekunde eine Meldung ausgeben:

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

/* Description: A process activity reporter */

@@interval:*:clock:1000
{
        printf("clock tick\n");
}

#  chmod +x par.e
#

Wir starten das Vue-Skript par.e und überprüfen die Funktion:

# ./par.e
clock tick
clock tick
clock tick
clock tick
^C
#

Das sieht schon mal ganz gut aus, aber ist der Abstand zwischen den Meldungen auch wirklich jeweils 1 Sekunde? ProbeVue bietet über die Funktion timestamp() die Möglichkeit an, auf die aktuelle Zeit zuzugreifen und über die Funktion printf() mit dem Konversions Bezeichner „%A“ auszugeben:

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

/* Description: A process activity reporter */

@@interval:*:clock:1000
{
        printf("%A clock tick\n",timestamp());
}

#

Ein kurzer Test des Skripts zeigt, dass das Intervall wirklich 1 Sekunde beträgt:

# ./par.e
Mar/20/21 08:35:16 clock tick
Mar/20/21 08:35:17 clock tick
Mar/20/21 08:35:18 clock tick
Mar/20/21 08:35:19 clock tick
Mar/20/21 08:35:20 clock tick
^C
#

Globale Variablen

Als nächstes wollen wir die Anzahl der read System-Calls eines Prozesses mitzählen. Hierzu verwenden wir, wie im ersten Teil, wieder den Proben Manager syscall. Die PID des zu überwachenden Prozesses soll über ein Argument beim Aufruf des Skriptes übergeben werden. Der zu verwendende Proben Punkt wäre dann:

@@syscall:$1:read:entry

Wobei „$1“ wieder für das erste übergebene Argument des Skripts (PID) steht, und im dritten Feld der read System-Call ausgewählt wurde.

Die Anzahl der read System-Calls speichern wir in einer globalen Variablen, die wir nreads nennen. Der Typ der Variablen ist int, das erlaubt das Speichern von ganzzahligen Werten. Die Variable wird automatisch mit 0 initialisiert. Als weitere Anweisung im Aktionsblock erhöhen wir die Variable nreads um 1 (++nreads). Die printf() Anweisung im Aktionsblock der Intervall-Probe erweitern wir um die Ausgabe der Integer-Variablen nreads. Insgesamt ergibt sich dann das folgende Skript:

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

/* Description: A process activity reporter */

@@interval:*:clock:1000
{
        printf("%A %d\n",timestamp(),nreads);
}

@@syscall:$1:read:entry
{
        int nreads;
        ++nreads;
}

#

Jedes Mal, wenn der angegebene Prozeß einen read System-Call startet, wird der Wert der globalen Variablen nreads um 1 erhöht. Nach Ablauf einer Sekunde wird der aktuelle Zeitstempel zusammen mit der Anzahl der ausgeführten read System-Calls seit Starten des Vue-Skripts ausgegeben:

# ./par.e 10682852
Mar/20/21 08:53:30 0
Mar/20/21 08:53:31 779
Mar/20/21 08:53:32 779
Mar/20/21 08:53:33 779
Mar/20/21 08:53:34 779
Mar/20/21 08:53:35 779
Mar/20/21 08:53:36 779
Mar/20/21 08:53:37 779
Mar/20/21 08:53:38 884
Mar/20/21 08:53:39 1662
Mar/20/21 08:53:40 1662
Mar/20/21 08:53:41 1662
Mar/20/21 08:53:42 1662
Mar/20/21 08:53:43 1662
Mar/20/21 08:53:44 1767
Mar/20/21 08:53:45 1767
^C
#

Die Deklaration der globalen Variablen nreads (Zeile: „int nreads;„) kann auch außerhalb des Aktionsblocks, vor allen Klauseln, erfolgen. Es ist dann eventuell besser zu erkennen, das diese Variable global ist, und an jeder beliebigen Stelle benutzt werden kann.

Anstelle von absoluten Werten möchten wir gerne die Anzahl der Aufrufe im letzten Zeitintervall ausgeben. Dazu benötigt man eine zweite globale Variable (wir verwenden oreads), in welcher der Stand am Anfang des Intervalls festgehalten wird. Durch Differenz-Bildung (nreads – oreads) bekommt man dann die Anzahl der Aufrufe während des letzten Zeitintervalls:

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

/* Description: A process activity reporter  */

int nreads;
int oreads;

@@interval:*:clock:1000
{
        printf("%A %d\n",timestamp(),nreads-oreads);
        oreads = nreads;
}

@@syscall:$1:read:entry
{
        ++nreads;
}

#

Ein Probelauf des Vue-Skriptes zeigt, das es die gewünschte Ausgabe liefert:

# ./par.e 10682852
Mar/20/21 09:47:29 0ll
Mar/20/21 09:47:30 0
Mar/20/21 09:47:31 0
Mar/20/21 09:47:32 779
Mar/20/21 09:47:33 105
Mar/20/21 09:47:34 778
Mar/20/21 09:47:35 0
Mar/20/21 09:47:36 0
Mar/20/21 09:47:37 105
Mar/20/21 09:47:38 778
Mar/20/21 09:47:39 0
Mar/20/21 09:47:40 105
^C
#

Ermitteln des Lese-Durchsatzes

Bei jedem read System-Call muß die Anzahl der zu lesenden Daten angegeben werden. Der Aufruf von read sieht so aus („man 2 read„):

ssize_t  read  (FileDescriptor,  Buffer,  NBytes)
       int FileDescriptor;
       void  * Buffer;
       size_t NBytes;

Das dritte Argument ist die Anzahl der zu lesenden Bytes. Vom ersten Teil des Artikels wissen wir schon, das man den Aufruf eines System-Calls mit Argumenten in Form eines Funktions-Prototyp deklarieren muss, wenn man auf die Argumente im Vue-Skript zugreifen möchte. Wir übernehmen dementsprechend die folgende Deklaration für den read System-Call in unser Skript:

ssize_t read( int FileDescriptor , void* Buffer , size_t NBytes );

Auf das dritte Argument kann man dann im Skript über die spezielle Builtin-Variable __arg3 zugreifen. Für die gelesenen Bytes führen wir die beiden globalen Variablen nreadBytes und oreadBytes ein, analog zu den beiden bisherigen Variablen. Im Aktionsblock der syscall Probe verwenden wir __arg3 um die Anzahl zu lesenden Bytes hochzuzählen. Und im Aktionblock für die Intervall-Probe geben wir die gelesenen Bytes im Intervall aus:

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

/* Description: A process activity reporter  */

ssize_t read( int FileDescriptor , void* Buffer , size_t NBytes );

int nreads;
int oreads;
int nreadBytes;
int oreadBytes;

@@interval:*:clock:1000
{
        printf("%A %d %d\n",timestamp(),nreads-oreads,nreadBytes-oreadBytes);
        oreads = nreads;
        oreadBytes = nreadBytes;
}

@@syscall:$1:read:entry
{
        ++nreads;
        nreadBytes += __arg3;
}

#

Leider lässt sich das Skript jetzt nicht mehr starten, es kommt sofort eine Fehlermeldung:

# ./par.e 10682852
./par.e: 8: unsupported operator in typecast: ,
#

Die Zeile 8 enthält die Deklaration des read System-Calls. Das Problem ist, das ProbeVue die benutzerdefinierten Datentypen ssize_t und size_t nicht kennt. Der Typ ssize_t ist letztlich der Datentyp signed long, und der Typ size_t der Datentyp unsigned long. Letztere Datentypen sind ProbeVue bekannt. Wir ersetzten daher in der Deklaration von read die beiden benutzerdefinierten Datentypen ssize_t und size_t durch die Datentypen signed long bzw. unsigned long.

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

/* Description: A process activity reporter  */

signed long read( int FileDescriptor , void* Buffer , unsigned long NBytes );

int nreads;
int oreads;
int nreadBytes;
int oreadBytes;

@@interval:*:clock:1000
{
        printf("%A %d %d\n",timestamp(),nreads-oreads,nreadBytes-oreadBytes);
        oreads = nreads;
        oreadBytes = nreadBytes;
}

@@syscall:$1:read:entry
{
        ++nreads;
        nreadBytes += __arg3;
}

#

Jetzt lässt sich das Vue-Skript auch wieder starten und produziert die gewünschte Ausgabe:

# ./par.e 10682852
Mar/20/21 10:26:58 0 0
Mar/20/21 10:26:59 0 0
Mar/20/21 10:27:00 0 0
Mar/20/21 10:27:01 0 0
Mar/20/21 10:27:02 779 2500602
Mar/20/21 10:27:03 0 0
Mar/20/21 10:27:04 105 85632
Mar/20/21 10:27:05 778 2496506
Mar/20/21 10:27:06 105 85632
Mar/20/21 10:27:07 778 2496506
Mar/20/21 10:27:08 105 85632
Mar/20/21 10:27:09 0 0
Mar/20/21 10:27:10 0 0
Mar/20/21 10:27:11 0 0
^C
#

Da wir auch an den write System-Calls und dem zugehörigen Durchsatz interessiert sind, erweitern wir unser Skript und überwachen auch die write System-Calls. Der write System-Call hat genauso wie der read System-Call 3 Argumente, wobei das dritte Argument die Anzahl der zu schreibenden Bytes ist. Wir können also im wesentlichen den Code von read übernehmen und einfach read durch write ersetzen:

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

/* Description: A process activity reporter */

signed long read( int FileDescriptor , void* Buffer , unsigned long NBytes );
signed long write( int FileDescriptor , const void* Buffer , unsigned long NBytes );

int nreads;
int oreads;
int nreadBytes;
int oreadBytes;
int nwrites;
int owrites;
int nwriteBytes;
int owriteBytes;

@@interval:*:clock:1000
{
        printf("%A %d %d %d %d\n",timestamp(),nreads-oreads,nreadBytes-oreadBytes,nwrites-owrites,nwriteBytes-owriteBytes);
        oreads = nreads;
        oreadBytes = nreadBytes;
        owrites = nwrites;
        owriteBytes = nwriteBytes;
}

@@syscall:$1:read:entry
{
        ++nreads;
        nreadBytes += __arg3;
}

@@syscall:$1:write:entry
{
        ++nwrites;
        nwriteBytes += __arg3;
}

#

Das Skript funktioniert auf Anhieb und liefert jetzt sowohl die Anzahl der Lese- und Schreib-Operationen eines Prozesses, als auch den entsprechenden Durchsatz:

# ./par.e 10682852
Mar/20/21 10:33:59 0 0 0 0
Mar/20/21 10:34:00 0 0 0 0
Mar/20/21 10:34:01 0 0 0 0
Mar/20/21 10:34:02 779 2500602 94 3530
Mar/20/21 10:34:03 0 0 0 0
Mar/20/21 10:34:04 0 0 0 0
Mar/20/21 10:34:05 105 85632 6 1966
Mar/20/21 10:34:06 778 2496506 94 3530
Mar/20/21 10:34:07 105 85632 6 1966
Mar/20/21 10:34:08 778 2496506 94 3530
Mar/20/21 10:34:09 105 85632 6 1966
Mar/20/21 10:34:10 0 0 0 0
Mar/20/21 10:34:11 0 0 0 0
^C
#

Formatierte Ausgabe

Die Ausgabe der einzelnen Spalten verschiebt sich von Zeile zu Zeile, was die Lesbarkeit der Ausgabe verschlechtert. Die Funktion printf() bietet die Möglichkeit die Breite einer Ausgabe vorzugeben, dazu wird im Format-String jeweils hinter dem Zeichen „%“ die gewünschte Anzahl von Zeichen angegeben. Ist eine Ausgabe kürzer, wird einfach mit Leerzeichen aufgefüllt. Für die Anzahl der read bzw. write System-Calls sehen wir erst einmal maximal 6 stellige Ausgaben vor, bei den Werten zum Durchsatz möchten wir eine Ausgabe in KB/s haben, wobei wir hier bis zu 7 Stellen vorsehen. Um auf KB zu kommen, müssen wir durch 1024 dividieren. Da bei der Integer-Division nicht gerundet wird, runden wir selber, indem wir im Zähler 512 addieren:

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

/* Description: A process activity reporter  */

signed long read( int FileDescriptor , void* Buffer , unsigned long NBytes );
signed long write( int FileDescriptor , const void* Buffer , unsigned long NBytes );

int nreads;
int oreads;
int nreadBytes;
int oreadBytes;
int nwrites;
int owrites;
int nwriteBytes;
int owriteBytes;

@@interval:*:clock:1000
{
        printf("%A %6d %7d KB/s %6d %7d KB/s\n",timestamp(),nreads-oreads,(nreadBytes-oreadBytes+512)/1024,nwrites-owrites,(nwriteBytes-owriteBytes+512)/1024);
        oreads = nreads;
        oreadBytes = nreadBytes;
        owrites = nwrites;
        owriteBytes = nwriteBytes;
}

@@syscall:$1:read:entry
{
        ++nreads;
        nreadBytes += __arg3;
}

@@syscall:$1:write:entry
{
        ++nwrites;
        nwriteBytes += __arg3;
}

#

Ein Test der neuen Skript Version zeigt, dass die Ausgabe der Spalten jetzt korrekt untereinander erfolgt, was deutlich besser lesbar ist:

# ./par.e 10682852
Mar/20/21 11:47:19      0       0 KB/s      0       0 KB/s
Mar/20/21 11:47:20      0       0 KB/s      0       0 KB/s
Mar/20/21 11:47:21    778    2438 KB/s     94       3 KB/s
Mar/20/21 11:47:22    105      84 KB/s      6       2 KB/s
Mar/20/21 11:47:23    779    2442 KB/s     94       3 KB/s
Mar/20/21 11:47:24    119      97 KB/s      4       2 KB/s
Mar/20/21 11:47:25    778    2438 KB/s     94       3 KB/s
Mar/20/21 11:47:26     73      31 KB/s     18       6 KB/s
^C
#

BEGIN Block

Schön wäre jetzt noch eine Überschrift über den einzelnen Spalten, damit auch klar ist, welche Werte in welcher Spalte ausgegeben werden. Die Überschrift müsste einmalig, zu Beginn des Skripts ausgegeben werden, bevor einer der Aktionsblöcke ausgeführt wird. ProbeVue bietet die Möglichkeit einen sogenannten BEGIN-Block zu definieren. Dazu wird als Pseudo Proben-Typ „@@BEGIN“ verwendet. Der folgende Aktionsblock wird dann einmalig zu Beginn des Skript-Laufs ausgeführt. Wir benutzen einen solchen BEGIN-Block, um mittels printf() eine Überschrift für die Spalten auszugeben:

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

/* Description: A process activity reporter  */

signed long read( int FileDescriptor , void* Buffer , unsigned long NBytes );
signed long write( int FileDescriptor , const void* Buffer , unsigned long NBytes );

int nreads;
int oreads;
int nreadBytes;
int oreadBytes;
int nwrites;
int owrites;
int nwriteBytes;
int owriteBytes;

@@BEGIN
{
        printf("%18s %6s %7s      %6s %7s\n","TIMESTAMP","#READ","READ/s","#WRITE","WRITE/s");
}

@@interval:*:clock:1000
{
        printf("%A %6d %7d KB/s %6d %7d KB/s\n",timestamp(),nreads-oreads,(nreadBytes-oreadBytes+512)/1024,nwrites-owrites,(nwriteBytes-owriteBytes+512)/1024);
        oreads = nreads;
        oreadBytes = nreadBytes;
        owrites = nwrites;
        owriteBytes = nwriteBytes;
}

@@syscall:$1:read:entry
{
        ++nreads;
        nreadBytes += __arg3;
}

@@syscall:$1:write:entry
{
        ++nwrites;
        nwriteBytes += __arg3;
}

#

Damit haben jetzt alle Spalten eine Überschrift:

# ./par.e 2568903
         TIMESTAMP  #READ  READ/s      #WRITE WRITE/s
Mar/20/21 13:02:46      1      16 KB/s   5914  378432 KB/s
Mar/20/21 13:02:47     13      17 KB/s   5702  364160 KB/s
Mar/20/21 13:02:48     17     256 KB/s   3048  190977 KB/s
Mar/20/21 13:02:49      2      16 KB/s      1       0 KB/s
Mar/20/21 13:02:50     12      39 KB/s   4863  304977 KB/s
Mar/20/21 13:02:51      4      16 KB/s  10671  682816 KB/s
Mar/20/21 13:02:52      1      16 KB/s  11470 -3460287 KB/s
Mar/20/21 13:02:53     22     241 KB/s   5931  375361 KB/s
^C
#

Einige Verbesserungen

Schaut man sich die letzte Ausgabe genauer an, speziell die Zeile von 13:02:52, dann sieht man das dort ein negativer Wert auftaucht. Das ist sehr unschön, und der Wert ist auch mit Sicherheit nicht korrekt! Die Ursache liegt darin begründet das wir den Datentyp int (32-bit) für die Anzahl gelesener bzw. geschriebener Bytes genommen haben. Offensichtlich ist es hier zu einem Überlauf gekommen! Der Datentyp für die Anzahl Bytes im read und write System-Call war unsigned long (64-bit). Wir ändern daher den Datentyp von int auf unsigned long ab. Bei der Ausgabe mit printf() müssen wir aber dann darauf achten den Format-Bezeichner von „%7d“ (32-bit Integer) auf „%7lld“ (64-bit Integer) abzuändern:

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

/* Description: A process activity reporter */

signed long read( int FileDescriptor , void* Buffer , unsigned long NBytes );
signed long write( int FileDescriptor , const void* Buffer , unsigned long NBytes );

int nreads;
int oreads;
unsigned long nreadBytes;
unsigned long oreadBytes;
int nwrites;
int owrites;
unsigned long nwriteBytes;
unsigned long owriteBytes;

@@BEGIN
{
        printf("%18s %6s %7s      %6s %7s\n","TIMESTAMP","#READ","READ/s","#WRITE","WRITE/s");
}

@@interval:*:clock:1000
{
        printf("%A %6d %7lld KB/s %6d %7lld KB/s\n",timestamp(),nreads-oreads,(nreadBytes-oreadBytes+512)/1024,nwrites-owrites,(nwriteBytes-owriteBytes+512)/1024);
        oreads = nreads;
        oreadBytes = nreadBytes;
        owrites = nwrites;
        owriteBytes = nwriteBytes;
}

@@syscall:$1:read:entry
{
        ++nreads;
        nreadBytes += __arg3;
}

@@syscall:$1:write:entry
{
        ++nwrites;
        nwriteBytes += __arg3;
}

#

Nach dieser Korrektur tritt der Überlauf nicht mehr (bzw. erst nach ca. 16 Millionen TB) auf.

Mit dem vorgestellten Vue-Skript lässt sich das I/O-Verhalten von einzelnen Prozessen ganz gut beobachten. Natürlich sind noch beliebige weitere Verbesserungen möglich. Dies sei aber dem Leser überlassen.