Profiling

Cuando EXPLAIN te muestra el plan que MySQL elige para ejecutar una consulta, obtienes información valiosa sobre qué índices se usan y cuántas filas se estiman. Pero EXPLAIN no te dice cuánto tiempo pasa MySQL en cada fase interna de la ejecución: abriendo tablas, enviando datos, creando archivos temporales de ordenación, esperando bloqueos. Para ese nivel de detalle necesitas profiling, la capacidad de medir el tiempo que MySQL invierte en cada paso del procesamiento interno de una consulta.

MySQL ofrece dos mecanismos de profiling. El primero es SHOW PROFILE, un comando clásico que permite activar la medición por sesión y ver un desglose detallado de cada fase. El segundo es Performance Schema, el sistema de instrumentación moderno que recopila estadísticas de rendimiento a nivel del servidor. Ambos se complementan y cada uno tiene sus fortalezas según el escenario.

SHOW PROFILE: el método clásico

El comando SHOW PROFILE fue durante años la herramienta estándar para diagnosticar el rendimiento interno de consultas individuales. Aunque está marcado como obsoleto desde MySQL 5.6, sigue funcionando en MySQL 8.0 y continúa siendo útil por su simplicidad: activar, ejecutar, analizar. Tres pasos sin configuración adicional.

El profiling por sesión registra información detallada sobre cada fase de ejecución de las consultas: cuánto tiempo pasa MySQL parseando la consulta, optimizando el plan, abriendo tablas, leyendo datos, ordenando resultados, enviando la respuesta al cliente y cerrando la conexión.

Activar el profiling

Para empezar a recopilar información de profiling, activa la variable de sesión profiling. Esta configuración solo afecta a tu sesión actual y no impacta a otros usuarios conectados al servidor:

-- Activar profiling para la sesión actual
SET profiling = 1;

Una vez activado, MySQL registrará automáticamente las estadísticas de tiempo de cada consulta que ejecutes en esa sesión. Por defecto, guarda las últimas 15 consultas, pero puedes aumentar este límite hasta 100 con SET profiling_history_size = 100.

Ejecutar y listar consultas

Ahora ejecuta las consultas que quieres analizar. Pueden ser consultas normales de tu aplicación o consultas de prueba que sospeches que son lentas:

-- Ejecutar algunas consultas de ejemplo
SELECT c.nombre, COUNT(p.id) AS total_pedidos
FROM clientes c
LEFT JOIN pedidos p ON p.cliente_id = c.id
GROUP BY c.id, c.nombre
ORDER BY total_pedidos DESC
LIMIT 10;
 
SELECT producto_id, SUM(cantidad) AS unidades_vendidas
FROM detalle_pedidos
GROUP BY producto_id
HAVING unidades_vendidas > 100;

Después de ejecutar las consultas, usa SHOW PROFILES (con S final) para ver la lista de todas las consultas registradas junto con su tiempo total de ejecución:

SHOW PROFILES;
+----------+------------+------------------------------------------------------------+
| Query_ID | Duration   | Query                                                      |
+----------+------------+------------------------------------------------------------+
|        1 | 0.00245300 | SELECT c.nombre, COUNT(p.id) AS total_pedidos FROM clie... |
|        2 | 0.01832100 | SELECT producto_id, SUM(cantidad) AS unidades_vendidas ... |
+----------+------------+------------------------------------------------------------+

La columna Duration muestra el tiempo total en segundos. Aquí podemos ver que la segunda consulta tardó casi 8 veces más que la primera. Para entender por qué, necesitamos ver el desglose interno.

Ver el desglose de una consulta

El comando SHOW PROFILE FOR QUERY N muestra el tiempo invertido en cada fase interna de la consulta especificada:

SHOW PROFILE FOR QUERY 2;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000042 |
| checking permissions           | 0.000008 |
| Opening tables                 | 0.000018 |
| init                           | 0.000025 |
| System lock                    | 0.000009 |
| optimizing                     | 0.000015 |
| statistics                     | 0.000032 |
| preparing                      | 0.000019 |
| Creating tmp table             | 0.000045 |
| executing                      | 0.012850 |
| end                            | 0.000006 |
| removing tmp table             | 0.000018 |
| end                            | 0.000004 |
| query end                      | 0.000008 |
| waiting for handler commit     | 0.000012 |
| closing tables                 | 0.000010 |
| freeing items                  | 0.000019 |
| cleaning up                    | 0.000011 |
+--------------------------------+----------+

En este desglose podemos identificar rápidamente que la fase executing consume casi todo el tiempo (12.8 ms de los 18.3 ms totales), y que MySQL creó una tabla temporal (Creating tmp table) para resolver el GROUP BY. Si viéramos un tiempo alto en Creating sort index, sabríamos que el problema es la ordenación, no la lectura de datos.

Las fases más comunes que encontrarás en el profiling y su significado son las siguientes. Opening tables indica el tiempo que MySQL pasa abriendo las tablas necesarias para la consulta; un tiempo alto aquí sugiere un problema con la caché de tablas (table_open_cache). executing representa el tiempo de ejecución real del plan de consulta, incluyendo lecturas de disco y procesamiento de filas. Creating tmp table aparece cuando MySQL necesita una tabla temporal para resolver GROUP BY, ORDER BY o DISTINCT que no pueden resolverse con índices. Creating sort index indica que MySQL está ordenando resultados sin poder usar un índice adecuado. Sending data (en versiones anteriores a 8.0) incluye tanto la lectura de filas como el envío al cliente.

Profiling de CPU y E/S de disco

Para obtener información más detallada sobre los recursos consumidos, puedes solicitar métricas de CPU y operaciones de disco:

-- Ver tiempos de CPU por fase
SHOW PROFILE CPU FOR QUERY 2;
+--------------------------------+----------+----------+------------+
| Status                         | Duration | CPU_user | CPU_system |
+--------------------------------+----------+----------+------------+
| starting                       | 0.000042 | 0.000031 | 0.000009   |
| executing                      | 0.012850 | 0.008200 | 0.002100   |
| Creating tmp table             | 0.000045 | 0.000030 | 0.000012   |
| ...                            | ...      | ...      | ...        |
+--------------------------------+----------+----------+------------+
-- Ver operaciones de E/S de disco
SHOW PROFILE BLOCK IO FOR QUERY 2;
+--------------------------------+----------+----------------+-----------------+
| Status                         | Duration | Block_ops_in   | Block_ops_out   |
+--------------------------------+----------+----------------+-----------------+
| executing                      | 0.012850 |           1024 |               0 |
| Creating tmp table             | 0.000045 |              0 |              32 |
| ...                            | ...      | ...            | ...             |
+--------------------------------+----------+----------------+-----------------+

Las columnas Block_ops_in y Block_ops_out revelan cuántas operaciones de lectura y escritura a disco se realizaron en cada fase. Si la fase executing muestra un número alto de Block_ops_in, significa que MySQL está leyendo datos del disco en lugar de encontrarlos en el buffer pool, lo que podría indicar que necesitas más memoria para innodb_buffer_pool_size.

También puedes combinar varios tipos de información en una sola solicitud:

SHOW PROFILE CPU, BLOCK IO, MEMORY FOR QUERY 2;

Nota sobre la deprecación

Es importante saber que SHOW PROFILE está marcado como deprecated (obsoleto) desde MySQL 5.6.7. Esto significa que funciona perfectamente en MySQL 8.0 y seguirá funcionando por un tiempo, pero podría eliminarse en una versión futura. MySQL recomienda usar Performance Schema como reemplazo a largo plazo. Sin embargo, para diagnósticos rápidos en una sesión de depuración, SHOW PROFILE sigue siendo la opción más rápida por su simplicidad.

Para desactivar el profiling cuando ya no lo necesites:

SET profiling = 0;

Performance Schema: el método moderno

Performance Schema es el sistema de instrumentación integrado en MySQL que recopila métricas de rendimiento detalladas sobre prácticamente todos los aspectos del servidor. A diferencia de SHOW PROFILE, que solo registra información de tu sesión actual, Performance Schema opera a nivel del servidor y puede monitorizar consultas de todas las conexiones simultáneamente.

Performance Schema está habilitado por defecto en MySQL 8.0 y almacena los datos en tablas del esquema performance_schema. No usa almacenamiento en disco tradicional: los datos residen en memoria con estructuras optimizadas que minimizan el impacto en el rendimiento del servidor. El overhead típico es del 5-10%, aunque depende de cuántos instrumentos tengas activados.

Verificar y configurar Performance Schema

Antes de usar Performance Schema, comprueba que está habilitado y que los instrumentos necesarios están activos:

-- Verificar que Performance Schema está habilitado
SHOW VARIABLES LIKE 'performance_schema';
+--------------------+-------+
| Variable_name      | Value |
+--------------------+-------+
| performance_schema | ON    |
+--------------------+-------+

Los "instrumentos" (instruments) son los puntos de medición y los "consumidores" (consumers) determinan qué datos se recopilan. Para el profiling de consultas, necesitas activar los instrumentos de statements y los consumidores de historial:

-- Activar instrumentos de sentencias (suelen estar activos por defecto)
UPDATE performance_schema.setup_instruments
SET ENABLED = 'YES', TIMED = 'YES'
WHERE NAME LIKE 'statement/%';
 
-- Activar instrumentos de fases (stages) para desglose detallado
UPDATE performance_schema.setup_instruments
SET ENABLED = 'YES', TIMED = 'YES'
WHERE NAME LIKE 'stage/%';
 
-- Activar consumidores para el historial de eventos
UPDATE performance_schema.setup_consumers
SET ENABLED = 'YES'
WHERE NAME IN (
    'events_statements_history',
    'events_statements_history_long',
    'events_stages_history',
    'events_stages_history_long'
);

La tabla setup_instruments controla qué se mide y la tabla setup_consumers controla dónde se almacenan los datos medidos. Activar instrumentos de stages es lo que te permite obtener un desglose similar a SHOW PROFILE pero con datos más precisos.

Consultar el historial de sentencias

Una vez configurado, Performance Schema registra automáticamente las consultas ejecutadas. La tabla events_statements_history almacena las últimas consultas de cada thread (conexión), mientras que events_statements_history_long mantiene un historial más extenso de todo el servidor:

-- Ver las consultas recientes de tu sesión actual
SELECT EVENT_ID,
       TRUNCATE(TIMER_WAIT / 1000000000000, 6) AS duracion_seg,
       SQL_TEXT,
       ROWS_EXAMINED,
       ROWS_SENT,
       CREATED_TMP_TABLES,
       CREATED_TMP_DISK_TABLES,
       NO_INDEX_USED
FROM performance_schema.events_statements_history
WHERE THREAD_ID = (
    SELECT THREAD_ID FROM performance_schema.threads
    WHERE PROCESSLIST_ID = CONNECTION_ID()
)
ORDER BY EVENT_ID DESC
LIMIT 10;
+----------+--------------+------------------------------------------+---------------+-----------+--------------------+-------------------------+--------------+
| EVENT_ID | duracion_seg | SQL_TEXT                                 | ROWS_EXAMINED | ROWS_SENT | CREATED_TMP_TABLES | CREATED_TMP_DISK_TABLES | NO_INDEX_USED|
+----------+--------------+------------------------------------------+---------------+-----------+--------------------+-------------------------+--------------+
|      185 |     0.018321 | SELECT producto_id, SUM(cantidad) AS ... |         45000 |        23 |                  1 |                       0 |            0 |
|      184 |     0.002453 | SELECT c.nombre, COUNT(p.id) AS tota... |          8720 |        10 |                  1 |                       0 |            0 |
+----------+--------------+------------------------------------------+---------------+-----------+--------------------+-------------------------+--------------+

Las columnas de esta tabla proporcionan información extremadamente valiosa que no obtienes con SHOW PROFILE. ROWS_EXAMINED vs ROWS_SENT te dice cuántas filas leyó MySQL internamente frente a cuántas devolvió al cliente: una diferencia grande indica ineficiencia. CREATED_TMP_DISK_TABLES mayor que cero significa que la tabla temporal no cabía en memoria y se escribió a disco, un problema serio de rendimiento. NO_INDEX_USED igual a 1 indica que la consulta hizo un full table scan.

Desglose por fases (stages)

Para obtener el equivalente de SHOW PROFILE con Performance Schema, consulta las tablas de stages vinculadas a una sentencia específica. Esto muestra el tiempo que MySQL pasó en cada fase interna:

-- Obtener el desglose de fases de la última consulta
SELECT es.EVENT_NAME AS fase,
       TRUNCATE(es.TIMER_WAIT / 1000000000000, 6) AS duracion_seg
FROM performance_schema.events_stages_history_long es
JOIN performance_schema.events_statements_history_long est
    ON es.NESTING_EVENT_ID = est.EVENT_ID
WHERE est.SQL_TEXT LIKE 'SELECT producto_id%'
ORDER BY es.TIMER_START;
+----------------------------------------------+--------------+
| fase                                         | duracion_seg |
+----------------------------------------------+--------------+
| stage/sql/starting                           |     0.000038 |
| stage/sql/checking permissions               |     0.000007 |
| stage/sql/Opening tables                     |     0.000016 |
| stage/sql/init                               |     0.000022 |
| stage/sql/System lock                        |     0.000008 |
| stage/sql/optimizing                         |     0.000013 |
| stage/sql/statistics                         |     0.000028 |
| stage/sql/preparing                          |     0.000017 |
| stage/sql/Creating tmp table                 |     0.000041 |
| stage/sql/executing                          |     0.012715 |
| stage/sql/end                                |     0.000005 |
| stage/sql/removing tmp table                 |     0.000016 |
| stage/sql/query end                          |     0.000007 |
| stage/sql/waiting for handler commit         |     0.000010 |
| stage/sql/closing tables                     |     0.000009 |
| stage/sql/freeing items                      |     0.000017 |
| stage/sql/cleaning up                        |     0.000009 |
+----------------------------------------------+--------------+

Este desglose es prácticamente idéntico al de SHOW PROFILE, pero con la ventaja de que los datos se almacenan en tablas consultables con SQL estándar. Esto significa que puedes filtrar, agregar y cruzar datos de profiling con otros datos de Performance Schema de formas que SHOW PROFILE no permite.

Resúmenes estadísticos por tipo de consulta

Una de las grandes ventajas de Performance Schema es la capacidad de agregar estadísticas por "digest" (firma normalizada de la consulta). Esto te permite identificar las consultas que más recursos consumen a lo largo del tiempo, no solo en una ejecución individual:

-- Top 10 consultas que más tiempo acumulan
SELECT DIGEST_TEXT,
       COUNT_STAR AS ejecuciones,
       TRUNCATE(SUM_TIMER_WAIT / 1000000000000, 4) AS tiempo_total_seg,
       TRUNCATE(AVG_TIMER_WAIT / 1000000000000, 4) AS tiempo_medio_seg,
       SUM_ROWS_EXAMINED AS filas_examinadas_total,
       SUM_ROWS_SENT AS filas_enviadas_total,
       SUM_CREATED_TMP_DISK_TABLES AS tablas_tmp_disco
FROM performance_schema.events_statements_summary_by_digest
ORDER BY SUM_TIMER_WAIT DESC
LIMIT 10;
+-----------------------------------------------+-------------+------------------+------------------+------------------------+---------------------+------------------+
| DIGEST_TEXT                                   | ejecuciones | tiempo_total_seg | tiempo_medio_seg | filas_examinadas_total | filas_enviadas_total | tablas_tmp_disco |
+-----------------------------------------------+-------------+------------------+------------------+------------------------+---------------------+------------------+
| SELECT `c`.`nombre`, COUNT(`p`....            |        1842 |          28.4210 |           0.0154 |              16058640  |               18420 |                0 |
| SELECT `producto_id`, SUM(`can...             |         923 |          16.9013 |           0.0183 |              41535000  |               21229 |              412 |
| SELECT * FROM `pedidos` WHERE ...             |       12480 |          14.2300 |           0.0011 |               3744000  |              249600 |                0 |
+-----------------------------------------------+-------------+------------------+------------------+------------------------+---------------------+------------------+

Esta vista es oro puro para la optimización. Puedes ver que la segunda consulta ha creado 412 tablas temporales en disco a lo largo de sus 923 ejecuciones, lo que indica un problema serio que justifica la creación de un índice adecuado o una reescritura de la consulta.

Flujo de trabajo práctico de diagnóstico

El profiling alcanza su máximo potencial cuando lo integras en un flujo de trabajo estructurado de diagnóstico. Seguir un proceso metódico evita que pierdas tiempo optimizando la parte equivocada de la consulta.

El flujo recomendado comienza identificando la consulta lenta, ya sea a través de los slow query logs, de Performance Schema o de las métricas de tu aplicación. Una vez identificada, el siguiente paso es analizar su plan de ejecución con EXPLAIN para entender qué estrategia usa MySQL. Si EXPLAIN muestra un plan razonable pero la consulta sigue siendo lenta, el profiling te revela dónde está el verdadero cuello de botella.

Paso 1: identificar y perfilar la consulta

-- Activar profiling
SET profiling = 1;
 
-- Ejecutar la consulta sospechosa
SELECT c.nombre, c.email,
       COUNT(p.id) AS total_pedidos,
       SUM(p.total) AS importe_total,
       MAX(p.fecha) AS ultimo_pedido
FROM clientes c
JOIN pedidos p ON p.cliente_id = c.id
WHERE p.fecha >= '2025-01-01'
GROUP BY c.id, c.nombre, c.email
HAVING importe_total > 500
ORDER BY importe_total DESC;
 
-- Ver el desglose
SHOW PROFILE FOR QUERY 1;

Paso 2: interpretar los resultados

Cuando examinas el desglose, busca las fases que consumen un porcentaje desproporcionado del tiempo total. Cada patrón apunta a una solución diferente.

Si la fase executing domina el tiempo, el problema está en la lectura de datos. Esto generalmente indica que falta un índice adecuado o que MySQL está leyendo del disco en lugar del buffer pool. Revisa el plan de ejecución con EXPLAIN y comprueba si puedes crear un índice compuesto que cubra las columnas del WHERE y el JOIN.

Si Creating tmp table y removing tmp table son significativos, MySQL no puede resolver el GROUP BY o el ORDER BY con los índices disponibles. La solución es crear un índice cuyas columnas coincidan con las columnas de agrupación u ordenación.

Si Creating sort index consume tiempo, MySQL está haciendo un filesort (ordenación en memoria o disco). Verifica si puedes añadir un índice que proporcione el orden necesario, evitando la ordenación explícita.

Si las operaciones de E/S de disco (Block_ops_in) son excesivas durante la ejecución, los datos no están en el buffer pool de InnoDB. Esto puede significar que innodb_buffer_pool_size es demasiado pequeño para tu dataset, o que la consulta accede a datos "fríos" que rara vez se usan.

Paso 3: aplicar la optimización y verificar

Una vez identificado el cuello de botella, aplica la técnica de optimización correspondiente y vuelve a perfilar para confirmar que la mejora es real:

-- Crear el índice que resuelve el cuello de botella
CREATE INDEX idx_pedidos_fecha_cliente ON pedidos (fecha, cliente_id);
 
-- Ejecutar de nuevo y comparar
SET profiling = 1;
 
SELECT c.nombre, c.email,
       COUNT(p.id) AS total_pedidos,
       SUM(p.total) AS importe_total,
       MAX(p.fecha) AS ultimo_pedido
FROM clientes c
JOIN pedidos p ON p.cliente_id = c.id
WHERE p.fecha >= '2025-01-01'
GROUP BY c.id, c.nombre, c.email
HAVING importe_total > 500
ORDER BY importe_total DESC;
 
SHOW PROFILE FOR QUERY 1;

Compara el desglose antes y después. Si la fase executing se redujo significativamente, el índice resolvió el problema de lectura. Si Creating tmp table desapareció, el nuevo índice permite agrupar sin tabla temporal. Usa EXPLAIN ANALYZE para obtener los tiempos reales del plan de ejecución y confirmar la mejora desde otra perspectiva.

Cuándo el problema no es el plan de consulta

Uno de los descubrimientos más valiosos del profiling es que a veces el plan de ejecución es correcto y la consulta sigue siendo lenta por razones que EXPLAIN no puede mostrar. El profiling revela estos problemas ocultos que de otra forma serían muy difíciles de diagnosticar.

Un ejemplo clásico es una consulta que usa el índice correcto pero la fase executing sigue tardando mucho porque los datos necesarios no están en memoria y MySQL debe leerlos del disco. En este caso, el profiling de BLOCK IO muestra un número alto de operaciones de lectura. La solución no es cambiar la consulta ni el índice, sino aumentar el tamaño del buffer pool o añadir más RAM al servidor.

Otro caso frecuente es un tiempo alto en System lock o waiting for handler commit, lo que indica contención con otras transacciones. La consulta en sí es eficiente, pero otras conexiones están bloqueando el acceso a las filas necesarias. Este tipo de problema solo se descubre con profiling y la solución es revisar las transacciones concurrentes, no la consulta individual.

También puede ocurrir que Creating tmp table muestra que MySQL crea la tabla temporal en disco (CREATED_TMP_DISK_TABLES en Performance Schema). Esto sucede cuando la tabla temporal excede tmp_table_size o max_heap_table_size, o cuando contiene columnas TEXT o BLOB que impiden usar tablas temporales en memoria. La solución es ajustar estos límites, reescribir la consulta para evitar columnas grandes en la tabla temporal o reducir el tamaño del resultado intermedio con filtros más restrictivos.

El profiling transforma la optimización de consultas de un ejercicio de adivinanza en un proceso basado en datos. En lugar de probar índices al azar o reescribir consultas esperando que mejoren, puedes medir exactamente dónde se invierte el tiempo e invertir tu esfuerzo de optimización donde tendrá el mayor impacto.

Escrito por Eduardo Lázaro