Test driving 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. BuildingTo build from source, follow the instructions at Installing from the Development Source Tree using the Community tree. And since this is a community feature, the documentation can be provided by the community as well. I posted a documentation stub in . Feel free to add to it. Test drivingOnce 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. select @@profiling; +-------------+ | @@profiling | +-------------+ | 0 | +-------------+ set profiling = 1; select @@profiling; +-------------+ | @@profiling | +-------------+ | 1 | +-------------+ Cool. Now what? 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! 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) |