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)
Did you file a bug?
When you file a bug, please make sure that you list the times with and without profiling for both MySQL 5.1 and 5.5.
It is not clear how much overhead there is in 5.5 profiling compared to 5.1
G
There is a bug for the Source_file issue on 5.5 and the Source_function issue on 5.1
http://bugs.mysql.com/bug.php?id=59273
Hi Ronald,
You cited “As you can see, the query takes some 50+ms longer with profiling enabled”
We have checked the case with 5.1.53 and 5.5.8 server with the same configuration.(Both the servers running on the same hardware configuration, Same queries on exactly same tables (both structure + data) and there was no other activity on the server while profiling the queries)
The following were the results:
Same queries on exactly same tables (both structure + data):
Total time taken on 5.5.8: 1.23727 seconds. (This is the only case where in 5.5.8 takes little more than the 5.1 server)
Total time taken on 5.1.3: 1.12447 seconds.
Query with a couple of joins:
Total time taken on 5.5.8: 0.01188 seconds.
Total time taken on 5.1.3: 0.01171 seconds.
One with a subquery in the FROM-clause
Total time taken on 5.5.8: 0.00507 seconds.
Total time taken on 5.1.3: 0.00505 seconds.
“There appears to be some new overhead that causes profiling to log excessive amount of information.”
According to the results obtained above we did not find the extra over head as mentioned in the above.
Ashwin A
Webyog