原文地址：http://www.mysqlperformanceblog.com/2006/09/06/slow-query-log-analyzes-tools/
MySQL has simple but quite handy feature – slow query log, which allows you to log all queries which took over define number of seconds to execute. There is also an option to enable logging queries which do not use indexes even if they take less time (–log-queries-not-using-indexes)
Slow query log is great to spot really slow queries which are often good candidates for optimization but it has few serious problems which limits extent to which it is helpful. First – it only allows you to set slow query time in seconds, having 1 second minimum value. For most of interactive applications this is way too large – if you’re developing Web application you probably want whole page to be generated less in 1 second, which issues many queries during generation. Second – if you enable option to log queries which do not use indexes it well can be flooded with fast and efficient queries, which just happen to do full table scans – for example if you would be having drop down list of states in your application and use SELECT * FROM STATES for that it would trigger and log the query.
Taking other Approach
For our clients we often need to find a queries which impact application the most. It does not always have to be slowest queries – query taking 10ms and run 1.000 times per second puts more load on server than 10 seconds query running once per second. We of course want to get rid of really slow queries but to really optimize application throughput queries which generate most of the load need to be investigated
Patching Slow Query Logging – First thing we did is created a Patch which allows you to specify slow query time in microseconds rather than seconds and allows you to log all queries in slow query log by setting long_query_time=0 This patch is adapted version of patch by Georg Richter which was made to run with recent MySQL version. Now why do not we use general log instead ? Unfortunately general logs queries before queries are executed (and even parsed) so it can’t contain query execution information such as execution and lock times and number of rows examined.
After this patch is applied your slow query log starts to look like this:
# User@Host: root[root] @ localhost [] # Query_time: 0.000652 Lock_time: 0.000109 Rows_sent: 1 Rows_examined: 1 SELECT id FROM users WHERE name='baouong'; # User@Host: root[root] @ localhost [] # Query_time: 0.001943 Lock_time: 0.000145 Rows_sent: 0 Rows_examined: 0 INSERT IGNORE INTO articles (id, body,)VALUES(3558268,'sample text');Filtering Slow Query Log – Especially after the changes to log all queries slow query log may be growing too rapidly to follow, so we implemented slow query log filter (based on parse_mysql_slow_log by Nathanial Hendler) which allows you to filter out only queries which took more than certain amount of time or examined more than certain amount of rows. This is great as allows multiple passes across same slow query log first to fix worse queries and then come to find more optimization candidates. So “tail -f mysql-slow.log | mysql_slow_log_filter -T 0.5 -R 1000” will look at queries as they come and will print out queries taking more than 0.5 seconds to execute or having more than 1000 rows examined.
Aggregating slow query log As I already mentioned besides finding slowest queries it is important to find queries which cause largest load on the server, which is with certain level of accuracy queries which take most time to execute combined. There is a tool mysqldumpslow in MySQL distribution which kind of does the thing – unfortunately being run on slow query log it does not give us information we’re looking for because only slow queries will be looked at. The other problem with this tool is – it replaces all real values with “N”, “S” etc placeholders, which means you can’t simply copy-paste query to run EXPLAIN for it. Using this tool normally require you to keep the other window open and find query sample with real constants which matches query with placeholders to work with it.
So we came op with slow query log parser tool which works with adjusted slow query log format and which gives samples of queries after aggregation. Here is how its output looks like:
### 3579 Queries ### Total time: 3.348823, Average time: 0.000935686784017883 ### Taking 0.000269 to 0.130820 seconds to complete ### Rows analyzed 1 - 1 SELECT id FROM forum WHERE id=XXX; SELECT id FROM forum WHERE id=12345;As you can see it also prints minimum and maximum execution times so you will be able to see if only in certain cases query takes long time to execute, for example if plan is different based on constants.
How to use this tool set ?
First be aware this patch to MySQL is not official and should be used with caution. We think it is pretty safe but it surely did not get as much battle testing as rest of MySQL Server. Good thing is – you do not have to run patched version all the time. You can just start it for a few hours to generate you query log and get back to unpatched version.
It is best if you generate this log for all your queries with long_query_time=0 so if serious portion of you load comes from very simple queries you would not lose this kind of info. Yes this will reduce your performance a bit and will require plenty of disk space which is another reason you might not wish to run it in this mode all the time. Happily you can change long_query_time without restarting server so it is easy to get sample of all queries for some period of time and then get back to logging only very slow queries.
Once you have created full log – parse it and check queries using EXPLAIN starting from most impacted onces. After you’ve implemented changes – repeat. Changes may help to one queries but hurt others, for example adding indexes often help SELECT queries but slow down INSERT/UPDATE ones.
Final Note: You do not have to have patched MySQL for these utilities to work. they are designed to handle standard slow query log format as well.
Update 2009-03-04: most of us at Percona now use for slow query log analysis.