the slow query log (and lock time, and InnoDB)

MySQL is not so heavily-instrumented as Oracle. (Back to tuning using ratios rather than the wait interface… sigh…) But it does offer (among other tools) the slow query log. Turn it on (put ‘log_slow_queries‘ in your config file), and all queries that take longer than long_query_time seconds (also set in your config file) will be logged to a slow query log file, along with the time they took to execute. Then you can use mysqldumpslow to analyze the output. You can see, for example, which slow queries are taking the most cumulative time on your server, or are being executed most frequently. (The manual doesn’t say much about it, and mysqldumpslow ––help doesn’t give too much help, but I think mysqldumpslow -s t and mysqldumpslow -s c do that.)

If you use InnoDB, though (as we do), be aware that the “lock time” logged in the slow query log only counts time for table-level locks that are taken at the MySQL top level, not InnoDB locks taken at the storage-engine level. (The logging is done at the “top” level.) So the “lock time” in the log is pretty useless for you. (You can use innodb_lock_monitor for that, but that’s another story…)

5 Responses to “the slow query log (and lock time, and InnoDB)”

  1. Peter Zaitsev Says:

    You’re very right.
    Though normal selects do not wait on any Innodb locks anyway.

    But anyway we’re working on the patch now which would log time spent on Innodb locks in slow query log as well as time spend waiting in innodb thread queue and few other pieces of info.

  2. ben Says:

    Peter – thanks for the good news!

  3. Mike Says:

    This was great. I am coming from an Oracle Env. One thing I am trying to find is dealing with the error log. Is there a list of errors I can find like withing Oracle I get the ORA messages. Looking to scrap my error log.

    Thanks

  4. Aurimas Mikalauskas Says:

    As Peter promised, there’s a patch showing more information about InnoDB behavior in slow query log if enabled. This was available in 5.0 Percona builds for couple years I think if innodb stats are enabled (see http://www.percona.com/docs/wiki/patches:microslow_innodb) – you can see InnoDB_rec_lock_wait in slow query logs. And very recently the patch was also ported to Xtradb10 which is based on 5.1.45 and available here.

  5. Vector Thorn Says:

    Ha, i’m still googling to try to find out exactly what the number means for lock time in the log. It doesn’t say if that’s cpu cycles, millionths of a second, or what; but thanks for pointing out that it is only referring to top level locks and not row locks.

Leave a comment