Mysql slow log parsing with Maatkit

One of the tools that is included with Maatkit is called ‘mk-query-digest’.  If you have Mysql slow logging enabled, this perl script can me used to examine these entries, and provide a very useful and user friendly report that will help you understand the queries that are exceeding your current slow log threshold. You can then take the results and determine whether or not you have opportunity to do some schema and/or query optimization.

In order to get the ball rolling all you need to do is execute the following command:

‘perl /path/to/mk-query-digest /path/to/slow.log’

Once you do you will be presented with a report similar to the following:

# 200ms user time, 10ms system time, 9.59M rss, 11.17M vsz
# Overall: 199 total, 8 unique, 0.92 QPS, 3.44x concurrency ______________
#                    total     min     max     avg     95%  stddev  median
# Exec time           745s      1s     15s      4s      9s      3s      3s
# Lock time            4ms       0   159us    21us    66us    18us    16us
# Rows sent         16.35M       0 381.59k  84.16k 298.06k  81.83k  76.03k
# Rows exam         16.35M       0 381.59k  84.16k 298.06k  81.83k  76.03k
# Time range        2010-03-04 18:32:44 to 2010-03-04 18:36:21
# bytes             55.53k       6   7.67k  285.75  313.99  519.23  271.23

# Query 1: 1.18 QPS, 4.96x concurrency, ID 0×46C7739F1C54146B at byte 88363
# This item is included in the report because it matches –limit.
#              pct   total     min     max     avg     95%  stddev  median
# Count         72     144
# Exec time     81    605s      1s     15s      4s     10s      3s      3s
# Lock time     59     3ms    10us    31us    17us    21us     3us    16us
# Rows sent     93  15.31M  36.79k 381.59k 108.88k 298.06k  80.73k  76.03k
# Rows exam     93  15.31M  36.79k 381.59k 108.88k 298.06k  80.73k  76.03k
# Users                  1 service_manager
# Hosts                  1 localhost
# Databases              1     mem
# Time range 2010-03-04 18:34:19 to 2010-03-04 18:36:21
# bytes         72  40.09k     267     332  285.08  313.99   17.02  271.23
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+  ####
# Tables
#    SHOW TABLE STATUS FROM `mem` LIKE ‘dc_ng_long_now’\G
#    SHOW CREATE TABLE `mem`.`dc_ng_long_now`\G
# EXPLAIN
SELECT end_time, end_time /*begin_time*/, value, 1 /* value_count */, instance_attribute_id
FROM dc_ng_long_now
WHERE
instance_attribute_id IN ( 172933,172907,172908,172925,172924,172988,172989,172887,172886,172868 )
AND end_time <= 1267727680328
AND end_time >= 1265308420328
ORDER BY instance_attribute_id, end_time ASC\G

…………..

# Profile
# Rank Query ID                   Response time     Calls  R/Call         Item
# ==== =========== =========     === ====    ==========
#    1 0×46C7739F1C54146B   604.8944 85.1%  144    4.2007    SELECT dc_ng_long_now
#    2 0×36DEFABC1BFA37A0  40.2883  5.7%     16    2.5180    UPDATE inventory_instance_attributes
#    3 0×8B68CA21D4CB9519  37.5560  5.3%     11    3.4142    SELECT dc_ng_double_now
#    4 0×813031B8BBC3B329   27.8052  3.9%      17    1.6356    COMMIT

You will see some overall statistics at the very top, followed by a list of individual queries with specific details, and finally a summery of the results.

You can also use this tool to look at server statistics in real-time, without the use of the slow log, for example:

‘perl mk-query-digest –user adminuser –password adminpasswd –processlist localhost –interval 0.01′

This command will login to the mysql server running on localhost, using the administrator username and password and look at the processlist every 0.01 seconds and produce the same type of report (after you exit the script) using real-time data instead of the entries from the mysql slow log.