Últimos Cambios
Blog personal: El hilo del laberinto
|
|
|
Últimos Cambios |
|
Blog personal: El hilo del laberinto
|
|
|
Ú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:
[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 };-)
Más información sobre los OpenBadges
Donación BitCoin: 19niBN42ac2pqDQFx6GJZxry2JQSFvwAfS
