systemadmin.es > DBA > SHOW PROFILE de MySQL

SHOW PROFILE de MySQL

El EXPLAIN a primera vista puede resultar algo confuso y en joins con muchas tablas tampoco nos indica en que esta perdiendo más tiempo el MySQL. Mediante SHOW PROFILE tendremos un detalle de los tiempos de ejecución.

Para poder ver los tiempos de ejecución deberemos dejar a 1 la variable de sesión profiling:

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

A continuación deberemos ejecutar las queries que queramos, pudiendo ver el resultado con SHOW PROFILE:

mysql> select id, object_id, concat(section,tag) , unix_timestamp(log_date) as thing_date from log where thing_timestamp >=  DATE_FORMAT(date_sub(CURRENT_TIMESTAMP(), interval 7 day),'%Y%m%d070000');
(...)
244606 rows in set (1.06 sec)

mysql> show profile;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000105 |
| checking permissions | 0.000009 |
| Opening tables       | 0.000025 |
| System lock          | 0.000013 |
| init                 | 0.000052 |
| optimizing           | 0.000012 |
| statistics           | 0.000069 |
| preparing            | 0.000017 |
| executing            | 0.000004 |
| Sending data         | 1.056121 |
| end                  | 0.000016 |
| query end            | 0.000004 |
| closing tables       | 0.000013 |
| freeing items        | 0.000021 |
| logging slow query   | 0.000004 |
| logging slow query   | 0.000786 |
| cleaning up          | 0.000125 |
+----------------------+----------+
17 rows in set (0.00 sec)

mysql>

En este caso podemos ver que el problema principal de esta query es que selecciona muchos datos. Usando EXPLAIN también lo podemos ver por las rows que examina:

mysql> explain select id, object_id, concat(section,tag) , unix_timestamp(log_date) as thing_date from log where thing_timestamp >=  DATE_FORMAT(date_sub(CURRENT_TIMESTAMP(), interval 7 day),'%Y%m%d070000');
+----+-------------+----------+-------+---------------+---------------+---------+------+--------+-------------+
| id | select_type | table    | type  | possible_keys | key           | key_len | ref  | rows   | Extra       |
+----+-------------+----------+-------+---------------+---------------+---------+------+--------+-------------+
|  1 | SIMPLE      | site_log | range | IDX_TIMESTAMP | IDX_TIMESTAMP | 4       | NULL | 367490 | Using where |
+----+-------------+----------+-------+---------------+---------------+---------+------+--------+-------------+
1 row in set (0.02 sec)

Podemos ver otro ejemplo con pocos registros de salida que el EXPLAIN ya tiene mala pinta:

mysql> select count(st.id) as total, s.region, s.lang from sites as s left join things as st on date_format(st.upload,'%m-%y')=date_format(now(),'%m-%y') and s.id_section=st.thing_section group by s.lang order by s.lang asc;
+----+-------------+-------+-------+---------------+-------------------+---------+------+--------+---------------------------------+
| id | select_type | table | type  | possible_keys | key               | key_len | ref  | rows   | Extra                           |
+----+-------------+-------+-------+---------------+-------------------+---------+------+--------+---------------------------------+
|  1 | SIMPLE      | s     | ALL   | NULL          | NULL              | NULL    | NULL |    537 | Using temporary; Using filesort |
|  1 | SIMPLE      | st    | index | NULL          | youtb_date_upload | 9       | NULL | 158470 | Using index                     |
+----+-------------+-------+-------+---------------+-------------------+---------+------+--------+---------------------------------+
2 rows in set (0.00 sec)

Y luego por el tamaño de las tablas podemos comprobar que tarda mucho la query. En este caso al usar tablas temporales:

mysql> select count(st.id) as total, s.region, s.lang from sites as s left join things as st on date_format(st.upload,'%m-%y')=date_format(now(),'%m-%y') and s.id_section=st.thing_section group by s.lang order by s.lang asc;
(...)
15 rows in set (1 min 16.19 sec)

mysql> show profile;
+----------------------+-----------+
| Status               | Duration  |
+----------------------+-----------+
| starting             |  0.000142 |
| checking permissions |  0.000007 |
| checking permissions |  0.000007 |
| Opening tables       |  0.000036 |
| System lock          |  0.000016 |
| init                 |  0.000054 |
| optimizing           |  0.000008 |
| statistics           |  0.000033 |
| preparing            |  0.000023 |
| Creating tmp table   |  0.000039 |
| executing            |  0.000004 |
| Copying to tmp table | 76.197538 |
| Sorting result       |  0.000036 |
| Sending data         |  0.000033 |
| end                  |  0.000004 |
| removing tmp table   |  0.000012 |
| end                  |  0.000005 |
| query end            |  0.000011 |
| closing tables       |  0.000022 |
| freeing items        |  0.000029 |
| logging slow query   |  0.000003 |
| logging slow query   |  0.000054 |
| cleaning up          |  0.000005 |
+----------------------+-----------+
23 rows in set (0.00 sec)

En el caso que ejecutemos varias queries podremos ver también los resultados uno a uno. Mediante SHOW PROFILES podremos las queries que tenemos disponibles:

mysql> show profiles;
+----------+------------+-------------------------------+
| Query_ID | Duration   | Query                         |
+----------+------------+-------------------------------+
|        1 | 0.00014300 | select NOW()                  |
|        2 | 0.00028700 | select NOW() union select '1' |
+----------+------------+-------------------------------+
2 rows in set (0.00 sec)

A continuación mediante SHOW PROFILE FOR QUERY y el identificador Query_ID podremos ver su resultado:

mysql> show profile for query 1;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000051 |
| checking permissions | 0.000011 |
| Opening tables       | 0.000009 |
| init                 | 0.000021 |
| optimizing           | 0.000006 |
| executing            | 0.000014 |
| end                  | 0.000006 |
| query end            | 0.000004 |
| closing tables       | 0.000004 |
| freeing items        | 0.000009 |
| logging slow query   | 0.000003 |
| cleaning up          | 0.000005 |
+----------------------+----------+
12 rows in set (0.00 sec)

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>