MySQL Query Profiling

This inbuilt part of MySQL allows you to look closely at queries run – per session. And you can use this information to find bottlenecks. To enable profiling, run this command in the MySQL client:

SET profiling = 1;

This will turn on the profiling. Then for each query you run, MySQL will log all the queries and extra information about them.

Run yourself some queries, and then run this command:

SHOW PROFILES;

It will show you a standard MySQL recordset of the queries you have run, each with an individual ID, in the order that you ran them.

+----------+-------------+--------------------------------------------------------+
| Query_ID | Duration    | Query                                                  |
+----------+-------------+--------------------------------------------------------+
|        1 |  0.00009260 | SELECT fieldname FROM table WHERE field = 'value'      |
+----------+-------------+--------------------------------------------------------+
There will be as many rows as queries that you ran. And that’s not it, you can drill down even more, to see what the duration is made up with… To drill down on a query, make a note of the Query_ID and use the following statement:
SHOW PROFILE FOR QUERY 1;
The resultset will be a list of operations that MySQL ran in order to complete the query. For example:
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000033 |
| checking query cache for query | 0.000073 |
| Opening tables                 | 0.000013 |
| System lock                    | 0.000007 |
| Table lock                     | 0.000035 |
| init                           | 0.000032 |
| optimizing                     | 0.000014 |
| statistics                     | 0.000016 |
| preparing                      | 0.000014 |
| executing                      | 0.000009 |
| Sending data                   | 0.331296 |
| end                            | 0.000016 |
| end                            | 0.000003 |
| query end                      | 0.000005 |
| storing result in query cache  | 0.000105 |
| freeing items                  | 0.000012 |
| closing tables                 | 0.000007 |
| logging slow query             | 0.000003 |
| logging slow query             | 0.000048 |
| cleaning up                    | 0.000006 |
+--------------------------------+----------+
20 rows in set (0.00 sec)
So you can see all the different operations performed by the server for that one query. This is invaluable in finding problems I would say in slow queries and bottlenecks in the database.
There is also a CPU profile you can use to see the CPU’s timings, and to do this, you just add on the CPU keyword:
SHOW PROFILE CPU FOR QUERY 1;
There are others you can use, MEMORY, BLOCK IO, SWAPS, etc. They are all available in the MySQL reference for the SHOW PROFILE syntax, http://dev.mysql.com/doc/refman/5.0/en/show-profiles.html
Profiling was introduced in MySQL version 5.0.37 Community Server.

Leave a Reply

Your email address will not be published.

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <s> <strike> <strong>

This site uses Akismet to reduce spam. Learn how your comment data is processed.