MySQL Slow Log Analyse mit mysqldumpslow und mk-query-digest

2010-11-21 - kostaki Keine Kommentare »

Vor ein paar Tagen habe ich mal wieder einen MySQL Server analysiert der meiner Ansicht nach übermäßig beansprucht wurde. Dabei ging mein erster Blick ins MySQL Slow Query Log in dem auch ein paar Queries standen. Nach einem Blick ins MySQL Manual fand ich dann das sehr einfache aber auch sehr hilfreiches Tool mysqldumpslow, das man zum MySQL slow.log analysieren benutzen kann. Es fast ähnliche Queries zusammen und macht es damit einfacher die Übersicht zu behalten.

$ mysqldumpslow /var/log/mysql/mysql-slow.log

Reading mysql slow query log from /var/log/mysql/mysql-slow.log

Count: 811  Time=3.73s (3021s)  Lock=0.00s (0s)  Rows=1.0 (816)
  SELECT
  id
  FROM bla
  WHERE
  title = 'S'

...

Will man es etwas genauer haben, kann ich das mk-query-digest Tool von Maatkit.org empfehlen. Es ist nicht im Debian Lenny Paket maatkit enthalten, aber auch so einfach installierbar:

$ wget http://www.maatkit.org/get/mk-query-digest
$ chmod 700 mk-query-digest

Die Benutzung ist genauso einfach wie bei mysqldumslow.

$ ./mk-query-digest /var/log/mysql/mysql-slow.log

# 550ms user time, 10ms system time, 17.46M rss, 56.69M vsz
# Current date: 
# Hostname: 
# Files: /var/log/mysql/mysql-slow.log
# Overall: 1.42k total, 4 unique, 0.08 QPS, 0.31x concurrency ____________
# Time range: 2010-11-18 07:43:06 to 12:35:29
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time          5402s      3s      8s      4s      6s      1s      3s
# Lock time              0       0       0       0       0       0       0
# Rows sent          1.38k       0       3    1.00    0.99    0.15    0.99
# Rows examine     381.57M  98.20k 776.37k 275.55k 270.35k  15.64k 270.35k
# Query size       138.76k      79     279  100.21  112.70    9.74   97.36

# Profile
# Rank Query ID           Response time    Calls R/Call   Apdx V/M   Item
# ==== ================== ================ ===== ======== ==== ===== =====
#    1 0xAC32ED49FDD4A629  5340.0000 98.9%  1403   3.8061 0.40  0.29 SELECT 
# MISC 0xMISC                62.0000  1.1%    15   4.1333   NS   0.0 <3 ITEMS>

# Query 1: 0.08 QPS, 0.30x concurrency, ID 0xAC32ED49FDD4A629 at byte 169115
# This item is included in the report because it matches --limit.
# Scores: Apdex = 0.40 [1.0], V/M = 0.29
# Time range: 2010-11-18 07:43:06
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         98    1403
# Exec time     98   5340s      3s      8s      4s      6s      1s      3s
# Lock time      0       0       0       0       0       0       0       0
# Rows sent     98   1.37k       0       3    1.00    0.99    0.15    0.99
# Rows examine  98 377.03M  98.20k 276.81k 275.18k 270.35k   8.95k 270.35k
# Query size    98 137.27k      79     143  100.19  112.70    8.48   97.36
# String:
# Databases    ... (1366/97%), ... (37/2%)
# Hosts
# Users       ... (1366/97%), ... (37/2%)
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+
# Tables
#    SHOW TABLE STATUS FROM LIKE 
#    SHOW CREATE TABLE 
# EXPLAIN /*!50100 PARTITIONS*/
SELECT

mk-query-digest kann noch viel mehr wie z.B. tcpdumps analysieren, aber dazu später mehr.

Debian Root