How LOCK TABLES interacts with the MySQL slow query log
Here’s a little trivia that you might find helpful. Suppose that I have the following in the MySQL slow query log (abbreviated for clarity):
# User@Host: root[root] @ localhost [127.0.0.1]
# Time: 100919 17:58:52
# Query_time: 9.648427 Lock_time: 8.648039
select sleep(1) from t limit 1;
To get this into the slow query log, I set the long_query_time to 0 and opened two sessions. In one session I ran LOCK TABLES t WRITE, and in the other I tried to select from that table. As you can see above, 1) LOCK TABLES contributes to the Lock_time number, and 2) the Query_time is the sum of execution time and lock time.
Now, I’ll set long_query_time = 2 and run the same test. What happens? Nothing shows up in the slow query log, because 3) the time spent waiting for table locks doesn’t count towards the slow query time threshold.
A final note: it was rumored that the LOCK TABLES query itself is somehow a special-case that is never logged to the slow query log. However, this is not true; if long_query_time is set to zero, the LOCK TABLES query will appear in the log.



windows:
mysql 5.1.41-community
mysql> show variables like ‘%long_query_time%’;
+—————–+———-+
| Variable_name | Value |
+—————–+———-+
| long_query_time | 0.000000 |
+—————–+———-+
and LOCK TABLES query itself is not logged to the slow query log.
huarong
20 Sep 10 at 3:30 am
Interesting. It gets logged on Linux 32-bit 5.1.41-community.
Xaprb
20 Sep 10 at 6:56 am
Nice information. Thanks for the post.
Praveen
23 Sep 10 at 9:04 am