Maatkit を試す 〜 mysql-5.1.XX, debian lenny 64bit

Maatkit とは？

• Perl Base の MySQL 管理のマルチツール
  • マルチツールと書いたのは、本当に多彩な機能があり、 MySQL のための"何"と言及するのに説明が窮したためそうしました。
  • 今回は私が特に DB の profiling をするのに有用な mk-query-digest 機能を使いたかったため、その機能を使ってみるところまで記載しています。
• より詳しく知りたい方は下記の URL を参照してみてください。
  • http://www.maatkit.org/
  • http://code.google.com/p/maatkit/wiki/TableOfContents?tm=6

mk-query-digest の何がすごいのか？

• 解析可能な log の種類の豊富さ
  これにつきます！

解析可能な log のリスト

Argument to	Meaning
slowlog (default)	MySQL's slow query log
binlog	Output of MySQL's mysqlbinlog program
genlog	MySQL's \general log" (log of all queries)
http	HTTP TCP/IP traffic from tcpdump
pglog	PostgreSQL logs (stdout or syslog)
tcpdump	MySQL TCP/IP traffic from tcpdump
memcached	memcached TCP/IP traffic from tcpdump

実際に mk-query-digest をつかってみた！

DBI,DBD の install

root# apt-get install libdbi-perl
root# apt-get install libdbd-mysql-perl

Maatkit の install

root# cd /usr/local/src
root# unzip maatkit-6070.zip
root# cd maatkit-6070
root# perl Makefile.PL
root# make
root# make test
root# make install

mk-query-digest で slow query を解析してみる！

• mk-query-digest に引数として、解析したい slow query の PATH を指定してあげるだけ。
• それだけで、各実行 SQL の解析と、 slow query 対象の mysqld 内で実行されていた SQL 毎の頻度を ranking 、 summarize した結果をだしてくれるのだ。

• 以下、実行例：

mysql% /usr/local/bin/mk-query-digest ~XXXXXXXXXX/slow-queries.log
# 350ms user time, 0 system time, 17.92M rss, 57.27M vsz
# Overall: 300 total, 10 unique, 0.01 QPS, 0.14x concurrency _____________
#                    total     min     max     avg     95%  stddev  median
# Exec time          3856s     11s     26s     13s     17s      2s     12s
# Lock time              0       0       0       0       0       0       0
# Rows sent          3.90k       0   1.04k   13.33   38.53   62.72    3.89
# Rows exam          4.93k       0   2.08k   16.82   38.53  121.81    3.89
# Time range        2010-04-19 12:36:44 to 2010-04-19 20:22:00
# bytes            149.93k      84   1.88k  511.75   1.09k  332.88  346.17

# Query 1: 0.01 QPS, 0.11x concurrency, ID 0xB0A3A3D8C92B843D at byte 117060
# This item is included in the report because it matches --limit.
#              pct   total     min     max     avg     95%  stddev  median
# Count         67     203
# Exec time     65   2544s     11s     19s     13s     15s      2s     12s
# Lock time      0       0       0       0       0       0       0       0
# Rows sent     69   2.72k       1     110   13.74   42.48   17.57    7.70
# Rows exam     55   2.72k       1     110   13.74   42.48   17.57    7.70
# Users                  1 XXXXXXXXXX....
# Hosts                 13 XXXXXXXXXX.... (24), XXXXXXXXXX.... (23)... 11 more
# Databases              2 XXXXXXXXXX (197), XXXXXXXXXX (6)
# Time range 2010-04-19 12:41:56 to 2010-04-19 18:51:41
# bytes         82 123.16k     306   1.88k  621.26   1.26k  355.59  511.45
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s
#  10s+  ################################################################
# Tables
#    SHOW TABLE STATUS FROM `XXXXXXXXXX` LIKE 'XXXXXXXXXX'\G
#    SHOW CREATE TABLE `XXXXXXXXXX`.`XXXXXXXXXX`\G
# EXPLAIN
select ... snip ...

# Query 2: 0.00 QPS, 0.03x concurrency, ID 0x23911BB7648A2D04 at byte 104147

... snip ...

# Query 3: 0.00 QPS, 0.01x concurrency, ID 0x46D779A837D64E37 at byte 38576

... snip ...

# Query 4: 0.00 QPS, 0.01x concurrency, ID 0x066EB115F07BE3A8 at byte 21668

... snip ...

# Profile
# Rank Query ID           Response time    Calls R/Call   Item
# ==== ================== ================ ===== ======== ================
#    1 0xB0A3A3D8C92B843D  2544.0000 69.1%   203  12.5320 SELECT XXXXXXX_?
#    2 0x23911BB7648A2D04   715.0000 19.4%    49  14.5918 REPLACE TABLE
#    3 0x46D779A837D64E37   275.0000  7.5%    22  12.5000 SELECT XXXXXXX_?
#    4 0x066EB115F07BE3A8   145.0000  3.9%    12  12.0833 SELECT XXX_XXX_?