SHOW PROFILES is finally available! It has been a long struggle, but finally this important community patch by
Jeremy Cole has been integrated into a publicly distributed MySQL source tree (thanks to Chad Miller excellent integration work).
What's SHOW PROFILES? Is a feature to let you peek inside MySQL internals, which tell you what your queries were doing during their execution.
This feature is also remarkable because it makes a significant difference between Community and Enterprise releases.
The binaries will be available soon, but in the meantime, you can build the source code and give it a try.
Building
To build from source, follow the instructions at
Installing from the Development Source Tree using the Community tree.
bkf clone bk://mysql.bkbits.net/mysql-5.0-community mysql-5.0
And since this is a community feature, the documentation can be provided by the community as well. I posted a
documentation stub in
MySQL Forge. Feel free to add to it.
Test driving
Once you have built your community distribution (or after downloading the binaries, if you are reading this when they are already available), it's time to see what SHOW PROFILE can do.
To use this addition, you need to enable it. The session variable
profiling is used to enable and disable it. By default, it is disabled, so the first order of business is: turn it on!
select @@profiling;
+-------------+
| @@profiling |
+-------------+
| 0 |
+-------------+
set profiling = 1;
select @@profiling;
+-------------+
| @@profiling |
+-------------+
| 1 |
+-------------+
Cool. Now what?
Now we play around with the system, and see how profiles works.
drop table if exists t1;
create table t1 (id int not null);
insert into t1 values (1), (2), (3);
select * from t1;
#
# AND FINALLY!
#
show profiles;
+----------+----------+-------------------------------------+
| Query_ID | Duration | Query |
+----------+----------+-------------------------------------+
| 0 | 0.000045 | set profiling = 1 |
| 1 | 0.000071 | select @@profiling |
| 2 | 0.000087 | drop table if exists t1 |
| 3 | 0.031741 | create table t1 (id int not null) |
| 4 | 0.000615 | insert into t1 values (1), (2), (3) |
| 5 | 0.000198 | select * from t1 |
+----------+----------+-------------------------------------+
Here is the first glimpse. Basically, it tells you the duration of each query. Not very exciting so far, but let's keep going. The Query_ID field is a reference for us, so that we can ask more about a specific query. In this list, the table creation is query no. 3, so let's ask some specifics about this one:
SHOW PROFILE FOR QUERY 3;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| checking permissions | 0.000040 |
| creating table | 0.000035 |
| After create | 0.031432 |
| query end | 0.000221 |
| freeing items | 0.000005 |
| logging slow query | 0.000006 |
| cleaning up | 0.000002 |
+----------------------+----------+
That's wonderful! Now we know more about the single tasks this query was performing. But it gets even better. Look at this:
SHOW PROFILE CPU FOR QUERY 3;
+----------------------+----------+----------+------------+
| Status | Duration | CPU_user | CPU_system |
+----------------------+----------+----------+------------+
| checking permissions | 0.000040 | 0.000000 | 0.000000 |
| creating table | 0.000035 | 0.000000 | 0.000000 |
| After create | 0.031432 | 0.001000 | 0.000000 |
| query end | 0.000221 | 0.000000 | 0.000000 |
| freeing items | 0.000005 | 0.000000 | 0.000000 |
| logging slow query | 0.000006 | 0.000000 | 0.000000 |
| cleaning up | 0.000002 | 0.000000 | 0.000000 |
+----------------------+----------+----------+------------+
If you are debugging code, you may like the information provided by the following option:
SHOW PROFILE source FOR QUERY 3;
+----------------------+----------+-----------------------+--------------+-------------+
| Status | Duration | Source_function | Source_file | Source_line |
+----------------------+----------+-----------------------+--------------+-------------+
| checking permissions | 0.000040 | check_access | sql_parse.cc | 5256 |
| creating table | 0.000035 | mysql_create_table | sql_table.cc | 1737 |
| After create | 0.031432 | mysql_create_table | sql_table.cc | 1768 |
| query end | 0.000221 | mysql_execute_command | sql_parse.cc | 5085 |
| freeing items | 0.000005 | mysql_parse | sql_parse.cc | 5973 |
| logging slow query | 0.000006 | log_slow_statement | sql_parse.cc | 2178 |
| cleaning up | 0.000002 | dispatch_command | sql_parse.cc | 2143 |
+----------------------+----------+-----------------------+--------------+-------------+
It tells you how much time was spent, and which lines of code you should look at if you want to improve it!
More options available in the
documentation stub.
Rather than trying all of them here, I will just give you a simple example of what can be hidden behind a query. Check this out:
connect;
set profiling=1;
use information_schema;
select count(*) from columns where table_schema='mysql';
+----------+
| count(*) |
+----------+
| 147 |
+----------+
show profiles;
+----------+----------+---------------------------------------------------------+
| Query_ID | Duration | Query |
+----------+----------+---------------------------------------------------------+
| 0 | 0.000194 | set profiling=1 |
| 1 | 0.000006 | SELECT DATABASE() |
| 2 | 0.005928 | select count(*) from columns where table_schema='mysql' |
+----------+----------+---------------------------------------------------------+
show profile for query 2;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| Opening tables | 0.000051 |
| System lock | 0.000281 |
| Table lock | 0.000002 |
| init | 0.000006 |
| optimizing | 0.000020 |
| statistics | 0.000009 |
| preparing | 0.000012 |
| executing | 0.000011 |
| checking permissions | 0.000039 |
| Opening tables | 0.000136 |
| checking permissions | 0.000010 |
| Opening tables | 0.000185 |
| checking permissions | 0.000008 |
| Opening tables | 0.000478 |
| checking permissions | 0.000007 |
| Opening tables | 0.000107 |
| checking permissions | 0.000006 |
| Opening tables | 0.000096 |
| checking permissions | 0.000006 |
| Opening tables | 0.000052 |
| checking permissions | 0.000006 |
| Opening tables | 0.000051 |
| checking permissions | 0.000007 |
| Opening tables | 0.000145 |
| checking permissions | 0.000006 |
| Opening tables | 0.000445 |
| checking permissions | 0.000007 |
| Opening tables | 0.000395 |
| checking permissions | 0.000007 |
| Opening tables | 0.000189 |
| checking permissions | 0.000007 |
| Opening tables | 0.000195 |
| checking permissions | 0.000005 |
| Opening tables | 0.000053 |
| checking permissions | 0.000006 |
| Opening tables | 0.000055 |
| checking permissions | 0.000005 |
| Opening tables | 0.000058 |
| checking permissions | 0.000005 |
| Opening tables | 0.000064 |
| checking permissions | 0.000005 |
| Opening tables | 0.000123 |
| checking permissions | 0.000007 |
| Sending data | 0.000898 |
| end | 0.001215 |
| query end | 0.000007 |
| freeing items | 0.000003 |
| closing tables | 0.000010 |
| removing tmp table | 0.000002 |
| closing tables | 0.000420 |
| logging slow query | 0.000003 |
| cleaning up | 0.000002 |
+----------------------+----------+
52 rows in set (0.00 sec)
Now it's your turn to experiment and share your experiences!
