One of my favorite tools in the Percona Toolkit is pt-query-digest. This tool is indispensable for identifying your top SQL queries, and analyzing which queries are accounting for your database load.
But the report you get from pt-query-digest is only as good as the log of queries you give it as input. You need a large enough sample of query logs, collected over a period of time when you have representative traffic on your database.
You also need the log to include all the queries, not just those that take more than N seconds. The reason is that some queries are individually quick, and would not be logged if you set the long_query_time configuration variable to 1 or more seconds. You want that threshold to be 0 seconds while you’re collecting logs.
However, activating such high-volume query log collection can be costly. Every statement executed on your database will cause file I/O, even when the query itself was served out of your buffer pool memory. That’s a lot of overhead, so we need to be careful about how and when we collect logs, and for how long we leave that running.
I’ve put together a simple shell script to help automate this. I have given it the functional but unimaginative name full-slow-log.
The script configures full logging, then sleeps for a number of seconds to allow queries to be collected in the logs. After it finishes sleeping, or if you interrupt the script, the script restores log configuration back to the values they started with.
$ full-slow-log [ -v ] [ -s seconds ] [ -c config ]
- -v is for verbose output.
- -s seconds allows you to specify the number of seconds to sleep. The default is 5 seconds, which is probably too short for most sites, but the value is chosen to be as low impact as possible if you forget to give another value.
- -c config allows you to specify a MySQL config file other than $HOME/.my.cnf, so you can store host, user, and password.
Here’s an example of running it with verbose output:
$ full-slow-log -v Discovering slow_query_log=1 Discovering slow_query_log_file=mysql-slow.log Discovering long_query_time=60.000000 Setting long_query_time=0 Setting slow_query_log_file=mysql-slow.log-full-20121122112413 Setting slow_query_log=1 Flushing slow query log Sleeping 5 seconds... done. Restoring slow_query_log_file=mysql-slow.log Restoring long_query_time=60.000000 Restoring slow_query_log=1 Flushing logs during restore
Notice that the script also redirects the slow query log to a new file, with a filename based on the timestamp. This is so you have a distinct file that contains only the specific time range of logs you collected.
The restoration of settings is in a “trap” which is a shell scripting feature that serves as both an exit handler and signal handler. So if you interrupt the script before it’s done, you have some assurance that it will do the right thing to restore settings anyway.
My full-slow-log script is now available on a Github project (along with a few other experimental scripts I have written). See https://github.com/billkarwin/bk-tools
I hope you find this script a useful complement to my upcoming talks at the Percona Live MySQL Conference in London, UK on December 3-4 2012:
Tweet the link to this blog for a chance to win a free full conference pass. Make sure to use hashtag #perconalive! Winner will be chosen at the end of the day.