MySQL: query profiler

By: Javier on 10/28/2011

Una de las grandes innovaciones de MySQL en la versión 5 fue incluir un pequeño truco, no muy extendido, que permite detectar problemas de rendimiento en nuestra BD: query profiler.

Esta funcionalidad, desactivada por defecto en MySQL, desglosa cada una de las partes de las que se compone una consulta. Está especialmente pensado para query's complejas, con varios join's. De esta forma se podrían optimizar mejor las consultas a la BD y así obtener un mejor rendimiento. Gracias a ella podemos descubrir en qué partes la consulta es más rápida y cual es la que le lleva más tiempo realizar. Un ejemplo:

mysql> set profiling=1;
Query OK, 0 rows affected (0.00 sec)

mysql> show databases;
+------------------------+
| Database               |
+------------------------+
| CV                     |
| documentacion          |
| gastos                 |
| mysql                  |
| test                   |
| viajes                 |
+------------------------+
23 rows in set (0.00 sec)

mysql> use gastos;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed

mysql> show profiles;
+----------+------------+---------------------------+
| Query_ID | Duration   | Query                     |
+----------+------------+---------------------------+
|        1 | 0.00037500 | show databases            |
|        2 | 0.00012600 | SELECT DATABASE()         |
|        3 | 0.19438700 | select count(*) from fact |
+----------+------------+---------------------------+
6 rows in set (0.00 sec)

mysql> select count(*) from facturacion;
+----------+
| count(*) |
+----------+
|   239319 |
+----------+
1 row in set (0.19 sec)

mysql> show profile for query 3;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000011 |
| checking query cache for query | 0.000026 |
| Opening tables                 | 0.000009 |
| System lock                    | 0.000003 |
| Table lock                     | 0.000026 |
| init                           | 0.000008 |
| optimizing                     | 0.000003 |
| statistics                     | 0.000007 |
| preparing                      | 0.000004 |
| executing                      | 0.000004 |
| Sending data                   | 0.193768 |
| end                            | 0.000012 |
| query end                      | 0.000003 |
| freeing items                  | 0.000159 |
| storing result in query cache  | 0.000290 |
| logging slow query             | 0.000002 |
| logging slow query             | 0.000048 |
| cleaning up                    | 0.000004 |
+--------------------------------+----------+
18 rows in set (0.00 sec)

mysql> set profiling=0;
Query OK, 0 rows affected (0.00 sec)

La sintaxis del comando es:

SHOW PROFILE [type [, type] ... ]
    [FOR QUERY n]
    [LIMIT row_count [OFFSET offset]]

Donde type puede ser alguno de estos valores:

• ALL: Muestra toda la información.
• BLOCK IO: Muestra los bloqueos de I/O.
• CONTEXT SWITCHES: Muestra las alternancias entre contextos voluntarios e involuntarios.
• CPU: Tiempo de CPU.
• IPC: Mensajes enviados y recibidos.
• PAGE FAULTS: Contador de major y minor pages.
• SOURCE: Muestra el nombre de las funciones del código y la línea.
• SWAPS: Contador de swap.

Por ejemplo, la query anterior mostrando los consumos de CPU quedaría,

mysql> show profile cpu for query 6;
+---------------------------+----------+----------+------------+
| Status                    | Duration | CPU_user | CPU_system |
+---------------------------+----------+----------+------------+
| starting                  | 0.000011 | 0.000000 |   0.000000 |
| checking query cache for  | 0.000026 | 0.000000 |   0.000000 |
| Opening tables            | 0.000009 | 0.000000 |   0.000000 |
| System lock               | 0.000003 | 0.000000 |   0.000000 |
| Table lock                | 0.000026 | 0.000000 |   0.000000 |
| init                      | 0.000008 | 0.000000 |   0.000000 |
| optimizing                | 0.000003 | 0.000000 |   0.000000 |
| statistics                | 0.000007 | 0.000000 |   0.000000 |
| preparing                 | 0.000004 | 0.000000 |   0.000000 |
| executing                 | 0.000004 | 0.000000 |   0.000000 |
| Sending data              | 0.193768 | 0.140009 |   0.012001 |
| end                       | 0.000012 | 0.000000 |   0.000000 |
| query end                 | 0.000003 | 0.000000 |   0.000000 |
| freeing items             | 0.000159 | 0.000000 |   0.000000 |
| storing result in query   | 0.000290 | 0.000000 |   0.000000 |
| logging slow query        | 0.000002 | 0.000000 |   0.000000 |
| logging slow query        | 0.000048 | 0.000000 |   0.000000 |
| cleaning up               | 0.000004 | 0.000000 |   0.000000 |
+---------------------------+----------+----------+------------+
18 rows in set (0.00 sec)

La utilidad es grande, ya que si observamos que una parte concreta de la query tarda mucho en ejecutarse, podemos optimizar dicha parte, ya sea la propia query o pensar en realizar, por ejemplo un índice que la acelere.