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)