systemadmin.es > LAMP y web > Encontrar la raíz del problema en un entorno LAMP (II)

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

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.

Deja un comentario:

XHTML - Tags permitidos:<a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <s> <strike> <strong>