Hace algún tiempo tuvimos problemas con una de nuestra aplicaciones. Los usuarios comentaban lentitud en ciertos puntos de la navegación y estuvimos analizando los distintos recursos que utiliza esta aplicación, disco, red, hardware, CPUs, etc. para descartar posibles cuellos de botella en la infraestructura. No encontramos ningún elemento de la arquitectura de sistemas que puediera suponer la causa de lentitud. El siguiente paso fue identificar a nivel de aplicación si existía algún componente software que fuese el responsable de la perdida de rendimiento, para ésto seguimos buscando desde abajo hacia arriba, si hemor comprobado la infraestructura, el siguiente elemento es el SO. Nuestro objetivo era conocer el comportamiento de la aplicación con el SO, mediante el uso de las llamadas a sistemas que realizaba.
Para identificar cual podría ser el problema, comenzamos por lo mas lógico, crear un script en DTrace que buscara todas las llamadas de sistemas que emplearan un tiempo excesivo, por ejemplo mas de 1 segundo, todos sabemos que 1 segundo es demasiado tiempo para una llamada a sistema, pero quisimos probar suerte.
root@host # cat ./syscall_all_pid.d
/*
* Presenta el tiempo empleado por cada syscall
* si es superior a los 1000 mseg
*
* Como parametro acepta el PID del proceso
*
* Version: 1.0
*/
syscall:::entry
/pid==$1/
{
array[tid]=timestamp;
self->th=tid;
}
syscall:::return
/pid==$1 && (timestamp-array[tid])/1000000 > 1000 && self->th == tid/
{
printf("nTID: % 8d t Time: %d t %s",tid,(timestamp-array[tid])/1000000,probefunc);
}
Al ejecutar el script obtenemos una salida parecida a la siguiente.
root@host # dtrace -q -s ./syscall_all_pid.d 4096 TID: 692 Time: 1009 pollsys TID: 98 Time: 1009 lwp_cond_wait TID: 115 Time: 1259 lwp_cond_wait TID: 233 Time: 1009 lwp_cond_wait TID: 692 Time: 1009 pollsys TID: 113 Time: 1259 lwp_cond_wait TID: 98 Time: 1009 lwp_cond_wait TID: 112 Time: 2009 lwp_cond_wait TID: 233 Time: 1009 lwp_cond_wait TID: 692 Time: 1009 pollsys TID: 259 Time: 3078 lwp_cond_wait TID: 98 Time: 1010 lwp_cond_wait TID: 224 Time: 7507 read TID: 259 Time: 1144 lwp_cond_wait TID: 692 Time: 1009 pollsys TID: 98 Time: 1009 lwp_cond_wait TID: 262 Time: 1281 recvfrom
De la salida anterior nos llamó la atención las llamadas read, ya que el resto pollsys, lwp_cond_wait y recvfrom son normales, ya que son syscall relacionadas con la espera, pero el tener llamadas read no es tan normal.
Lo siguiente que hicimos fue crear un script para estudiar con algo de mas detalle las llamadas read
root@host # cat syscall_read_pid.d
/*
* Presenta el tiempo empleado por cada llamada read
* si es superior a los 1000 mseg
*
* Como parametro acepta el PID del proceso
*
* Version: 1.0
*/
syscall::read:entry
/pid==$1/
{
array[tid,arg0]=timestamp;
self->fd=arg0;
self->th=tid;
self->sz=arg2;
self->vtype=(int)(curthread->t_procp->p_user.u_finfo.fi_list[arg0].uf_file->f_vnode->v_type);
}
syscall::read:return
/pid==$1 && (timestamp-array[tid,self->fd])/1000000 > 1000 && self->th == tid && self->vtype != 9/
{
printf("nTID: % 8d t FD: % 8d t Size: % 8d t Time: %d t %s t v_type DPort: ",tid,self->fd,self->sz,(timestamp-array[tid,self->fd])/1000000,probefunc);
}
syscall::read:return
/pid==$1 && (timestamp-array[tid,self->fd])/1000000 > 1000 && self->th == tid && self->vtype==9/
{
self->sdata=(sonode_t *)(curthread->t_procp->p_user.u_finfo.fi_list[self->fd].uf_file->f_vnode->v_data);
self->so_in=(struct sockaddr_in *)(self->sdata->so_faddr.soa_sa);
self->port=self->so_in->sin_port;
printf("nTID: % 8d t FD: % 8d t Size: % 8d t Time: %d t %s t v_type %d DPort: %d",tid,self->fd,self->sz,(timestamp-array[tid,self->fd])/1000000,probefunc,self->vtype,self->port);
}
Al ejecutar el script obtenemos una salida parecida a la siguiente.
root@host # dtrace -q -s ./syscall_read_pid.d 4096 TID: 224 FD: 9 Size: 32768 Time: 7510 read v_type 9 DPort: 5002 TID: 118 FD: 46 Size: 8 Time: 9113 read v_type 9 DPort: 1521 TID: 224 FD: 9 Size: 32768 Time: 7503 read v_type 9 DPort: 5002 TID: 224 FD: 9 Size: 32768 Time: 7507 read v_type 9 DPort: 5002 TID: 118 FD: 46 Size: 8 Time: 9106 read v_type 9 DPort: 1521 TID: 224 FD: 9 Size: 32768 Time: 7515 read v_type 9 DPort: 5002 TID: 118 FD: 46 Size: 8 Time: 8733 read v_type 9 DPort: 1521
De la salida del script syscall_read_pid.d podemos ver que hay llamadas de sistemas read las cuales están demorando unos 9 segundos, además son llamadas que utilizan un FD a un puerto 1521, que es el de BD. Tenemos que identificar qué se ha solicitado a la BD para que la respuesta sea tan lenta, ya que las syscall las debemos considerar desde el punto de vista de ejecución de un thread como una operación atómica. Otro aspecto curioso de este ejemplo es que lo que se devuelve en la llamada read son únicamente 8 bytes.
root@host # dtrace -q -s ./syscall_sendread_pid.d 4096 > /tmp/salida_dtrace
root@host # cat /tmp/salida_dtrace | more
Time: 495
Time: 1495
2091 TID: 224 FD: 9 Size: 32768 Time: 0 read entry
Time: 2495
2039 TID: 223 FD: 9 Size: 32768 Time: 0 send entry
2039 TID: 223 FD: 9 Size: 32768 Time: 0 send return
0 1 2 3 4 5 6 7 8 9 a b c d e f 0123456789abcdef
0: 78 c0 01 39 1f e7 38 cd 63 c7 bf b5 80 01 5a 55 x..9..8.c.....ZU
10: 16 a7 9b dd b8 43 e0 00 01 05 1f f8 a3 37 be bf .....C.......7..
20: 79 c0 01 0a 54 e7 3b cd 63 c7 bc b5 80 01 45 a9 y...T.;.c.....E.
30: 5e f6 da b9 92 d2 94 00 05 ad 74 f4 a7 37 b1 53 ^.........t..7.S
40: 1b 85 01 09 05 ac 31 99 6f 78 8e f4 80 02 14 a3 ......1.ox......
50: 16 b0 9b df 65 cd e0 00 05 2b 0f bc e5 67 b8 a7 ....e....+...g..
60: 3c 85 01 09 05 a5 79 cd 6f 7a 96 b1 80 0e a9 cf <.....y.oz......
70: 1b f3 98 8e fc bc e0 01 2c a2 18 14 65 37 bd ee ........,...e7..
80: 51 48 4e cf 8c e7 2d cd 6c 2b d2 f0 80 02 15 ab QHN...-.l+......
90: 5e f8 87 96 a3 bc e3 50 14 2a 57 bd e7 7f e9 ef ^......P.*W.....
a0: 7b 9a 5d 0a 55 ad 78 85 3b 7b dd a0 92 02 15 aa {.].U.x.;{......
b0: 5f bb cf de f4 ec f3 00 05 2b 56 f4 b2 37 be bf _........+V..7..
c0: 6c c0 01 0e 54 e7 2d cd 6c 2b cb f0 80 22 17 e3 l...T.-.l+..."..
d0: 0a f3 98 8e e0 bc e0 20 07 62 03 bc e5 67 aa ef ....... .b...g..
...
7797 TID: 118 FD: 46 Size: 169 Time: 0 read entry
7797 TID: 118 FD: 46 Size: 169 Time: 0 read return
0 1 2 3 4 5 6 7 8 9 a b c d e f 0123456789abcdef
0: 00 00 06 02 01 01 00 01 0a 00 00 00 07 06 76 6f ..............vo
10: 71 2e 61 78 15 01 01 01 07 06 76 6f 72 2e 61 78 q.ax......vor.ax
20: 15 01 01 01 07 06 76 6f 73 2e 61 78 15 01 01 01 ......vos.ax....
30: 07 06 76 6f 74 2e 61 78 15 01 01 01 07 06 76 6f ..vot.ax......vo
40: 75 2e 61 78 15 01 01 01 07 06 76 6f 76 2e 61 78 u.ax......vov.ax
50: 15 01 01 01 07 09 78 38 71 6b 31 70 2e 61 78 15 ......x8qk1p.ax.
60: 01 01 01 07 ....
El contenido del fichero temporal es la salida de la instrucción tracemem, ahora tendriamos que sacar la información de este fichero. Mediante un script en PERL podemos tratar nuestro fichero para que de una salida mas sencilla, pero este es un trabajo que dejo aquí para quien se anime. Nosotros vamos a seguir paso a paso. Lo siguiente es buscar en el fichero /tmp/salida_dtrace todas las líneas correspondientes al thread 118 que es el que ha obtenido respuestas lentas de la BD
root@tcapp04 # cat /tmp/salida_dtrace | grep "TID: 118" ... 8076 TID: 118 FD: 46 Size: 17 Time: 0 send return 8076 TID: 118 FD: 46 Size: 8 Time: 0 read entry 17183 TID: 118 FD: 46 Size: 8 Time: 9106 read return 17183 TID: 118 FD: 46 Size: 210 Time: 0 read entry 17183 TID: 118 FD: 46 Size: 210 Time: 0 read return 17184 TID: 118 FD: 46 Size: 23 Time: 0 send entry 17184 TID: 118 FD: 46 Size: 23 Time: 0 send return ... 17247 TID: 118 FD: 46 Size: 218 Time: 0 read return 17247 TID: 118 FD: 46 Size: 17 Time: 0 send entry 17247 TID: 118 FD: 46 Size: 17 Time: 0 send return 17248 TID: 118 FD: 46 Size: 8 Time: 0 read entry 25981 TID: 118 FD: 46 Size: 8 Time: 8733 read return 25981 TID: 118 FD: 46 Size: 65 Time: 0 read entry 25981 TID: 118 FD: 46 Size: 65 Time: 0 read return root@host #
Con la salida anterior podemos identificar el comportamiento de las llamadas a sistemas read y send y lo que nos debería llamar la atención es el tiempo transcurrido entre la entrada en el read y la salida de dicha llamada a sistema, hay un intervalo de 9,1 segundos. Una vez que hemos detectado este read, debemos saber qué se envió a la BD mediante la llamada send para intentar identificar la causa de la lentitud. Buscamos en el fichero de salida de dtrace todas las lineas anteriores a los 8076 milisegundos y encontramos que en el milisegundo 8070 se ejecuta una llamada send
8070 TID: 118 FD: 46 Size: 2048 Time: 0 send entry
8070 TID: 118 FD: 46 Size: 2048 Time: 0 send return
0 1 2 3 4 5 6 7 8 9 a b c d e f 0123456789abcdef
0: 08 00 00 00 06 00 00 00 00 20 03 5e 00 02 80 29 ......... .^...)
10: 00 01 02 25 e2 01 01 0d 00 00 00 00 04 7f ff ff ...%............
20: ff 01 02 01 32 00 00 00 00 00 00 00 0a 53 45 4c ....2........SEL
30: 45 43 54 20 44 49 53 54 49 4e 43 54 20 44 6f 63 ECT DISTINCT Doc
....
Ahora solo tenemos que sacar la consulta y averiguar si está bien construida, faltan indices, etc. Pero este es otro asunto. Este blog es un ejemplo de como una herramienta como DTrace nos puede ayudar a identificar puntos lentos en nuestras aplicaciones.
Comentarios Recientes
Sobre
Esta plantilla a sido creada con la validacion de CSS y XHTML, por N.Design Studio.Los iconos usados son de Web 2 Mini pack.