Changes in using Profiling in MySQL 5.5

In the past I’ve used the profiling features (e.g. SHOW PROFILES) in MySQL to help with timing SQL statements, especially those in the < 10 millisecond range.

Out of habit I did use this to time all SQL statements however in MySQL 5.5.8 GA I’ve found this no longer to be representative.

As you can see, the query takes some 50+ms longer with profiling enabled, not to mention they have broken the Source_file column which I’ve actually used to troll the source code with.

mysql> set profiling=1;

4 rows in set (1.14 sec)
4 rows in set (1.15 sec)
4 rows in set (1.17 sec)

mysql> set profiling=0;

4 rows in set (0.37 sec)
4 rows in set (0.37 sec)
4 rows in set (0.37 sec)

Investigating further showed the cause. There appears to be some new overhead that causes profiling to log excessive amount of information.

mysql> show profile source for query 35;
+--------------------------------+----------+-----------------------+----------------------+-------------+
| Status                         | Duration | Source_function       | Source_file          | Source_line |
+--------------------------------+----------+-----------------------+----------------------+-------------+
| starting                       | 0.000047 | NULL                  | NULL                 |        NULL |
| Waiting for query cache lock   | 0.000008 | try_lock              | /export/home/pb2/bui |         454 |
| checking query cache for query | 0.000112 | send_result_to_client | /export/home/pb2/bui |        1537 |
| checking permissions           | 0.000008 | check_access          | /export/home/pb2/bui |        4613 |
| checking permissions           | 0.000006 | check_access          | /export/home/pb2/bui |        4613 |
| checking permissions           | 0.000006 | check_access          | /export/home/pb2/bui |        4613 |
| checking permissions           | 0.000009 | check_access          | /export/home/pb2/bui |        4613 |
| Opening tables                 | 0.000035 | open_tables           | /export/home/pb2/bui |        4732 |
| System lock                    | 0.000015 | mysql_lock_tables     | /export/home/pb2/bui |         299 |
| Waiting for query cache lock   | 0.000056 | try_lock              | /export/home/pb2/bui |         454 |
| init                           | 0.000068 | mysql_select          | /export/home/pb2/bui |        2545 |
| optimizing                     | 0.000019 | optimize              | /export/home/pb2/bui |         858 |
| statistics                     | 0.000036 | optimize              | /export/home/pb2/bui |        1049 |
| preparing                      | 0.000025 | optimize              | /export/home/pb2/bui |        1071 |
| Creating tmp table             | 0.000050 | optimize              | /export/home/pb2/bui |        1587 |
| Sorting for group              | 0.000010 | optimize              | /export/home/pb2/bui |        1632 |
| executing                      | 0.000006 | exec                  | /export/home/pb2/bui |        1818 |
| Copying to tmp table           | 0.000049 | exec                  | /export/home/pb2/bui |        1965 |
| optimizing                     | 0.000011 | optimize              | /export/home/pb2/bui |         858 |
| statistics                     | 0.000053 | optimize              | /export/home/pb2/bui |        1049 |
| preparing                      | 0.000014 | optimize              | /export/home/pb2/bui |        1071 |
| executing                      | 0.000006 | exec                  | /export/home/pb2/bui |        1818 |
| Sending data                   | 0.000025 | exec                  | /export/home/pb2/bui |        2356 |
....

| Sending data                   | 0.000009 | exec                  | /export/home/pb2/bui |        2356 |
| executing                      | 0.000006 | exec                  | /export/home/pb2/bui |        1818 |
| Sending data                   | 0.000051 | exec                  | /export/home/pb2/bui |        2356 |
| Sorting result                 | 0.000034 | exec                  | /export/home/pb2/bui |        2244 |
| Sending data                   | 0.000052 | exec                  | /export/home/pb2/bui |        2356 |
| end                            | 0.000008 | mysql_select          | /export/home/pb2/bui |        2581 |
| removing tmp table             | 0.000014 | free_tmp_table        | /export/home/pb2/bui |       11121 |
| end                            | 0.000009 | free_tmp_table        | /export/home/pb2/bui |       11146 |
| query end                      | 0.000010 | mysql_execute_command | /export/home/pb2/bui |        4310 |
| closing tables                 | 0.000023 | mysql_execute_command | /export/home/pb2/bui |        4362 |
| freeing items                  | 0.000026 | mysql_parse           | /export/home/pb2/bui |        5509 |
| Waiting for query cache lock   | 0.000009 | try_lock              | /export/home/pb2/bui |         454 |
| freeing items                  | 0.000051 | NULL                  | NULL                 |        NULL |
| Waiting for query cache lock   | 0.000006 | try_lock              | /export/home/pb2/bui |         454 |
| freeing items                  | 0.000006 | NULL                  | NULL                 |        NULL |
| storing result in query cache  | 0.000017 | end_of_result         | /export/home/pb2/bui |        1020 |
| logging slow query             | 0.000006 | log_slow_statement    | /export/home/pb2/bui |        1444 |
| cleaning up                    | 0.000009 | dispatch_command      | /export/home/pb2/bui |        1400 |
+--------------------------------+----------+-----------------------+----------------------+-------------+
124504 rows in set (0.48 sec)
Tagged with: Databases MySQL

Related Posts

Databases MySQL

MySQL 5.5.8 GA and PHP 5.3.4 don’t get along with libmysql

Today I discovered that you are unable to compile the current stable PHP version 5.3.4 with yesterday’s MySQL 5.5.8 GA release. I was able to download the current MySQL 5.1.54 and compile without issue.

Read more
Databases MySQL

Five reasons to upgrade to MySQL 5.5

Updated Nov 2011. Check out my Reasons to use MySQL 5.5 Presentation for more in-depth information about installing/configuring and using MySQL 5.5 I have been looking forward to the general availability (GA) release of MySQL 5.

Read more
Databases MySQL

Wish list for MySQL thread polling events

It is great to draw inspiration from other Open Source communities. Brad Fitzpatrick recently wrote about Android Strict Mode . His twitter tag line for this post was “I see you were doing 120 ms in a 16 ms zone” which is all I needed to hear from somebody who also worries unreasonably about responsiveness (Web site quote).

Read more