Desde la versión 5 de MySql se incorpora al cliente esta funcionalidad para conocer más al detalle los tiempos de ejecución de cada consulta. Si activamos esta opción podremos ver desglosadas las partes que la forman y en como se distribuye el tiempo total de la consulta. Para buscar problemas en determinados procesos o descubrir donde está el cuello de botella es un opción bastante útil. En si, de una manera muy simplificada, nos puede mostrar información similar a la que nos puede dar MS SQL Server Profiler aunque con una diferencia muy importante: solo podemos analizar las consultas de nuestra sesión actual y las que ejecutamos a partir de su activación con un cambio de parámetro.
Eso quiere decir que no podemos atacar directamente a las aplicaciones si no que debemos cazar las consultas problemáticas al vuelo del log de slow-querys o del log de mysql...
Vamos a ver como funciona. Primero lo habilitamos para la sesión actual:
mysql> set profiling = 1; Query OK, 0 rows affected (0.00 sec)
A continuación ejecutamos una consulta de ejemplo:
mysql> select count(*) from mysql.db; +----------+ | count(*) | +----------+ | 766 | +----------+ Query OK, 0 rows affected (0.00 sec)
Luego, para ver el detalle usamos show profile:
mysql> show profile for query 1; +--------------------------------+----------+ | Status | Duration | +--------------------------------+----------+ | starting | 0.000143 | | Waiting for query cache lock | 0.000048 | | checking query cache for query | 0.000070 | | checking permissions | 0.000050 | | Opening tables | 0.000058 | | System lock | 0.000052 | | init | 0.000054 | | optimizing | 0.000050 | | executing | 0.000052 | | end | 0.000048 | | query end | 0.000047 | | closing tables | 0.000051 | | freeing items | 0.000055 | | logging slow query | 0.000047 | | cleaning up | 0.000048 | +--------------------------------+----------+ Query OK, 0 rows affected (0.00 sec)
El caso anterior es un ejemplo muy trivial, vemos que los tiempos son ínfimos y el resultado es el esperado. Realmente no hay nada que buscar. También es útil saber que si usamos un script, podemos ver con posterioridad un listado con las consultas que se han ejecutado, aunque vereis que a cada consulta desde la activación del parámetro se le asigna un autoincremental. También sirve simplemente para comparar tiempos totales de ejecución de consultas consecutivas ejecutadas con el profiling acivado. Para listarlas ejecutamos show profiles:
mysql> show profiles; +----------+------------+-------------------------------+ | Query_ID | Duration | Query | +----------+------------+-------------------------------+ | 1 | 0.00086975 | select count(*) from mysql.db | +----------+------------+-------------------------------+ 1 rows in set (0.00 sec)
En otros casos, quizás más reales, podemos tener una consulta que tarda mucho en ejecutarse en mysql y lo descubrimos porque tenemos habilitado y/o controlamos de vez en cuando las slow querys que se ejecutan sobre la base de datos. Investigamos más, vemos su plan de ejecución y aparentemente usa índice aunque está haciendo una join entre dos tablas además de tener una ordenación. Nada raro... Aparentemente. Por ejemplo, hemos podido creer que se estaban usando los índices, pero existe la posibilidad de que sin darnos cuenta los estemos inhabilitando porque sin percatarnos estamos usando una conversión implicita en la condición de unión que está obligando a la base de datos a crear una copia temporal de la tabla (además para aplicar una ordenación!). La salida del profiler podría ser algo así:
mysql> show profile for query 4; +--------------------------------+-----------+ | Status | Duration | +--------------------------------+-----------+ | starting | 0.000100 | | Waiting for query cache lock | 0.000048 | | checking query cache for query | 0.000116 | | checking permissions | 0.000048 | | checking permissions | 0.000046 | | checking permissions | 0.000047 | | checking permissions | 0.000048 | | Opening tables | 0.000065 | | System lock | 0.000051 | | Waiting for query cache lock | 0.000067 | | init | 0.000081 | | optimizing | 0.000061 | | statistics | 0.000099 | | preparing | 0.000070 | | executing | 0.000047 | | Sending data | 0.078635 | | Waiting for query cache lock | 0.000075 | | Sending data | 0.000047 | | storing result in query cache | 16.043585 | | end | 0.000119 | | query end | 0.000051 | | closing tables | 0.000052 | | freeing items | 0.000061 | | logging slow query | 0.000047 | | logging slow query | 0.000047 | | cleaning up | 0.000050 | +--------------------------------+-----------+ 26 rows in set (0.00 sec)
Viendo esto pensamos wow! Algo falla con la cache. Pues entonces miramos de deshabilitarla para la sesión actual y entonces volvemos a ejecutar la consulta para finalmente ver el profile...
mysql> SET SESSION query_cache_type = OFF; Query OK, 0 rows affected (0.00 sec)
mysql> show profile for query 7; +----------------------+-----------+ | Status | Duration | +----------------------+-----------+ | starting | 0.000206 | | checking permissions | 0.000049 | | checking permissions | 0.000047 | | checking permissions | 0.000047 | | checking permissions | 0.000048 | | Opening tables | 0.000067 | | System lock | 0.000052 | | init | 0.000081 | | optimizing | 0.000062 | | statistics | 0.000103 | | preparing | 0.000073 | | executing | 0.000048 | | Sending data | 16.554224 | | end | 0.000124 | | query end | 0.000048 | | closing tables | 0.000052 | | freeing items | 0.000062 | | logging slow query | 0.000048 | | logging slow query | 0.000048 | | cleaning up | 0.000049 | +----------------------+-----------+ 20 rows in set (0.00 sec)
Finalmente ya vemos ya que el problema es en el envío de datos. Esto ya nos tiene que llevar a pensar que la consulta puede ser optimizable. Usaremos explain para ver el plan de ejecución y pensar si es mejorable la consulta, la indexación etc...
En conclusión...
... Mysql Query Profiler me parece útil como algo complementario al EXPLAIN para ver planes de ejecución. Si con EXPLAIN podremos ver problemas derivados de la planificación o la forma de la consulta, con Query Profiler podremos ver otro tipo de incidencias. Me imagino que en ocasiones donde tengamos problemas a nivel de servidor, demasiada concurrencia, algun parámetro olvidado que ralentiza (slow querys), falta de memoria etc saltarán malos tiempos a la vista si sabemos cuales son los tiempos base o los aceptables, aunque para temas de optimización general de MySQL es mejor utilizar otros métodos para mejorar el rendimiento.
En otro post explicaré un poquito como funciona EXPLAIN y lo que no nos gustará encontrar al utilizarlo.
