Schlagwort: probevue

Veröffentlicht am

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

Platten und Storage Systeme unterstützen Tagged Command Queueing, d.h. angeschlossene Server können mehrere I/O Aufträge an die Platte oder das Storage-System senden ohne zu Warten das ältere I/O-Aufträge fertig sind. Wieviele I/O-Aufträge man an eine Platte senden darf, bevor man warten muss das ältere I/O-Aufträge abgeschlossen wurden, kann über das hdisk Attribut queue_depth unter AIX konfiguriert werden. Für viele hdisk Typen ist der Wert 20 für die queue_depth der Default-Wert. In der Regel erlauben die meisten Storage-Systeme aber noch größere Werte für die Queue-Depth.

Mit Hilfe von ProbeVue lässt sich die Auslastung der Platten-Queue sehr leicht beobachten.

Ab AIX 7.1 TL4 bzw. AIX 7.2 TL0 unterstützt AIX den I/O Probe Manager. Damit lassen sich auf einfache Weise Ereignisse im I/O Stack von AIX tracen. Wird ein I/O vom Platten-Treiber gestartet, so geschieht dies über die Funktion iostart im Kernel, der Request wird an den Adapter-Treiber weitergegeben und geht dann über den Host-Bus-Adapter an das Storage-System. Das Bearbeiten der Antwort wird von der Funktion iodone im Kernel übernommen. Der I/O Probe-Manager unterstützt (unter anderem) Proben an diesen Stellen:

@@io:disk:iostart:read:<filter>
@@io::disk:iostart:write:<filter>
@@io:disk:iodone:read:<filter>
@@io::disk:iodone:write:<filter>

Als Filter kann z.B. ein Hdisk Name wie hdisk2 angegeben werden. Die Proben-Punkte lösen dann nur Ereignisse für die Platte hdisk2 aus. Damit lässt sich schon einmal eine Aktion durchführen wann immer ein I/O für eine Hdisk beginnt oder endet. Damit könnte man z.B. messen wie lange eine I/O Operation dauert oder auch einfach nur mitzählen wieviele I/Os ausgeführt werden. In unserem Beispiel waren wir aber an der Auslastung der Platten-Queue interessiert, d.h. der Anzahl I/Os die an die Platte gesendet aber noch nicht abgeschlossen wurden. Der I/O Probe-Manager besitzt für die I/O Ereignisse  iostart und iodone die Builtin-Variable __diskinfo mit den folgenden Feldern (https://www.ibm.com/support/knowledgecenter/en/ssw_aix_72/com.ibm.aix.genprogc/probevue_man_io.htm):

name          char*     Name der Platte
…
queue_depth   int       Die Queue-Depth der Platte (Wert aus der ODM)
cmds_out      int       Anzahl der ausstehenden I/Os
…

Das Feld cmds_out gibt an wieviele I/Os an die Platte gesendet wurden, für die das I/O noch nicht abgeschlossen ist (Antwort ist noch nicht beim Server angekommen).

Mit dem folgenden Code-Abschnitt ermitteln wir die minimale, maximale und durchschnittliche Anzahl an Einträgen in der Platten-Queue:

@@io:disk:iostart:*:hdisk0     // Nur I/Os für hdisk0 berücksichtigen
{
   queue = __iopath->cmds_out; // Anzahl ausstehende I/Os in Variable queue festhalten
   ++numIO;                    // Anzahl I/Os in der Variablen numIO mitzählen (wegen Durchschnittsbildung)
   avg += queue;               // Variable avg um Anzahl ausstehende I/Os erhöhen
   if ( queue < min )
      min = queue;             // Überprüfen auf Minimum und gegebenenfalls setzen
   if ( queue > max )
      max = queue;             // Überprüfen auf Maximum und gegebenenfalls setzen
}

Die ermittelten Werte geben wir dann einmal pro Sekunde mit Hilfe des Intervall Probe-Managers aus:

@@interval:*:clock:1000
{
   if ( numIO == 0 )
      numIO = 1;    // Verhindert Division durch 0 bei der Durchschnittsbildung
   if ( min > max )
      min = max;
   printf( "%5d  %5d  %5d\n" , min , avg/numIO , max );
   min = 100000;   // Zurücksetzen der Variablen für das nächste Intervall
   avg = 0;
   max = 0;
   numIO = 0;
}

Das vollständige Skript ist auf unserer Webseite zum Download verfügbar: ioqueue.e.

Hier ein Beispiel-Lauf des Skriptes für die Platte hdisk13:

# ./ioqueue.e hdisk13
  min    avg    max
    1      1      2
    1      1      9
    1      1      2
    1      1      8
    1      1      2
    1      1      2
    1      1      8
    1      1     10
    1      1      2
    1      1      1
    1      1     10
    1      1      2
    1      1     11
...

Das Skript erwartet die Angabe einer hdisk als Argument und gibt dann einmal pro Sekunde die ermittelten Werte für die angegebene hdisk aus.

In der Beispiel-Ausgabe sieht man das die maximale Anzahl der Einträge in der Platten-Queue 11 ist. Eine Erhöhung des Attributes queue_depth macht daher aus Performance-Sicht keinen Sinn.

Hier ein anderes Beispiel:

# ./ioqueue.e hdisk21
  min    avg    max
    9     15     20
   11     17     20
   15     19     20
   13     19     20
   14     19     20
   17     18     20
   18     18     19
   16     19     20
   13     18     20
   18     19     19
   17     19     20
   18     19     20
   17     19     19
...

In diesem Fall wird der maximale Wert 20 (die hdisk21 hat eine queue_depth von 20) regelmäßig erreicht. Eine Erhöhung der queue_depth kann in diesem Fall zu einer Verbesserung des Durchsatzes führen.

Das Beispiel-Skript lässt sich natürlich noch beliebig erweitern, man könnte z.B. noch den Durchsatz erfassen, oder die Wartezeit von I/Os in der Wait-Queue oder auch die Position und Größe jedes I/Os auf der Platte. Das dargestellte Beispiel zeigt wie einfach man Informationen zu I/Os mit Hilfe von ProbeVue ermitteln kann.

Weitere Artikel zum Thema ProbeVue

ProbeVue: Praktische Einführung

ProveVue: Praktische Einführung II

ProbeVue in Action: Identifizieren eines Abstürzenden Prozesses

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

 

Veröffentlicht am

ProbeVue in Action: Identifizieren eines Abstürzenden Prozesses

Kürzlich meldete unser Monitoring ein volles /var-Filesystem auf einem unserer Systeme. Schnell war herausgefunden das Core-Files im Verzeichnis /var/adm/core das Filesystem gefüllt hatten. Es stellte sich schnell heraus das alle Core-Files von Perl stammten. Allerdings konnte anhand der Core-Files nicht festgestellt werden welches Perl-Skript den Absturz von Perl verursacht hatte. Ein Blick auf die Zeitstempel der Core-Files ließ leider kein Muster erkennen:

-bash-4.4$ ls -ltr /var/adm/core
total 2130240
drwxr-xr-x    2 root     system          256 Jan 29 10:20 lost+found/
-rw-------    1 root     system    100137039 Jun 26 04:51 core.22610328.26025105.Z
-rw-------    1 root     system     99054991 Jun 26 06:21 core.21102892.26042104.Z
-rw-------    1 root     system     99068916 Jun 26 08:06 core.18153840.26060607.Z
-rw-------    1 root     system    100132866 Jun 26 08:21 core.19005848.26062105.Z
-rw-------    1 root     system     97986020 Jun 26 16:36 core.15270246.26143608.Z
-rw-------    1 root     system     99208958 Jun 26 22:21 core.22675838.26202106.Z
-rw-------    1 root     system     97557063 Jun 27 01:06 core.5505292.26230604.Z
-rw-------    1 root     system     98962499 Jun 27 10:06 core.8257960.27080603.Z
-rw-------    1 root     system     99804173 Jun 27 14:51 core.18940202.27125107.Z
-rw-------    1 root     system     99633676 Jun 28 03:21 core.17563960.28012107.Z
-rw-------    1 root     system     99116032 Jun 28 19:06 core.8651210.28170608.Z
-bash-4.4$

Auch die Einträge im Error Report lieferten keine Informationen um welches Perl-Skript es sich hier handelt und auf welchem Wege dieses gestartet wurde.

 

-bash-4.4$ sudo errpt -j A924A5FC –a
...
---------------------------------------------------------------------------
LABEL:          CORE_DUMP
IDENTIFIER:     A924A5FC

Date/Time:       Wed May 29 15:21:25 CEST 2019
Sequence Number: 17548
Machine Id:      XXXXXXXXXXXX
Node Id:         XXXXXXXX
Class:           S
Type:            PERM
WPAR:            Global
Resource Name:   SYSPROC        

Description
SOFTWARE PROGRAM ABNORMALLY TERMINATED

Probable Causes
SOFTWARE PROGRAM

User Causes
USER GENERATED SIGNAL

        Recommended Actions
        CORRECT THEN RETRY

Failure Causes
SOFTWARE PROGRAM

        Recommended Actions
        RERUN THE APPLICATION PROGRAM
        IF PROBLEM PERSISTS THEN DO THE FOLLOWING
        CONTACT APPROPRIATE SERVICE REPRESENTATIVE

Detail Data
SIGNAL NUMBER
         11
USER'S PROCESS ID:
              13369662
FILE SYSTEM SERIAL NUMBER
           1
INODE NUMBER
                 69639
CORE FILE NAME
/var/adm/core/core.13369662.29132106
PROGRAM NAME
perl
STACK EXECUTION DISABLED
           0
COME FROM ADDRESS REGISTER

PROCESSOR ID
  hw_fru_id: 1
  hw_cpu_id: 19

ADDITIONAL INFORMATION

Unable to generate symptom string.
Too many stack elements.
-bash-4.4$

Die einzige Information, die sich entnehmen ließ, war das die Prozesse mit dem Signal 11 (SIGSEGV) beendet wurden, also aufgrund eines Zugriffs auf eine ungültige Speicher-Adresse.

Es stellte sich die Frage: wie kann ermittelt werden um welches Perl-Skript es sich handelt und auf welchem Wege es gestartet wird.

Dies sollte sich eigentlich mit Hilfe von ProbeVue herausfinden lassen.

Es bot sich der sysproc-Provider an, der im Falle eines Exits eines Prozesses ein Event generiert. Über die spezielle built-in Variable __exitinfo werden genauere Informationen zum Exit, wie Exit-Status oder die Signal-Nummer die den Prozess beendet hat bereitgestellt. Damit lässt sich schon einmal die folgende Probe schreiben:

1: @@sysproc:exit:*
2: when ( __exitinfo->signo == 11 )
3: {
4:         printf( "%llu:  %s\n" , __pid , __pname );
5:         ptree(10);
6: }

Die 6 Zeilen seien hier kurz erklärt:

  1. Der Probe-Point: Provider ist sysproc, Event is exit, * bedeutet beliebiger Prozeß
  2. Durch Verwendung des obigen Prädikats wird der nachfolgende Action Block nur ausgeführt, wenn der Prozeß mit dem Signal 11 (SIGSEGV) beendet wurde.
  3. Start des Action Blocks.
  4. Ausgeben der PID und des Programm-Namens des Prozesses.
  5. Die Funktion ptree gibt den Vater, Großvater usw. (bis 10 Ebenen) des Prozesses aus.
  6. Hier endet der Action Block.

Leider lassen sich hier keine Argumente auflisten, mit denen das Programm gestartet wurde, was in unserem Falle mit Perl den Namen des Skriptes geliefert hätte. Aber immerhin bekommt man über die Funktion ptree heraus auf welchem Wege das Programm aufgerufen wurde, was in manchen Fällen schon ausreicht um das Programm dann letztlich zu identifizieren.

Wir hätten zur Identifikation gerne noch die Information über die Argumente mit denen Perl aufgerufen wurde. Diese Information liefert der syscall-Provider für den System-Call execve mit dem das Programm letztlich gestartet wird. Der Probe-Point ist damit syscall:*:execve:entry, da beim Eintritt in die Funktion die Argumente bekannt sind. Die Signatur von execve für ProbeVue sieht dann so aus:

int execve( char* , struct arg_t* args , char* );

Hierbei ist das erste Argument (wird von ProbeVue als __arg1 bereitgestellt) der Programm-Name. Das zweite Argument ist eine Struktur mit den gesuchten Argumenten (bereitgestellt über __arg2). Über das dritte Argumente hat man Zugriff auf Environment-Variablen, was aber in unserem Falle nicht von Bedeutung ist. Die Struktur struct arg_t sieht für 5 Argumente so aus:

struct arg_t
{
        union
        {
                char* arg[5];
                int num[5];
        } u;
};

Diese Struktur und die Signatur von execve müssen im ProbeVue-Skript deklariert werden, bevor man diese benutzen kann.

Beim Zugriff auf die Argumente ergibt sich dann noch ein kleines weiteres Problem: wenn der Action Block für unsere Probe angesprochen wird, sind wir im Kernel-Modus, die Argumente selber sind aber Adressen im User-Mode des Prozesses. Die Daten (in diesem Falle Zeichenketten) müssen aus dem User-Adreß-Raum herauskopiert werden. Dies erledigt die Funktion get_userstring.

Wir lassen uns bei jedem execve die PID, den Programm-Namen, das Kommando und bis zu 5 Argumente ausgeben. Dies ist im folgenden Programm implementiert:

#! /usr/bin/probevue

struct arg_t
{
        union
        {
                char* arg[5];
                int num[5];
        } u;
};

int execve( char* , struct arg_t* args , char* );

@@syscall:*:execve:entry
{
        __auto String command[128];
        __auto String argument[128];
        __auto struct arg_t argv;
        copy_userdata( __arg2 , argv );
        command = get_userstring( __arg1 , -1 );
        argument = get_userstring( argv.u.arg[0] , -1 );
        printf( "%llu: %s called execve(%s) with arguments: %s " , __pid , __pname , command , argument )
;
        if ( argv.u.num[1] != 0 )
        {
                argument = get_userstring( argv.u.arg[1] , -1 );
                printf( "%s " , argument );
                if ( argv.u.num[2] != 0 )
                {
                        argument = get_userstring( argv.u.arg[2] , -1 );
                        printf( "%s " , argument );
                        if ( argv.u.num[3] != 0 )
                        {
                                argument = get_userstring( argv.u.arg[3] , -1 );
                                printf( "%s " , argument );
                                if ( argv.u.num[4] != 0 )
                                {
                                        argument = get_userstring( argv.u.arg[4] , -1 );
                                        printf( "%s " , argument );
                                }
                        }
                }
        }
        printf( "\n" );
}

@@sysproc:exit:*
when ( __exitinfo->signo == 11 )
{
        printf( "%llu:  %s\n" , __pid , __pname );
        ptree(10);
}

Das Skript haben wir capture_segv.e genannt und ausführbar gemacht.

In der Theorie sollte das Programm nach dem Start alle startenden Programme mit PID, Namen und bis zu 5 Argumenten ausgeben. Außerdem erfolgt eine Ausgabe wenn ein Prozess mit dem Signal 11 (SIGSEGV) abgebrochen wird. Die entsprechende PID kann man dann weiter oben in der Ausgabe suchen und damit das Programm mit Argumenten identifizieren.

Leider ergibt sich in der Praxis das folgende kleine Problem: wenn ein Programm nach dem execve sehr schnell beendet wird, bevor ProbeVue mit get_userstring die Argumente kopieren kann, kommt es bei get_userstring zu einem Zugriff auf eine nicht mehr existierende Adresse und das ProbeVue Skript wird abgebrochen. Wir haben dies umgangen, indem wir das ProbeVue Skript einfach über eine Endlos-Schleife immer wieder starten:

# while true; do ./capture_segv.e >>/tmp/wait_for_segv ; done

Wir haben das ProbeVue Skript dann einige Stunden laufen lassen, bis es dann wieder zu einem Core-File von Perl kam. Die Datei /tmp/wait_for_segv enthielt ca 23.000 Zeilen! Wir haben hier nur die relevanten Zeilen aufgelistet:

# cat /tmp/wait_for_segv
…
8651210: ksh called execve(xxxx_hacheck.pl) with arguments: xxxx_hacheck.pl -c
8651210: ksh called execve(/var/opt/OV/bin/instrumentation/xxxx_hacheck.pl) with arguments: xxxx_hacheck
.pl -c
20054518: ksh called execve(/bin/proc2mon.pl) with arguments: proc2mon.pl
…
8651210:  perl

     PID              CMD
       1              init
                        |
                        V
9634196              ovcd
                        |
                        V
9765232              opcacta
                        |
                        V
8651210              perl    <=======
…

Man sieht das Perl über das Programm opcacta gestartet wurde, welches selbst von ovcd gestartet wurde. Diese Prozesse gehören zu HP OpenView das hier im Einsatz ist. Weiter oben in der Ausgabe kann man sehen das das Perl-Skript /var/opt/OV/bin/instrumentation/xxxx_hacheck.pl gestartet wurde. Damit haben wir das Skript gefunden das die vielen Core-Files erzeugt.

Das Skript wurde erst kürzlich geschrieben und muß offensichtlich noch einmal untersucht und überarbeitet werden.

Mit Hilfe von ProbeVue hat ein kurzes Skript und einige Stunden Warten ausgereicht um die Ursache des Problems zu finden! ProbeVue ist aber nicht nur bei der Untersuchung von Problemen nützlich; auch beim Performance Monitoring erweist sich ProbeVue als extrem hilfreich.

Weitere Artikel zum Thema ProbeVue

ProbeVue: Praktische Einführung

ProveVue: Praktische Einführung II

ProbeVue in Action: Identifizieren eines Abstürzenden Prozesses

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