When troubleshooting issues inside of LMI, it can be useful to enable MySQL profiling.  This gives a number of statistics that can help to identify bottlenecks inside MySQL.

mysql> select @@profiling;
+-------------+
| @@profiling |
+-------------+
|           0 |
+-------------+
1 row in set, 1 warning (0.00 sec)

This shows that profiling is not currently enabled, so we need to turn it on.  Note that in this instance we will be setting a session variable.  It is possible to enable profiling globally inside my.cnf, but that is beyond the remit of this KB.

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

The query above enables profiling.  Note that the warning that is referenced refers to the fact that profiling may be removed in a later version.  Now that we have profiling enabled, we can run a query to create a profile.  I've chosen the following as it is reasonably intensive, which is useful for illustration:

mysql> select max(originalFilesize), min(originalFilesize), max(compressedFilesize), min(compressedFilesize), count(*) from logapprtrpt.stDataFiles;
+-----------------------+-----------------------+-------------------------+-------------------------+----------+
| max(originalFilesize) | min(originalFilesize) | max(compressedFilesize) | min(compressedFilesize) | count(*) |
+-----------------------+-----------------------+-------------------------+-------------------------+----------+
|               1303562 |                     0 |                  262144 |                  262144 |   196250 |
+-----------------------+-----------------------+-------------------------+-------------------------+----------+
1 row in set (0.15 sec)

We can now run the show profiles query:

mysql> show profiles;
+----------+------------+----------------------------------------------------------------------------------------------------------------------------------+
| Query_ID | Duration   | Query                                                                                                                            |
+----------+------------+----------------------------------------------------------------------------------------------------------------------------------+
|        1 | 0.15672400 | select max(originalFilesize), min(originalFilesize), max(compressedFilesize), min(compressedFilesize), count(*) from stDataFiles |
+----------+------------+----------------------------------------------------------------------------------------------------------------------------------+
1 row in set, 1 warning (0.00 sec)

We can now see the profile for our query by refering to it by Query_ID:

mysql> show profile for query 1;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000083 |
| checking permissions | 0.000011 |
| Opening tables       | 0.000035 |
| init                 | 0.000043 |
| System lock          | 0.000015 |
| optimizing           | 0.000008 |
| statistics           | 0.000023 |
| preparing            | 0.000018 |
| executing            | 0.000005 |
| Sending data         | 0.156215 |
| end                  | 0.000022 |
| query end            | 0.000014 |
| closing tables       | 0.000032 |
| freeing items        | 0.000177 |
| cleaning up          | 0.000024 |
+----------------------+----------+
15 rows in set, 1 warning (0.01 sec)

As you can see, we now have a breakdown of exactly where our time is being used.  In this instance, it is clear that, were we thinking this query were causing problems, we should focus on the Sending data phase.  In addition to this basic data, there are a number of additional sets of metrics that are captured by the profilier.  These are:

    • ALL - displays all information
    • BLOCK IO - displays counts for block input and output operations
    • CONTEXT SWITCHES - displays counts for voluntary and involuntary context switches
    • CPU - displays user and system CPU usage times
    • IPC - displays counts for messages sent and received
    • MEMORY - is not currently implemented
    • PAGE FAULTS - displays counts for major and minor page faults
    • SOURCE - displays the names of functions from the source code, together with the name and line number of the file in which the function occurs
    • SWAPS - displays swap counts

As an example, for our query above, we may wish to see the CPU stats and the source function inside MySQL that is associated.  We would then run:

mysql> show profile cpu, source for query 1;
+----------------------+----------+----------+------------+-----------------------+----------------------+-------------+
| Status               | Duration | CPU_user | CPU_system | Source_function       | Source_file          | Source_line |
+----------------------+----------+----------+------------+-----------------------+----------------------+-------------+
| starting             | 0.000083 | 0.000064 |   0.000013 | NULL                  | NULL                 |        NULL |
| checking permissions | 0.000011 | 0.000008 |   0.000002 | check_access          | sql_authorization.cc |         807 |
| Opening tables       | 0.000035 | 0.000030 |   0.000006 | open_tables           | sql_base.cc          |        5650 |
| init                 | 0.000043 | 0.000000 |   0.000860 | handle_query          | sql_select.cc        |         121 |
| System lock          | 0.000015 | 0.000000 |   0.000000 | mysql_lock_tables     | lock.cc              |         323 |
| optimizing           | 0.000008 | 0.000000 |   0.000000 | optimize              | sql_optimizer.cc     |         151 |
| statistics           | 0.000023 | 0.000000 |   0.000000 | optimize              | sql_optimizer.cc     |         367 |
| preparing            | 0.000018 | 0.000000 |   0.000000 | optimize              | sql_optimizer.cc     |         475 |
| executing            | 0.000005 | 0.000000 |   0.000000 | exec                  | sql_executor.cc      |         119 |
| Sending data         | 0.156215 | 0.147700 |   0.000000 | exec                  | sql_executor.cc      |         195 |
| end                  | 0.000022 | 0.000000 |   0.000000 | handle_query          | sql_select.cc        |         199 |
| query end            | 0.000014 | 0.000000 |   0.000000 | mysql_execute_command | sql_parse.cc         |        4967 |
| closing tables       | 0.000032 | 0.000000 |   0.000000 | mysql_execute_command | sql_parse.cc         |        5019 |
| freeing items        | 0.000177 | 0.000000 |   0.000000 | mysql_parse           | sql_parse.cc         |        5593 |
| cleaning up          | 0.000024 | 0.000000 |   0.000000 | dispatch_command      | sql_parse.cc         |        1902 |
+----------------------+----------+----------+------------+-----------------------+----------------------+-------------+
15 rows in set, 1 warning (0.00 sec)

Note that the ALL metric displays all of the others together.

This KB article will show how to enabling profiling inside MySQL.