Archivo de la etiqueta: debug

Depurando problemas con nginx

[spanish]La semana pasada he estado pegándome con un problemilla que tenía con el nginx de mi blog: de vez en cuando se quedaba frito, no respondía a ningún request y tenía que reinciarlo. Hace tiempo que monté un script que se ejcutaba cada X minutos, comprobaba si se había quedado tostado y lo reiniciaba, pero esto no es una solución, sólo una ñapa termporal.

Como decía he estado unos días mirándolo con más detalle, y preguntando en la lista de correo de nginx. Un detalle importante que me dijeron allí es que el log de error se puede poner en modo «debug», que saca trazas bastante completas de lo que está haciendo cada proceso (con su PID) en cada paso del procesado de las requests: cabeceras, rewrites, proxies, cgis … todo.

error_log /var/log/nginx/$host-error.log debug;

Con esto, sabiendo el PID del proceso que está chungo, es muy fácil ver qué estaba haciendo en el momento que se ha quedado colgado. Y para juntar una cosa con la otra, el script que usaba para detectar los cuelgues, en el que añadí varias métricas como un netstat -nap (que saca el PID), un ps, vmstat, etc.:

#!/bin/sh

TIMEOUT=20
CHECK=http://localhost/wp-admin/
LOG=/var/log/checkWeb/checkWeb-$(date +%Y%m%d).log
LOGR=/var/log/checkWeb/restart-$(date +%Y%m%d).log
TMP=/tmp/checkWeb-$RANDOM

if ! wget -t 1 -o /dev/null -O /dev/nul -T $TIMEOUT $CHECK
then
echo "ERROR, reiniciando nginx"
echo "** REINICIANDO **" >> $TMP
date >> $TMP
echo "- CLOSE_WAIT:" >> $TMP
netstat -nap | grep -c CLOSE_WAIT >> $TMP
echo "- vmstat" >> $TMP
vmstat 1 5 >> $TMP
echo "- free" >> $TMP
free >> $TMP
echo "- ps" >> $TMP
ps aux >> $TMP
echo "- netstat" >> $TMP
netstat -nap >> $TMP
echo "" >> $TMP
echo "" >> $TMP

#       pkill -9 -f php-cgi
pkill -9 -f nginx
sleep 1s
/etc/init.d/nginx start

cat $TMP
cat $TMP >> $LOG
date >> $LOGR
fi

rm -rf $TMP

De esta forma, cada vez que localhost/wp-admin (estaba debuggeando un WordPress) no respondía, aparte de reiniciar nginx, me guardaba en un log bastante información sobre el sistema. Con el tiempo vi que siempre que se quedaba colgado, había varios procesos nginx con sockets en el estado CLOSE_WAIT. Con ese PID y el error.log de nginx en modo debug, vi que siempre que un proceso se quedaba colgado con sockets en CLOSE_WAIT, lo último que había estado sirviendo era lo mismo: en el blog tengo varios ejemplos de cómo ejecutar servidores con daemontools; daemontools utiliza «named pipes» (FIFO) en disco, que básicamente si no tienen un proceso alimentándolos, para el que los lee son un agujero negro; cuando nginx se ponía a servir uno de estos FIFO es cuando se quedaba frito.

Lo curioso es que no había tenido problemas ni con Apache ni con lighttpd. Aunque desde luego el problema es que esos FIFO no deberían estar ahí. Los quité y llevo más de cinco días sin cuelgues, cuando antes tenía 3-4 al día mínimo.[/spanish]

[english]Last week I’ve been debugging a problem I had with this site’s nginx server: from time to time it hanged and I had to restart the process. Some time ago I wrote a little script that checked if it was running OK and restarted it otherwise, but anyway that wasn’t a real solution.

So I spent some days really looking into it and asking for support and reporting my findings to the nginx mailing list. One useful tip I got there was enabling the «debug» mode on the error log, which shows full traces of the processes (including their PID) as they’re processing the request, the rewrites, upstreams, etc.

error_log /var/log/nginx/$host-error.log debug;

With this extended log and the PID of the process malfunctioning, it’s quite easy finding out what that process was doing right before hanging. In order to find out the PID of the hanged processes, I extended my check-reboot script to log some generic system metrics right before restarting nginx: netstat -nap (which shows the PID), ps, vmstat, etc.

#!/bin/sh

TIMEOUT=20
CHECK=http://localhost/wp-admin/
LOG=/var/log/checkWeb/checkWeb-$(date +%Y%m%d).log
LOGR=/var/log/checkWeb/restart-$(date +%Y%m%d).log
TMP=/tmp/checkWeb-$RANDOM

if ! wget -t 1 -o /dev/null -O /dev/nul -T $TIMEOUT $CHECK
then
echo "ERROR, restarting nginx"
echo "** RESTARTING **" >> $TMP
date >> $TMP
echo "- CLOSE_WAIT:" >> $TMP
netstat -nap | grep -c CLOSE_WAIT >> $TMP
echo "- vmstat" >> $TMP
vmstat 1 5 >> $TMP
echo "- free" >> $TMP
free >> $TMP
echo "- ps" >> $TMP
ps aux >> $TMP
echo "- netstat" >> $TMP
netstat -nap >> $TMP
echo "" >> $TMP
echo "" >> $TMP

#       pkill -9 -f php-cgi
pkill -9 -f nginx
sleep 1s
/etc/init.d/nginx start

cat $TMP
cat $TMP >> $LOG
date >> $LOGR
fi

rm -rf $TMP

This way, each time localhost/wp-admin was unresponsive (I was debugging a WP site), besides restarting nginx I was getting a lot of system info. With time I got to realize that nginx processes were not actually hanging, but some of their sockets got on the CLOSE_WAIT state forever until the process was restarted. Looking for the PID of those processes according to netstat on the error log, the last request they were processing before getting to the CLOSE_WAIT state was always the same: on my blog I have some examples of how running servers with daemontools; daemontools uses named pipes (FIFOs), which can become kind of black holes if there’s no process feeding them; when nginx hit one of these FIFOs, it hanged.

Funny thing is that I never had this problem with either Apache nor lighttpd. But anyway the problem is not nginx but those FIFOs which shouldn’t really be there. I removed them and have had no hanged processes in five days, while before this nginx was restarting 3-4 times a day.[/english]

iostat & iotop: I/O debugging

[spanish]

Hace unos meses tuvimos un caso raro en un cliente: una aplicación no daba el rendimiento que debería, sin embargo más del 20% de CPU estaba en estado «idle» y no se había tocado la swap, por lo que no era por falta de recursos. Fijándonos mejor en los porcentajes de CPU que daba vmstat, vimos que alrededor del 30% estaba en I/O, por lo que el problema era un cuello de botella en entrada/salida.

Para averiguar la causa utilizamos dos programas:

  • iostat (viene en el paquete sysstat): similar a vmstat o ifstat, pero para operaciones de I/O. Muestra por dispositivo y por partición, cada X segundos, la cantidad de bloques leídos/escritos.
  • iotop: como el top de toda la vida, pero ordena los procesos por consumo de I/O.

Con ayuda de éstas dos utilidades es fácil detectar qué programa está causando el cuello de botella, y en qué dispositivo.

En nuestro caso, el problema era una controladora RAID hardware que estaba dando muy mal rendimiento de escritura, unida a un programa que realizaba del orden de 15 pequeñas escrituras aleatorias por segundo.

[/spanish]

[english]

A couple of months ago, we had an interesting issue at a customer: an application wasn’t performing well, but the system had more than 20% CPU idle and wasn’t swapping memory, so it wasn’t a lack of resources. After a deeper look into vmstat, we saw a constant 30% of CPU in I/O state. We had some kind of I/O bottleneck.

To discover the root of the issue we used two programs:

  • iostat (comes with the sysstat package): similar to vmstat or ifstat, but shows I/O operations per device and partition, updating its output every X seconds.
  • iotop: like the classic top, sorting the processes according to their I/O rate.

By using these two utilities it’s quite easy to discover which process is creating the I/O bottleneck, and on which particular device.

In our case, the problem was a RAID controller that was giving a terrible writing performance, coupled with a process that was doing around 15 small, random access writes per second.

[/english]