{"id":160,"date":"2010-04-12T10:43:33","date_gmt":"2010-04-12T15:43:33","guid":{"rendered":"http:\/\/www.shainmiley.com\/wordpress\/?p=160"},"modified":"2010-11-15T13:03:09","modified_gmt":"2010-11-15T18:03:09","slug":"mysql-slow-log-parsing-with-maatkit","status":"publish","type":"post","link":"https:\/\/www.shainmiley.com\/wordpress\/2010\/04\/12\/mysql-slow-log-parsing-with-maatkit\/","title":{"rendered":"Mysql slow log parsing with Maatkit"},"content":{"rendered":"

One of the tools that is included with Maatkit<\/a> is called ‘mk-query-digest’.\u00c2\u00a0 If you have Mysql slow logging\u00c2\u00a0enabled, 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.<\/p>\n

In order to get the ball rolling all you need to do is execute the following command:<\/p>\n

‘perl \/path\/to\/mk-query-digest \/path\/to\/slow.log’<\/p>\n

Once you do you will be presented with a report similar to the following:<\/p>\n

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

<\/p>\n

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

…………..<\/p>\n

# Profile
\n# Rank Query ID\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0 \u00c2\u00a0 \u00c2\u00a0 \u00c2\u00a0 \u00c2\u00a0 \u00c2\u00a0Response time\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0Calls\u00c2\u00a0 R\/Call\u00c2\u00a0 \u00c2\u00a0 \u00c2\u00a0 \u00c2\u00a0\u00c2\u00a0 Item
\n# ==== =========== =========\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0 === ====\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0==========
\n#\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0 1 0x46C7739F1C54146B\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0604.8944 85.1%\u00c2\u00a0\u00c2\u00a0144\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0 4.2007 \u00c2\u00a0\u00c2\u00a0 SELECT dc_ng_long_now
\n#\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0 2 0x36DEFABC1BFA37A0\u00c2\u00a0 40.2883\u00c2\u00a0 5.7%\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a016\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a02.5180 \u00c2\u00a0\u00c2\u00a0 UPDATE inventory_instance_attributes
\n#\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0 3 0x8B68CA21D4CB9519\u00c2\u00a0\u00c2\u00a037.5560\u00c2\u00a0 5.3%\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a011\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a03.4142\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0SELECT dc_ng_double_now
\n#\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0 4 0x813031B8BBC3B329\u00c2\u00a0\u00c2\u00a0\u00c2\u00a027.8052\u00c2\u00a0 3.9%\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a017\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a01.6356\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0\u00c2\u00a0COMMIT<\/p>\n

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.<\/p>\n

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

‘perl mk-query-digest –user adminuser –password adminpasswd –processlist localhost –interval 0.01’<\/p>\n

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.<\/p>\n","protected":false},"excerpt":{"rendered":"

One of the tools that is included with Maatkit is called ‘mk-query-digest’.\u00c2\u00a0 If you have Mysql slow logging\u00c2\u00a0enabled, 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 […]<\/p>\n","protected":false},"author":2,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":[],"categories":[3,17,6],"tags":[],"_links":{"self":[{"href":"https:\/\/www.shainmiley.com\/wordpress\/wp-json\/wp\/v2\/posts\/160"}],"collection":[{"href":"https:\/\/www.shainmiley.com\/wordpress\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.shainmiley.com\/wordpress\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.shainmiley.com\/wordpress\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"https:\/\/www.shainmiley.com\/wordpress\/wp-json\/wp\/v2\/comments?post=160"}],"version-history":[{"count":20,"href":"https:\/\/www.shainmiley.com\/wordpress\/wp-json\/wp\/v2\/posts\/160\/revisions"}],"predecessor-version":[{"id":364,"href":"https:\/\/www.shainmiley.com\/wordpress\/wp-json\/wp\/v2\/posts\/160\/revisions\/364"}],"wp:attachment":[{"href":"https:\/\/www.shainmiley.com\/wordpress\/wp-json\/wp\/v2\/media?parent=160"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.shainmiley.com\/wordpress\/wp-json\/wp\/v2\/categories?post=160"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.shainmiley.com\/wordpress\/wp-json\/wp\/v2\/tags?post=160"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}