目の前に僕らの道がある

勉強会とか、技術的にはまったことのメモ

chiba.pm 2回目に行ってきた #chibapm

行ってきた。

自分の観測範囲だと総武線沿いというか千葉方面で勉強会があまりないので、chiba.pmはすごいありがいたいです。
ゆるふわな感じでPerlについて話ができてとても楽しかったです。

今回は基本全員LTしないといけないということに前日の夜に気がついて1時間で死霊を作るというていたらくでした。次回は余裕を持って、ちゃんとした発表をしたいです。

はなしたこと

pt-query-digestは便利だよって話をしました。
(pt|mk)-query-digestに関しては自分以外の人が詳しく書いているのでそちらの方も参照いただければ、より理解できるかと。

ゆるふわにクエリ解析したい

MySQL前提の話です。

アプリケーションのボトルネックになるのは、だいたいDBなのですが、じゃあ、どうやってボトルネックとなっているクエリを特定するかというとまずは、slowlogを見て遅そうなクエリを特定しようということになるかと思います。

ただ、生のslowlogを目grep、目wcするのは辛いのでそこでmysqldumpslowで集計するわけですが、自分が使いこなせていないこともありつつ、ちょっと使いづらいなと思ってました。

別アプローチで、Devel::KYTProfで閾値を超えたクエリをエラーログに出力するという方法もあります。これは開発環境では充分機能するのですが、本番環境では流量が多すぎてこれも目grepがとてもできない感じになっています。まあ、いろいろあって結局ログが汚れるだけなので、本番でははかないようになりました。

そこで、もっとゆるふわお手軽にクエリ解析できる手段はないかなと見つけたのがpt-query-digestでした。

pt-query-digest?

pt-query-digestはMySQLに関連する便利ツール群であるところのpercona-toolkitの一部です。で、MySQLのコンサルティングやサポートをしているPercona社が開発しています。以前はmaatkitの一部として公開されていたので、mk-query-digestという名前で紹介されているものと同じです。maatkitはpercona-toolkitに吸収されています。

pt-query-digest自体はslowlogを解析してレポートを生成してくれるツールです。こんな感じでslowlogを食わせて実行すると標準出力にレポートを吐いてくれます。簡単ですね。

pt-query-digest /var/lib/mysql/$(hostname)-slow.log

※ファイル名は設定によって違います

pt-query-digestのすごいところはslowlogだけでなく、tcpdumpのログからもレポートを生成してくれる点で、slowlogには吐かれないけど、大量に発行されているクエリとかも発見できていい感じです。

こんな感じ使ってるよ

現状、こんな感じで、tcpdumpを取るスクリプトとレポートを出力するスクリプトを分けて運用しています。というのは、dumpしたデータが大きいとそこそこCPUパワーが持って行かれるので、サービスから外した状態か、アクセスの少ない時間帯にレポートを生成しないとサービスに影響が出てしまうのです。

素のtcpdumpの形式だとデータサイズがものすごく膨らんでしまうので、pcap形式で保存します。

capture-mysql.sh

#! /usr/bin/zsh -ue
#vim:ft=zsh:

DUMP_TO="/tmp/mysql.pcap"
DURATION_SEC=600

#バックグラウンドで実行して
tcpdump -i eth0 port 3306 -s 65535 -w ${DUMP_TO} &

# ${DURATION_SEC}秒待って、tcpdumpを止める
sleep ${DURATION_SEC}

#XXX: $!の方が良い気がしつつ
pkill tcpdump

pcap形式から元に戻した上でpt-query-digestに食わせてあげます。filterでadmin pingみたいな余計なコマンドを省いてあげます。(Perlのコードが出てくるのはここだけ) explainオプションを付けてあげると、explainの結果もレポートに含めてくれます。limitオプションで、デフォルトより多くのクエリをレポートするよう指定しています。

サブクエリを使っているプロジェクトだと少し注意して欲しいです。うちはサブクエリをほぼ使わないので、問題はあまりないのですが、EXPLAINを実行するとサブクエリが実際に実行されてしまうので、現用のアプリケーションに影響が出る可能性があります。

generate-query-report.sh

#! /usr/bin/zsh -ue
#vim:ft=zsh:

WRITE_TO="/tmp/$(hostname)_$(date +'%Y-%m-%d_%H-%M')_digest.txt"
DSN="h=$(hostname),u=****,p=****"

tcpdump -s 65535 -x -nn -q -tttt -l -r /tmp/mysql.pcap |           \
    pt-query-digest                                                \
        --type tcpdump                                             \
        --filter '$event->{fingerprint} !~ m/^(commit|admin|set)/' \
        --explain ${DSN}                                           \
        --limit=100 > ${WRITE_TO}

こんな感じの出力

ヘッダー部分

全体的なサマリがのってます。だいたい見たまんまです。

# 254.2s user time, 1.1s system time, 162.97M rss, 215.57M vsz
# Current date: Tue Mar 19 15:15:34 2013
# Hostname: *****
# Files: STDIN
# Overall: 119.38k total, 162 unique, 198.96 QPS, 0.16x concurrency ______
# Time range: 2013-03-19 14:53:52.942927 to 15:03:52.928121
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time            99s    44us      4s   826us     1ms    14ms   176us
# Rows affecte           0       0       0       0       0       0       0
# Query size        21.33M      13     809  187.36  299.03   89.08  166.51
# Warning coun           0       0       0       0       0       0       0
# Boolean:
# No index use  14% yes,  85% no
クエリ一覧

クエリにIDが振られているので気になるクエリがあればIDで検索すれば、該当のクエリの詳細に飛ぶことが出来ます。基本的には総実行時間が多い順にソートされています。
EXPLAINがa(full table scan)やi(full index scan)、F(file sort)とかになっているやつとか、R/Callが大きいやつ、Callsがやたら多いやつとか怪しそうなクエリが一目で分かって良い感じです。

各列の意味はこんな感じ。下手に訳するより原文の方がわかりやすいと思うのでそのままです。

Column Meaning
Rank The query's rank within the entire set of queries analyzed
Query ID The query's fingerprint
Response time The total response time, and percentage of overall total
Calls The number of times this query was executed
R/Call The mean response time per execution
Apdx The Apdex score; see --apdex-threshold for details
V/M The Variance-to-mean ratio of response time
EXPLAIN If --explain was specified, a sparkline; see --explain
Item The distilled query
http://www.percona.com/doc/percona-toolkit/2.1/pt-query-digest.html#output

explain列の意味はこんな感じ

a ALL
c const
e eq_ref
f fulltext
i index
m index_merge
n range
o ref_or_null
r ref
s system
u unique_subquery

http://www.percona.com/doc/percona-toolkit/2.1/pt-query-digest.html#cmdoption-pt-query-digest--explain

んで、>TFってなっているのは“Using temporary” で “Using filesort” なやつです。

# Profile
# Rank Query ID           Response time Calls R/Call Apdx V/M   EXPLAIN Item
# ==== ================== ============= ===== ====== ==== ===== ======= ==========
#    1 0xEADE97FBAE5FB4AE  9.0725  9.2%  3288 0.0028 1.00  1.39 R       SELECT u****
#    2 0x37589B7D7D604378  7.2478  7.3%   429 0.0169 1.00  0.02 r       SELECT u****
#    3 0xDBAC9DBE36FAFFDC  5.4690  5.5%  3182 0.0017 1.00  0.15 c       SELECT u****
#    4 0x79882A39EE381E85  5.1937  5.3% 23127 0.0002 1.00  0.04 c       SELECT i****
#    5 0x00F2F35435E546F2  4.5750  4.6%    37 0.1236 1.00  0.07 r>TF    SELECT u****
#    6 0x0B5583D1B4B37258  4.4587  4.5%   228 0.0196 1.00  0.24 r       SELECT u****
#    7 0x23DB871E0A8F0FF9  4.0279  4.1%   286 0.0141 1.00  0.26 N       SELECT p****
#    8 0x4882E69072537796  3.4654  3.5%    28 0.1238 1.00  0.09 a       SELECT u****
#    9 0x0386244D47C56701  3.1653  3.2%   242 0.0131 1.00  0.65 n       SELECT n****
#   10 0x800D7ACB1C324E99  3.1192  3.2%  2517 0.0012 1.00  0.05 r       SELECT u****
#   11 0x44F4B42F4FEC008F  3.0278  3.1%    43 0.0704 1.00  0.00 i       SELECT m****
#   12 0x68FBEFB7399A4113  2.9726  3.0% 12187 0.0002 1.00  0.01 r       SELECT e****
#   13 0xD2CD48CEF279E4C8  2.9483  3.0% 16991 0.0002 1.00  0.00 a       SELECT n****
#   14 0x5F042CF35BC6F481  2.6329  2.7%   503 0.0052 1.00  0.07 r>F     SELECT e****
クエリ詳細

explainオプションをつけているとEXPLAIN実行結果を自動で追記してくれます。便利ですね。オプションを付けていなくても代表的なクエリにEXPLAINを付けてくれるので、コピペして実行すれば、良いので親切です。

# Query 1: 5.49 QPS, 0.02x concurrency, ID 0xEADE97FBAE5FB4AE at byte 540683153
# This item is included in the report because it matches --limit.
# Scores: Apdex = 1.00 [1.0], V/M = 1.39
# EXPLAIN sparkline: R
# Query_time sparkline: |  ^-___ |
# Time range: 2013-03-19 14:53:53.123352 to 15:03:51.991362
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          2    3288
# Exec time      9      9s   144us      4s     3ms     3ms    62ms   839us
# Rows affecte   0       0       0       0       0       0       0       0
# Query size     0 215.16k      64      68   67.01   65.89    0.33   65.89
# Warning coun   0       0       0       0       0       0       0       0
# String:
# Databases    db*******
# Errors       none
# Hosts        ***.***.***.*** (332/10%)... 24 more
# Users        *******
# Query_time distribution
#   1us
#  10us
# 100us  ################################################################
#   1ms  ############################################
#  10ms  #
# 100ms  #
#    1s  #
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `db******` LIKE 'u*****'\G
#    SHOW CREATE TABLE `db******`.`u*****`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT COUNT(*) AS cnt
FROM u*****
WHERE (user_id = '*****')
\G
# *************************** 1. row ***************************
#            id: 1
#   select_type: SIMPLE
#         table: u******
#    partitions: NULL
#          type: ref
# possible_keys: u****
#           key: u****
#       key_len: 4
#           ref: const
#          rows: 2480
#         Extra: Using index

課題

前述したとおり、CPUパワーを持って行かれるので、サービスからゆるふわに外せないMasterサーバでレポート作るのはちょっとはばかられます。この点、レポート生成は別サーバで行えばいいという話もあります。
あと、これは運用の問題ですが、スクリプト化したとはいえ、手動で実行しているので、定時に実行してくれる仕組みが作れればいいなと思いつつも、tcpdumpはroot権限がないと実行できないので、その点、rootでcronを回すのをちょっと躊躇しています。

まとめ

いろいろ考えないといけない部分はまだあるんですが、ゆるふわにクエリ解析が出来るようになってだいぶパフォーマンスチューニングがしやすくなってステキでしたというお話でした。
pt-query-digestはperlスクリプトだからperlのお話でしたよ?

てな感じでした。




今回のchiba.pmもとても楽しかったです。3ヶ月後の開催を楽しみにしています。