JJMora@arrakis.es

En el post Solaris: Analizando ficheros Core Dump vimos en un sencillo ejemplo como podemos analizar los ficheros core generados por alguna de nuestras aplicaciones y cómo podemos intentar averiguar la causa de que se haya producido el fichero core. En este post veremos de una forma rápida, cómo podemos analizar el fichero core generado por el sistema después de que se haya producido un panic.

Mirando dentro del stack

Por defecto cada vez que se produzca un panic en una máquina Solaris, se generarán 2 ficheros, uno con la imagen del kernel que se estaba ejecutando y otra con el contenido del espacio de memoria del Kernel, para ver como y donde se generarán los ficheros podemos utilizar el comando dumpadm(1M) y el fichero de configuración /etc/dumpadm.conf.

Normalmente después de un crash los ficheros con el volcado de memoria del kernel se almacenan en el directorio /var/crash/< hostname >/. Vamos a utilizar el debuger mdb para analizar el volcado de memoria del Kernel que se ha generado después de un panic.

root@huelva # pwd
/var/crash/huelva
root@huelva # ls
act.0     act.1     bounds    unix.0    unix.1    vmcore.0  vmcore.1
root@huelva #root@huelva # mdb -k unix.1 vmcore.1
Loading modules: [ unix krtld genunix md ip usba random nfs ipc ptm ]
>
> $C
000002a101184621 vpanic(3, 14a7960, 2a1011850e0, 0, 0, 0)
000002a1011846f1 ufs_fault_v+0xe0(3000b1dbb60, 14a7960, 2a1011850e0, 6968,1591890, 0)
000002a1011847a1 ufs_fault+0×1c(3000b1dbb60, 14a7960, 0, 4f7, 300070ce0d4, 0)
000002a101184851 alloccgblk+0×4bc(0, 90000, 4f7, 4f7, 4f7, 300070ce560)
000002a101184901 alloccg+0×158(de, de0, 300192fbce0, 300001fd778, 2000, 635f1610)
000002a1011849b1 hashalloc+0×2c(30017b8b9f8, de, ac6600, 2000, 1192db8,2a101185320)
000002a101184a61 realloccg+0×1b8(300003f9088, 2, de, ac6600, 800, 2a101185630)
000002a101184b31 bmap_write+0×4e8(30017b8b9f8, 4400, 0, 0, 300003f9088, 22)
000002a101184e41 wrip+0×428(400, 2a1011859f8, 0, 300003f9088, 105ac00, 0)
000002a101185071 ufs_write+0×480(30017b8bb60, 30017b8bbb0, 14a6c00, 14a6c00, 20, 0)
000002a101185141 write+0×26c(1, 1b, 200, ffbfb438, 7f7b98e6, ffbfd730)
000002a101185241 write32+0×38(a, ffbfb5c8, 200, 2000, 7f7f0000, 635f1610)
000002a1011852f1 syscall_trap32+0xa8(a, ffbfb5c8, 200, 2000, 7f7f0000, 635f1610)
>

Con $C podemos ver el contenido del stack, en el stack debe estar la llamada que ha provocado el panic. Como se puede ver la última llamada que se realizó fue vpanic(), las dos llamadas anteriores son ufs_fault() y justo antes está la llamada alloccgblk(), seguramente el panic se ha producido en esta función.

Buscando el proceso

Ya sabemos qué función ha provocado el Panic, ahora vamos a ver qué proceso ha sido el causante del PANIC

Podemos utiliza el dcmd ::whatis para averiguar qué es la dirección 0×000002a101184621.

>
> 000002a101184621::whatis
2a101184621 is in thread 30018ca2d20's stack
>

El dcmds nos ha devuelto el mensaje que la dirección 0×2a101184621 pertence al stack del thread 0×30018ca2d20, vamos a ver este thread a qué proceso pertenece.

> 30018ca2d20::print -t kthread_t
{
struct _kthread *t_link = 0
caddr_t t_stk = 0x2a101185af0
int (*)() t_startpc = 0
struct cpu *t_bound_cpu = 0x300047ca000
...
struct proc *t_procp = 0×3000b270078
…

t_taskq = 0
t_anttime = 0
}
>

En el campo t_procp tenemos un puntero a la estructura de “struct proc” que define al proceso que ha lanzado el thread que estamos investigando, volvemos a utilizar el dcmd ::print para ver el contenido de la estructura struct proc, buscamos el campo p_user que es de tipo struct user:

typedef struct  user {
        gregset_t       u_reg;          /* user's saved registers */
        greg_t          *u_ar0;         /* address of user's saved R0 */
        char    u_psargs[PSARGSZ];      /* arguments from exec */
        void    (*u_signal[MAXSIG])();  /* Disposition of signals */
        int             u_code;         /* fault code on trap */
        caddr_t         u_addr;         /* fault PC on trap */
} user_t;

Y tipo user_t tiene un campo denominado u_psargs, el cual almacena los argumentos pasados por exec.

>
> 0x3000b270078::print -t proc_t p_user.u_psargs
char [80] p_user.u_psargs = [ "/usr/j2se/bin/java  -XX:MaxPermSize=128M -Dweblogic.net.h" ]
>

Ya hemos obtenido la línea de comando ejecutada para lanzar el proceso 0×3000b270078, que a su vez se ha encargado de lanzar el thread 0×30018ca2d20. Tambien podemos conocer el proceso que ha generado el panic cruzando la información que tenemos, la dirección de la estructura de tipo proc_t y la salida del dcmds ::ps

> ::ps
S    PID   PPID   PGID    SID   UID      FLAGS             ADDR NAME
R      0      0      0      0     0 0x00000019 0000000001438788 sched
R      3      0      0      0     0 0x00020019 00000300048a6008 fsflush
R      2      0      0      0     0 0x00020019 00000300048a6a20 pageout
R      1      0      0      0     0 0x00004008 00000300048a7438 init
R   1585      1   1460   1175   114 0x00004008 000003000ba2c0a0 java
R   1443      1   1413   1175   114 0x00024008 0000030007152038 java
R   1654   1443   1654   1654   114 0x00004008 000003000bdf60a8 java
R   1653   1443   1653   1653   114 0×00004008 000003000b270078 java
R   1652   1443   1652   1652   114 0×00004008 000003000b9e2098 java
R   1651   1443   1651   1651   114 0×00004008 000003000b880090 java
R   1617   1443   1617   1617   114 0×00004008 000003000b82f4b8 java
R   1221      1   1208   1175   114 0×00004008 000003000b94ead8 java
R    793      1    793    793     0 0×00004008 0000030006c08028 sh
R    895    793    895    793     0 0×00014008 00000300070a2048 bash
R   1408    895   1408    793     0 0×00004008 000003000bfa2ad0 mdb
R    792      1    792    792     0 0×00014008 0000030004a03440 sac
R    795    792    792    792     0 0×00014008 000003000b5a1490 ttymon
R    789      1    789    789     0 0×00000008 000003000b2a4a88 dmispd
R    787      1    787    787     0 0×00014008 0000030007146040 vold
R    780      1    780    780     0 0×00004008 000003000b82e088 mibiisa
R    458      1    458    458     0 0×00020008 000003000b9e34c8 caagentd.64
R    397      1    397    397     0 0×00000008 000003000b48a058 xntpd
>

El problema de esta forma es que la información sobre la línea de comando ejecutada es menor, obtenemos el PID y el nombre del proceso, para nuestro caso java pero no sabemos cuales de lor procesos java ha dado el error. Si obtenemos la información de los argumentos utilizados por el proceso, esta información nos puede ayudar a identificar cuales de los procesos java ha provocado el panic.

Buscando la causa

En este punto ya conocemos qué thread provocó el panic y cuales fueron los argumentos que se pasaron al binario de la aplicación para lanzar el proceso, conocemos el PID, ahora vamos a seguir profundizando en la información obtenida del stack para intentar conocer qué provocó el panic.

Como hemos visto al principio del post, la función que ha provocado el panic ha sido alloccgblk, buceando en el código fuente de OpenSolaris, puede encontrar el caso en el que la función alloccgblk genera un panic, en ese caso de llama a la función ufs_fault() y es en esta llamada donde podemos obtener cierta información por ejemplo el inode y el FS del fichero o directorio que ha provocado el panic.

> $C
000002a101184621 vpanic(3, 14a7960, 2a1011850e0, 0, 0, 0)
000002a1011846f1 ufs_fault_v+0xe0(3000b1dbb60, 14a7960, 2a1011850e0, 6968,1591890, 0)
000002a1011847a1 ufs_fault+0x1c(3000b1dbb60, 14a7960, 0, 4f7,300070ce0d4, 0)
000002a101184851 alloccgblk+0×4bc(0, 90000, 4f7, 4f7, 4f7, 300070ce560)
000002a101184901 alloccg+0×158(de, de0, 300192fbce0, 300001fd778, 2000, 635f1610)
000002a1011849b1 hashalloc+0×2c(30017b8b9f8, de, ac6600, 2000, 1192db8,2a101185320)
000002a101184a61 realloccg+0×1b8(300003f9088, 2, de, ac6600, 800, 2a101185630)
000002a101184b31 bmap_write+0×4e8(30017b8b9f8, 4400, 0, 0, 300003f9088, 22)
000002a101184e41 wrip+0×428(400, 2a1011859f8, 0, 300003f9088, 105ac00, 0)
000002a101185071 ufs_write+0×480(30017b8bb60, 30017b8bbb0, 14a6c00, 14a6c00, 20, 0)
000002a101185141 write+0×26c(1, 1b, 200, ffbfb438, 7f7b98e6, ffbfd730)
000002a101185241 write32+0×38(a, ffbfb5c8, 200, 2000, 7f7f0000, 635f1610)
000002a1011852f1 syscall_trap32+0xa8(a, ffbfb5c8, 200, 2000, 7f7f0000, 635f1610)
>

Vamos a ver el contenido de las direcciones de memoria pasadas a la función ufs_fault(3000b1dbb60, 14a7960, 0, 4f7, 300070ce0d4, 0). De las dos llamadas que se realiza a la función ufs_fault en alloccgblk(), en ambos casos el segundo parámetro es una cadena de texto, por lo tanto 0×14a7960 debe ser la dirección de una cadena de texsto, vamos a realiza un volcado del contenido de esta dirección.

> 0x14a7960::dump -w 4
          / 1 2 3  4 5 6 7  8 9 a b  c d e f  0 1 2 3  4 5 6 7  8 9 a b  c d e f  0 1 2 3  4 5 6 7  8
 9 a b  c d e f  0 1 2 3  4 5 6 7  8 9 a b  c d e f  v123456789abcdef0123456789abcdef0123456789abcdef01
23456789abcdef
14a7960:  616c6c6f 63636762 6c6b3a20 63616e27 74206669 6e642062 6c6b2069 6e206379 6c2c2070 6f733a25 64
2c2069 3a25642c 2066733a 25732062 6e6f3a20 25780a00
alloccgblk: can’t find blk in cyl, pos:%d, i:%d, fs:%s bno: %x..
>

En nuestro caso el volcado de la dirección 0×14a7960 nos devuelve la cadena

alloccgblk: can’t find blk in cyl, pos:%d, i:%d, fs:%s bno: %x

, con esto sabemos que el penúltimo parámetro es una cadena con el FS donde está el fichero/directorio que ha provocado el panic y el antepenúltimo parámetro contiene el inode.

> 300070ce0d4::dump
               0 1 2 3 / 5 6 7  8 9 a b  c d e f  0123v56789abcdef
300070ce0d0:  01ff0000 2f736f66 74000000 00000000  ..../soft.......
>
> 0x4f7=D
                1271
>

El FS donde estaba el fichero es /soft y el inode en hexadecimal 0×4f7 es 1271 en decimal.

Conclusión

Por lo tanto el panic de este ejemplo se ha producido cuando uno de los threads del proceso con PID 1653, que es un proceso java, accedía mediante una llamada de la función alloccgblk() a un fichero almacenado en el FS /soft y cuyo inode era 1271.

Technorati Tag(s) : Solaris OpenSolaris MDB