DTrace: Consultas lentas en BD

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.