Pages

Wednesday, April 13, 2011

MySQL: Profiling

MySQL: Profiling




Hope this you in SQL query tuning using MySQL Profiler
The SQL Profiler is built into the database server and can be dynamically enabled/disabled via the MySQL client utility. To begin profiling one or more SQL queries, simply issue the following command:
mysql> set profiling=1;
Query OK, 0 rows affected (0.00 sec)
Two things happen once you issue this command. First, any query you issue from this point on will be traced by the server with various performance diagnostics being created and attached to each distinct query. Second, a memory table named profiling is created in the INFORMATION_SCHEMA database for your particular session (not viewable by any other MySQL session) that stores all the SQL diagnostic results. This table remains persistent until you disconnect from MySQL at which point it is destroyed.
Now, simply execute a SQL query:
mysql> select count(*) from client where broker_id=2;
+----------+
| count(*) |
+----------+
|      200 |
+----------+
1 row in set (0.00 sec)
Once the query completes, you can issue the following command to view the SQL profiles that have currently been stored for you:
mysql> show profiles;
+----------+------------+-----------------------------------------------+
| Query_ID | Duration   | Query                                         |
+----------+------------+-----------------------------------------------+
|        0 | 0.00007300 | set profiling=1                               |
|        1 | 0.00044700 | select count(*) from client where broker_id=2 |
+----------+------------+-----------------------------------------------+
2 rows in set (0.00 sec)
You get a quick summary of all your captured SQL plus the total duration that the query took to complete. To get the same diagnostic info, you can also query the memory table that holds your statistical information:
mysql> select sum(duration) from information_schema.profiling where query_id=1;
+---------------+
| sum(duration) |
+---------------+
|      0.000447 |
+---------------+
1 row in set (0.00 sec)
I'll show you why it's good to be able to query the memory-based profiling table later in this article, but for now, let's concentrate on other SHOW commands that you can use to get more detailed diagnostic info about one or more queries that you've profiled. The most basic command is one that lists the steps a profiled query went through to satisfy your SQL request, along with each step's time:
mysql> show profile for query 1;
+--------------------+------------+
| Status             | Duration   |
+--------------------+------------+
| (initialization)   | 0.00006300 |
| Opening tables     | 0.00001400 |
| System lock        | 0.00000600 |
| Table lock         | 0.00001000 |
| init               | 0.00002200 |
| optimizing         | 0.00001100 |
| statistics         | 0.00009300 |
| preparing          | 0.00001700 |
| executing          | 0.00000700 |
| Sending data       | 0.00016800 |
| end                | 0.00000700 |
| query end          | 0.00000500 |
| freeing items      | 0.00001200 |
| closing tables     | 0.00000800 |
| logging slow query | 0.00000400 |
+--------------------+------------+
15 rows in set (0.00 sec)
You can also just issue SHOW PROFILE and exclude the identification of a specific profile number to see the very last profile you created.
Regardless of how you obtain the output, you can see this data is extremely valuable in that it allows you to see where your query spends its time during execution. This is done for all types of queries, and not just SELECT statements as this example shows:
mysql> alter table t engine=myisam;
Query OK, 112050 rows affected (0.64 sec)
Records: 112050  Duplicates: 0  Warnings: 0


mysql> show profiles;
+----------+------------+-----------------------------------------------+
| Query_ID | Duration   | Query                                         |
+----------+------------+-----------------------------------------------+
|        0 | 0.00007300 | set profiling=1                               |
|        1 | 0.00044700 | select count(*) from client where broker_id=2 |
|        2 | 0.00003400 | set profiling=0                               |
|        3 | 0.00007400 | set profiling=1                               |
|        4 | 0.63789700 | alter table t engine=myisam                   |
|        5 | 0.00004000 | set profiling=0                               |
+----------+------------+-----------------------------------------------+
6 rows in set (0.00 sec)


mysql> show profile for query 4;
+----------------------+------------+
| Status               | Duration   |
+----------------------+------------+
| (initialization)     | 0.00002900 |
| checking permissions | 0.00000800 |
| init                 | 0.00004000 |
| Opening table        | 0.00009400 |
| System lock          | 0.00000500 |
| Table lock           | 0.00000700 |
| setup                | 0.00004200 |
| creating table       | 0.00195800 |
| After create         | 0.00010900 |
| copy to tmp table    | 0.52264500 |
| rename result table  | 0.11289400 |
| end                  | 0.00004600 |
| query end            | 0.00000700 |
| freeing items        | 0.00001300 |
+----------------------+------------+
14 rows in set (0.00 sec)
So as you can see in the above profile, the ALTER TABLE statement spends the bulk of its time in the temporary table copy step. Armed with this type of information, you have more insight into the hoops your query is jumping through from start to finish, and therefore, you can then work to tune your queries to help eliminate any identified bottlenecks.
There's more information than just duration that you can get from your profiles - for example, CPU usage (which, unfortunately, is not available on all platforms; the below comes from Linux):
mysql> show profile cpu for query 4;
+----------------------+------------+------------+------------+
| Status               | Duration   | CPU_user   | CPU_system |
+----------------------+------------+------------+------------+
| (initialization)     | 0.00002900 | 0.00000000 | 0.00000000 |
| checking permissions | 0.00000800 | 0.00000000 | 0.00000000 |
| init                 | 0.00004000 | 0.00000000 | 0.00000000 |
| Opening table        | 0.00009400 | 0.00100000 | 0.00000000 |
| System lock          | 0.00000500 | 0.00000000 | 0.00000000 |
| Table lock           | 0.00000700 | 0.00000000 | 0.00000000 |
| setup                | 0.00004200 | 0.00000000 | 0.00000000 |
| creating table       | 0.00195800 | 0.00000000 | 0.00100000 |
| After create         | 0.00010900 | 0.00000000 | 0.00000000 |
| copy to tmp table    | 0.52264500 | 0.55591600 | 0.04199300 |
| rename result table  | 0.11289400 | 0.00199900 | 0.00000000 |
| end                  | 0.00004600 | 0.00000000 | 0.00000000 |
| query end            | 0.00000700 | 0.00000000 | 0.00000000 |
| freeing items        | 0.00001300 | 0.00000000 | 0.00000000 |
+----------------------+------------+------------+------------+





No comments: