Entras por SSH, haces un top de manual y ahí lo ves: mysqld chupándose un 99.9% de CPU. Sudores fríos. El Load Average de la máquina Linux por las nubes. La base de datos está sufriendo, y tú con ella.

Estos días he estado pegándome con un cuello de botella de los que hacen época. Tienes una aplicación en PHP que iba como un tiro hace un año, pero ahora que la tabla de registros ha pasado del millón de filas, de repente todo se vuelve inmanejable. Hoy no quiero hablaros de cómo diseñar la base de datos o desnormalizarla para ganar rendimiento (eso ya lo vimos). Hoy vamos a meternos al barro con algo más directo: cómo saber exactamente qué demonios está haciendo MySQL con nuestra consulta.

El clásico EXPLAIN

El primer paso cuando pillas una consulta lenta en tu slow query log (espero que lo tengas activado en el my.cnf) es plantarle un EXPLAIN delante. Esto es básico, pero veo a mucha gente tirando de intuición en lugar de mirar los datos.

EXPLAIN SELECT p.id, p.titulo, c.nombre 
FROM posts p 
JOIN categorias c ON p.cat_id = c.id 
WHERE p.estado = 'publicado' 
ORDER BY p.fecha_publicacion DESC LIMIT 50;

Si en la columna Extra ves cosas como Using filesort o Using temporary, tienes un problema. Significa que MySQL está creando tablas temporales en disco o cargando todo en memoria para ordenarlo, en lugar de usar un índice. Esto destroza el rendimiento si tienes mucha carga concurrente.

Entrando en las tripas: SHOW PROFILES

Pero a veces el EXPLAIN se queda corto. Te dice el plan de ejecución, pero no dónde se está gastando el tiempo exactamente. Desde MySQL 5.0.37 (y ahora en las versiones 5.1 que solemos tener montadas en los servidores web), tenemos una joya oculta que mucha gente ignora: el profiling.

Para usarlo, primero tienes que habilitarlo en tu sesión de consola de MySQL:

mysql> SET profiling = 1;

Luego, lanzas tu maldita consulta lenta, esa que tarda 4 segundos en devolver los resultados. Una vez acabe, ejecutas:

mysql> SHOW PROFILES;

Esto te devolverá una tabla con el Query_ID y el tiempo total de ejecución. Supongamos que nuestra consulta conflictiva tiene el ID 1. Ahora viene la magia de verdad:

mysql> SHOW PROFILE FOR QUERY 1;

El resultado es un desglose microscópico de los hilos de ejecución. Vas a ver cosas como esta:

+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000021 |
| Opening tables       | 0.000014 |
| System lock          | 0.000006 |
| Table lock           | 0.000010 |
| init                 | 0.000022 |
| optimizing           | 0.000005 |
| statistics           | 0.000011 |
| preparing            | 0.000010 |
| executing            | 0.000003 |
| Copying to tmp table | 3.120562 |
| Sorting result       | 0.540121 |
| Sending data         | 0.231014 |
| end                  | 0.000005 |
| query end            | 0.000004 |
| freeing items        | 0.000012 |
| closing tables       | 0.000008 |
| logging slow query   | 0.000003 |
| cleaning up          | 0.000004 |
+----------------------+----------+

¡Pum! Ahí lo tienes. En este ejemplo real, el problema no es que traiga muchos datos (Sending data tarda poco), sino que se pasa 3 malditos segundos copiando datos a una tabla temporal en disco (Copying to tmp table). Esto pasa mucho cuando la tabla temporal es demasiado grande para los parámetros de memoria (tmp_table_size y max_heap_table_size) y MySQL decide tirarla a disco, que es infinitamente más lento.

Conclusión

Perfilar consultas de esta manera es artesanía pura, y te ahorra muchísimas horas de palos de ciego cambiando índices a lo loco o reescribiendo código.

Cada vez manejamos más gigas de datos y MySQL hace lo que puede, pero tener que mirar con lupa el tiempo de procesador milisegundo a milisegundo desde la consola parece algo de otra época.

Nos leemos.