Member of The Internet Defense League Últimos cambios
Últimos Cambios
Blog personal: El hilo del laberinto Geocaching

Investigación de un problema de rendimiento sobre Solaris 10

Última Actualización: 02 de agosto de 2006 - Miércoles

Hace unos días estaba verificando la integridad de una de mis bases de datos BerkeleyDB cuando me tropecé con un importante problema de rendimiento en mis máquinas con Solaris 10.

Los pasos fueron más o menos los siguientes:

  1. Copio el fichero de base de datos a "/tmp", que es un sistema de ficheros montado sobre espacio "swap". Tengo 36 gigabytes de "swap", así que es el lugar perfecto.

  2. Copio los ficheros de log transacional de la base de datos a "/tmp".

  3. Hago un "db_recover" para que BerkeleyDB estabilice y actualice la copia de la base de datos en "/tmp". El comando completa su trabajo inmediatamente, como debe ser. Éste es el procedimiento canónico a seguir con bases de datos BerkeleyDB.

  4. A continuación hago un "db_verify" para verificar la integridad y consistencia de la base de datos en "/tmp". El procedimiento se completa con éxito, pero le lleva muchísimo tiempo:
    [root@tesalia z]# time /usr/local/BerkeleyDB.4.4/bin/db_verify storage.db
    
    real    3m45.092s
    user    0m10.319s
    sys     0m6.776s
    

Es decir, ha tardado casi cuatro minutos, pero solo ha consumido 17 segundos de CPU.

La diferencia podría estar justificada si la carga de CPU fuese muy alta, con lo que ese comando tendría que competir con el resto de la máquina. Pero no es el caso. La carga de CPU de esta máquina es vestigial.

Otra posible causa del problema es el disco duro. Pero la base de datos está copiada en "/tmp", que es un sistema de ficheros creado sobre el "swap". El "swap" reside en disco duro, pero con cuatro gigabytes de memoria RAM y apenas un gigabyte de base de datos a procesar, no espero que ocurra ningún "swapping" hacia disco.

¿Qué está pasando?.

El primer paso consiste en tener una idea de qué está haciendo el programa. Para ello utilizamos el comando "truss" de Solaris (el equivalente aproximado en Linux es "strace"). Su salida muestra un interminable número de llamadas al sistema "pread64()" y "pwrite64()". Hasta aquí todo normal, aunque las escrituras resultan un poco extrañas cuando se supone que el comando de verificación no altera la base de datos en modo alguno (más sobre esto luego).

Mi siguiente paso fue investigar qué llamadas al sistema ocupan más tiempo. Para ello empleo DTRACE, una excelentísima herramienta de diagnóstico de Solaris 10. El script que utilizo es el siguiente:

#!/usr/sbin/dtrace -s

unsigned long long t;

syscall:::entry
/pid==$1/
{
  t=timestamp;
}

syscall:::return
/(pid==$1) && t/
{
  @suma[probefunc]=sum(timestamp-t);
}

Este script dtrace contabiliza el tiempo que el programa pasa en cada llamada al sistema que efectúa.

Y su salida es:

  fstat64                                                        1825
  fcntl                                                          3705
  read                                                           4030
  open64                                                        10305
  stat64                                                        13619
  close                                                         92495
  pread64                                                  6075750833
  pwrite64                                               196440475999

Los tiempos son nanosegundos. Puede verse que, con una gran diferencia, la mayor pérdida de tiempo es en "pwrite64()". Sorprendente, entre otras cosas porque la verificación de una base de datos no debería alterarla en modo alguno. ¿A dónde van esas escrituras?. Lo veremos más adelante :-).

De momento investigo la distribución de tiempos de "pwrite()". Ello supone escribir un nuevo script dtrace:

#!/usr/sbin/dtrace -s

unsigned long long t;

syscall::pwrite64:entry
/pid==$1/
{
  t=timestamp;
}

syscall::pwrite64:return
/(pid==$1) && t/
{
  @suma[probefunc]=quantize(timestamp-t);
}

Y su salida es:

  pwrite64
           value  ------------- Distribution ------------- count
            1024 |                                         0
            2048 |@                                        16802
            4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@        433408
            8192 |@@@@                                     48677
           16384 |@                                        11597
           32768 |@                                        10423
           65536 |                                         1836
          131072 |                                         65
          262144 |                                         0
          524288 |                                         0
         1048576 |                                         0
         2097152 |                                         0
         4194304 |                                         0
         8388608 |                                         0
        16777216 |                                         0
        33554432 |                                         0
        67108864 |                                         1
       134217728 |                                         1
       268435456 |                                         2
       536870912 |                                         7
      1073741824 |                                         15
      2147483648 |                                         11
      4294967296 |                                         6
      8589934592 |                                         7
     17179869184 |                                         0

Recordando que los tiempos son nanosegundos, vemos que la inmensa mayoría de las llamadas se completan muy rápidamente, pero en unas pocas ocasiones algunas escrituras ¡¡pueden tardar varios segundos en completarse!!. ¡¡Segundos!!. De hecho hay trece llamadas que han tardado más de cuatro segundos en completarse, cada una. ¡Qué barbaridad!.

Por lo tanto, la mayor parte del tiempo transcurre en unas pocas llamadas al sistema, excepcionalmente lentas. Pero, ¿por qué son tan lentas?.

Para verlo con claridad necesitamos escribir un nuevo script dtrace. En esta ocasión estamos solo interesados en lo que ocurre dentro de "pwrite64()" cuando se ejecuta de forma lenta. Pero claro, no sabemos si ha sido una ejecución lenta o rápida hasta que la llamada al sistema se completa y termina, y en ese momento ya es demasiado tarde para analizar qué ha estado haciendo esa función un microsegundo antes.

Afortunadamente dtrace dispone de capacidad "especulativa", que permite realizar un análisis como siempre, para tirar el resultado al final si no estamos interesados en él. La idea, pues, es realizar siempre el análisis, pero mostrar sólo aquellos que nos interesan. Es decir, aquellos en los que "pwrite64()" ha tardado, por ejemplo, más de 5 segundos en ejecutarse. El script dtrace es el siguiente:

#!/usr/sbin/dtrace -Fs

unsigned long long t;
unsigned long long t2;
this unsigned long long t;

syscall::pwrite64:entry
/pid==$1/
{
  t=t2=timestamp;
  spec=speculation();
  speculate(spec);
}

syscall::pwrite64:return
/(pid==$1) && ((timestamp-t)>=5000000000)/
{
  t=0;
  speculate(spec);
  commit(spec);
}

syscall::pwrite64:return
/(pid==$1) && ((timestamp-t)<5000000000)/
{
  t=0;
  discard(spec);
}

fbt:::
/(pid==$1) && t/
{
  speculate(spec);
  this->t=timestamp;
  printf("%llu",this->t-t2);
  t2=this->t;
}

El análisis generado por una de esas llamadas lentas mide casi 80 Kbytes, así que no lo incluyo entero. Pero la porción relevante muestra un cambio de contexto de cinco segundos, en medio de la sincronización de discos duros (tengo un sistema RAID 1 o espejo). El cambio de contexto parece debido a la espera en una variable de condición:

[...]
  0            -> mirror_mark_resync_region   1297
  0              -> cv_wait                   1918
  0                -> thread_lock             1307
  0                <- thread_lock             1299
  0                -> cv_block                1575
  0                  -> ts_sleep              1671
  0                  <- ts_sleep              1750
  0                  -> new_mstate            1289
  0                    -> gethrtime_unscaled  1056
  0                    <- gethrtime_unscaled  948
  0                    -> cpu_update_pct      1105
  0                      -> scalehrtime       1178
  0                        -> tsc_scalehrtime 1455
  0                        <- tsc_scalehrtime 1004
  0                      <- scalehrtime       956
  0                      -> cpu_grow          1299
  0                        -> cpu_decay       1098
  0                        <- cpu_decay       1201
  0                      <- cpu_grow          1014
  0                    <- cpu_update_pct      1026
  0                  <- new_mstate            1550
  0                  -> disp_lock_enter_high  1075
  0                  <- disp_lock_enter_high  1236
  0                  -> disp_lock_exit_high   1156
  0                  <- disp_lock_exit_high   1149
  0                <- cv_block                1581
  0                -> disp_lock_exit_nopreempt 1007
  0                <- splx                    1128
  0              <- disp_lock_exit_nopreempt  1040
  0              -> swtch                     2068
  0                -> disp                    1941
  0                  -> disp_lock_enter       1143
  0                    -> lock_set_spl        1210
  0                    <- splx                1002
  0                  <- lock_set_spl          1065
  0                <- disp_lock_enter         1002
  0                -> disp_lock_exit          1184
  0                <- splx                    1007
  0              <- disp_lock_exit            995
  0              -> disp_getwork              1656
  0              <- splx                      1645
  0            <- disp_getwork                1463
  0            -> restore_mstate              1702
  0            <- restore_mstate              1731
  0          <- disp                          1949
  0          -> resume                        1968
  0            -> savectx                     1626
  0            <- savectx                     2142
  0            -> restorectx                  4961700909
  0            <- restorectx                  3861
  0          <- splx                          1091
  0        <- resume                          1007
  0      <- swtch                             1175
  0    <- cv_wait                             1292
[...]

El hecho de que esté involucrado el RAID indica que se están grabando datos en algún lugar misterioso, ya que la base de datos a analizar está en "/tmp", que dicho sistema de ficheros reside en el "swap" y que no hago mirror del "swap". ¿Dónde rayos está grabando?.

Usando la herramienta solaris "truss" vemos que los "pwrite64()" van todos al descriptor de ficheros número siete. ¿A qué fichero apunta ese descriptor?

[root@tesalia z]# truss -f /usr/local/BerkeleyDB.4.4/bin/db_verify storage.db 2>&1| grep "open.* 7$"
2208:   open64("/var/tmp/BDB02208", O_RDWR|O_CREAT|O_EXCL, 0600) = 7

Al parecer se crea un fichero de trabajo temporal en "/var/tmp", al que se van haciendo escrituras a mansalva. Imagino que para mantener lo mínimo en RAM mientras se analiza la integridad de una base de datos, de forma que se puedan analizar bases de datos muy grandes. Vaya, ya hemos resuelto el misterio de las escrituras :-). ¿Cuánto se escribe en ese fichero temporal?. Usando "truss", veo que se producen 609423 llamadas a "pwrite64()", cada una de ellas de 1Kbyte. En total se escriben, por tanto, unos 609423 megabytes. Tampoco parece tanto...

A priori el directorio "/var/tmp/" debería utilizar también el "swap", dada su naturaleza. ¿Qué ocurre si lo montamos así?. Para ello añadimos una línea "swap - /var/tmp tmpfs - yes -" a nuestro "/etc/vfstab", seguido de un "mount -a". Veamos ahora lo que tarda en verificar la base de datos:

[root@tesalia z]# time /usr/local/BerkeleyDB.4.4/bin/db_verify  storage.db

real    0m14.279s
user    0m9.750s
sys     0m4.525s

¡Hemos pasado de casi cuatro minutos a catorce segundos!.

Hemos solucionado el problema de rendimiento, aunque no sabemos la causa última inicial. Investigar el tema más a fondo queda como ejercicio para el lector };-)


Historia

  • 02/ago/06: Primera versión de esta página.



Python Zope ©2006 jcea@jcea.es

Más información sobre los OpenBadges

Donación BitCoin: 19niBN42ac2pqDQFx6GJZxry2JQSFvwAfS