Encontrar la raíz del problema en un entorno LAMP (II)
Anteriormente ya vimos evaluar el estado de un Apache mediante su server-status, hoy vamos a ver como evaluar el estado de un MySQL
Malditos administradores de sistemas
En caso de problemas resulta muy importante guardar la salida de los comandos que ejecutemos, ya que en un primer momento siempre se analiza a ojo y rápidamente todo lo que uno puede pero posteriormente con se pueden sacar más datos útiles. Para ello resulta muy útil el comando tee de MySQL mediante cual almacenamos los comandos SQL en un fichero.
Para ver el estado de un MySQL con las queries que se estan ejecutando podemos usar el comando SHOW FULL PROCESSLIST:
mysql> show full processlist; +----------+-------------+---------------------+---------------+-------------+--------+----------------------------------------------------------------+-----------------------+ | Id | User | Host | db | Command | Time | State | Info | +----------+-------------+---------------------+---------------+-------------+--------+----------------------------------------------------------------+-----------------------+ | 12776 | slave | 172.16.100.8:59453 | NULL | Binlog Dump | 687370 | Has sent all binlog to slave; waiting for binlog to be updated | NULL | | 12777 | slave | 172.16.100.1:41442 | NULL | Binlog Dump | 687369 | Has sent all binlog to slave; waiting for binlog to be updated | NULL | | 18994821 | systemadmin | 172.17.11.130:52701 | systemadminWP | Sleep | 16 | | NULL | | 19004000 | root | localhost | NULL | Query | 0 | NULL | show full processlist | | 19004088 | systemadmin | 172.16.100.9:50711 | systemadminWP | Sleep | 0 | | NULL | | 19004097 | systemadmin | 172.16.100.9:50723 | systemadminWP | Sleep | 0 | | NULL | | 19004098 | systemadmin | 172.16.100.9:40345 | systemadminWP | Sleep | 0 | | NULL | | 19004099 | systemadmin | 172.16.100.9:40347 | systemadminWP | Sleep | 0 | | NULL | | 19004100 | systemadmin | 172.16.100.9:50726 | systemadminWP | Sleep | 0 | | NULL | +----------+-------------+---------------------+---------------+-------------+--------+----------------------------------------------------------------+-----------------------+ 9 rows in set (0.00 sec)
Típicamente en un entorno LAMP veremos pocas conexiones activas en el MySQL ya que se suelen abrir y cerrar. Deberemos mirar con un estado “normal” las que hay pero podemos decir sin miedo a equivocarnos que si hay más de 100 queries es que tenemos un problema.
Ante situaciones como esta suele pasar que acabamos con un error de “Too many connections“:
# mysql ERROR 1040 (00000): Too many connections
Es evidente que si cambiamos el valor y reiniciamos solucionamos el problema en ese instante, pero no por el cambio del valor, sino por el hecho de reiniciar el MySQL. El cambio del valor simplemente hace que tarde un poco más a dar el error, pero el MySQL ya hace tiempo que ha dejado de ser funcional.
Para situaciones como esta deberemos entrar como root y sacar el processlist, ya que aunque hayamos llegado al límite de conexiones (max_connections y max_user_connections) el MySQL nos reserva una para las conexiones de usuarios con el privilegio SUPER.
Es por esto que deberíamos evitar usar procesos con usuarios SUPER, ya que en caso de algún problema podríamos quedarnos sin esta conexión extra para ver que pasa.
Cuando se nos queda un MySQL frito de conexiones resulta muy típico que sea por Lockeds (columna State):
mysql> show full processlist; +-----+-----------+-----------+---------------+---------+------+------------+----------------------------------------+ | Id | User | Host | db | Command | Time | State | Info | +-----+-----------+-----------+---------------+---------+------+------------+----------------------------------------+ | 113 | root | localhost | systemadminWP | Query | 38 | User sleep | insert into comments select sleep(100) | | 117 | root | localhost | systemadminWP | Query | 7 | Locked | insert into comments values(1) | | 118 | root | localhost | systemadminWP | Query | 8 | Locked | insert into comments values(1) | | 119 | root | localhost | systemadminWP | Query | 20 | Locked | insert into comments values(1) | | 120 | root | localhost | NULL | Query | 0 | NULL | show full processlist | +-----+-----------+-----------+---------------+---------+------+------------+----------------------------------------+ 11 rows in set (0.00 sec)
Este es un ejemplo muy evidente usando un sleep, en un caso real tendríamos queries mezcladas por el medio de otras tablas y muchas más lineas. Para buscar la query que esta causando problemas podemos valernos del sort por la columna 6 (Time):
# echo "show full processlist;" | mysql | sort -nk 6 133 root localhost NULL Query 0 NULL show full processlist Id User Host db Command Time State Info 117 root localhost systemadminWP Query 2 Locked insert into comments values(1) 118 root localhost systemadminWP Query 6 Locked insert into comments values(1) 119 root localhost systemadminWP Query 11 Locked insert into comments values(1) 113 root localhost systemadminWP Query 46 User sleep insert into comments select sleep(100)
En al última linea que se muestre veremos la query que lleva más tiempo, por lo que será la que tiene más números de ser la que causa el problema.
Podemos optar por matar la query con un kill con el ID que vemos en la primera columna:
mysql> kill 113; Query OK, 0 rows affected (0.00 sec)
En situaciones dónde realmente tenemos un problema y se nos bloquea frecuentemente podemos llegar a dejar un proceso que mate las sesiones cuando pasan de un cierto límite. Lógicamente esto debe entenderse como una solución temporal mientras se solucionan los problemas de la aplicación, nunca como algo permanente.
Pero no siempre tiene porque ser así de simple, por ejemplo:
# echo "show full processlist;" | mysql | sort -nk 6 148 root localhost NULL Query 0 NULL show full processlist Id User Host db Command Time State Info 119 root localhost systemadminWP Query 3 Waiting for release of readlock insert into comments values(1) 118 root localhost systemadminWP Sleep 42 NULL 145 root localhost systemadminWP Query 55 Waiting for release of readlock insert into comments values(1) 113 root localhost systemadminWP Query 87 Waiting for release of readlock insert into comments select sleep(100) 117 root localhost systemadminWP Query 107 Waiting for release of readlock insert into comments values(1)
En este caso por mucho que matemos las queries que llevan más tiempo no vamos a liberar el bloqueo. Éstas están bloqueadas pero sin el estado Locked, por lo que deberemos fijarnos en el comentario:
Waiting for release of readlock insert into comments values(1)
Lo que tenemos es que se han bloqueado las tablas con:
mysql> flush tables with read lock; Query OK, 0 rows affected (31.38 sec)
En este caso seguramente tendremos algún problema con el backup, para liberar el bloqueo simplemente tendremos que hacer un unlock tables:
mysql> unlock tables; Query OK, 0 rows affected (0.00 sec)
Por otro lado tenemos el log de slow queries de dónde también podemos analizar los problemas. Por defecto se quedan registradas todas las queries que tardan más de 10 segundos, pero en un entorno LAMP resulta muy conveniente registrar todas las que tardan más de 1 segundo:
slow_query_log=1
Este log puede llegar a crecer mucho, por lo que se hace imprescindible rotar periódicamente este log de MySQL. No solo por tamaño, sino que luego resultará mucho más cómo de tratar.
Dicho log lo podemos leer directamente o pasarlo por una herramienta de análisis como puede ser el mk-query-digest del Maatkit.
Mediante esta herramienta podemos llegar a ver las slow queries dentro de un límite de fechas con las opciones –since y –until. Incluso con un poco de scripting podemos sacar el informe para cada minuto de una hora:
$ for i in $(seq -w 0 58); do echo "# HORA: 23:$i"; mk-query-digest /var/log/mysql/mysqld-slow.log --since "2010-06-21 23:$i:00" --until "2010-06-21 23:$(if [ $(echo "$i+1" | bc -l | wc -c) -eq 2 ]; then echo 0; fi)$(echo "$i+1" | bc -l):59" | sed -n '/^# Rank/,$p'; done
En el caso de páginas web recién salidas del horno no suelen aparecer slow queries por la falta de carga. Para evitar problemas cuando empiece a tener visitas es muy recomendable habilitar la opción de registrar las queries que no usen índices:
log_queries_not_using_indexes=1
Con esta opción y mejorando las queries que se registren evitaremos problemas futuros.
Con esto hemos visto problemas comunes, pero cada entorno es único por lo que debe ser evaluado cada caso.
Relacionados
Imprimir
Deja un comentario: