Xaprb

Stay curious!

How LOCK TABLES interacts with the MySQL slow query log

with 3 comments

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.

Written by Xaprb

September 19th, 2010 at 6:08 pm

3 Responses to 'How LOCK TABLES interacts with the MySQL slow query log'

Subscribe to comments with RSS

  1. 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

  2. Interesting. It gets logged on Linux 32-bit 5.1.41-community.

    Xaprb

    20 Sep 10 at 6:56 am

  3. Nice information. Thanks for the post.

    Praveen

    23 Sep 10 at 9:04 am

Leave a Reply