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