MySQLがおかしい！あなたならどうしますか？ – MySQL Casual Advent Calendar 2011

しわっす！DBA 兼オペレーションエンジニア兼タスクマネージャやってる riywo です。何のネタを書こうかなぁと考えたのですが、正直ネタを仕込む時間もなかったので僕がいつもやってることをさらっと紹介するということで勘弁して下さい＞＜

MySQL がおかしい！

03:14 hidek: なんかエラー出まくってるんだけど！
03:14 zigorou: MySQL と通信してるとこっぽい
03:15 riywo: 見ます

こんなやりとりは皆さん日常茶飯事ですよね？ね？ね？こんな時に、DB に責任を持つものとして真っ先に対応するのが僕らの仕事です。でも、じゃあ具体的にこのあと何をしましょう？既にサービスはエラーだらけで一刻を争う状態です。

(対応開始)

まずはエラーメッセージ

今回の様な場合はアプリのエラーログにどばっと MySQL に関するエラーが出ているでしょう。まずはそれを見ることが始まりです。エラーメッセージはクライアントが出すものもサーバが出すものもあります。よく訓練された DBA なら、エラーログを tail していれば目 grep でこれらのメッセージが光って見えます。

• Can't connect to MySQL server on
• Unknown MySQL server host
• Lost connection to MySQL server during query
• Too many connections
• Lock wait timeout exceeded
• Deadlock found
• and more:)

これだけからも色々と仮説が立てられると思います。例えば、Can't connectであればそもそもつなぐ先のmysqldが落ちている可能性があります。Too many connections(TMC)であれば重いクエリとかで接続がサーバ側に滞留してしまっているのかも知れません。分かりやすいメッセージは想像しやすいと思います。

Lock wait timeoutは結構厄介で、分散 DB 間のDeadlockの場合もあれば、1 レコードへの更新が多すぎてinnodb_lock_wait_timeoutを越えているだけかも知れません。他にもトランザクション中にロックを取った後で別のことをしていて、それが時間かかってるだけかも知れません。こういう場合はやはりサーバ側を見てみないといけないですね。

(ここまで 10 秒くらい)

MySQL サーバに入って何をみますか？

何はなくともサーバに ssh しましょう。vmstatなどの一般的な情報を見るのは当然です。そもそも swap してるとかであれば、変なプロセスがいないかとか、mysqldが太ってないかとかをまず確認すべきでしょう。ハードウェア障害とかで例えば I/O があからさまに劣化している場合は、そっちをなんとかすべきでしょう。I/O についてはiostat -xがオススメです。また、コア単位の cpu 使用率を見たい時もあるのでその時はmpstat -P ALLしましょう。

(ここまで 30 秒くらい)

ただ、サービスの状況を見るには MySQL に特化した情報を見る必要があります。僕が最もよく見るのは次の 3 つです。

• error-log
• slow-log
• show full processlist

色々便利なもの(分析ツールとか RRDtool のグラフとか)を準備してある環境ならそれらが参考になるでしょうが、世の中そうじゃない環境も多いと思います。でもそんな準備や時間がなくとも、今目の前で起こっているトラブルについては大抵この辺で当たりが付けられます。

error-log

いわゆるエラーログです。my.cnf 等ではlog-errorで指定します。mysqldが落ちたとかの場合には一番活躍します。ストレージ障害などがあったときはここに怪しげなメッセージが出ることが多いです。

slow-log

遅いクエリが吐かれるログです。log-slow-queries/slow_query_log_fileで指定します。long_query_timeを超えたものが吐かれるのでクエリが遅くて問題が起きているときは大抵このログで事足ります。

• 参考

  • 漢(オトコ)のコンピュータ道: MySQL 5.1 のスロークエリログ

show full processlist

これは mysqld に接続して発行します。色んな情報見たいのでとりあえず root でいいんじゃないかと思います。show full processlistは mysqld が一体何をしているかを一番端的に表示してくれます。slow-logには出ないけどちょっと遅いクエリとかは何回かshow full processlistを叩けば大抵ひっかかります。あと、レプリケーション遅延などの場合には SQL Thread の実行しているクエリを見ると原因が分かったりします。

改善すべきクエリを探してる時に、show full processlistでもひっかからない時にはどうしましょうか？そういう時はlong_query_timeを一時的に短くしてみましょう。

mysql> set global long_query_time = 0.1;

これで 0.1 秒以上の物が記録されます 100ms は結構遅い方ですね。あとはこれを徐々に短くしながらslow-logをtail -fしておけば大体怪しいクエリがあぶり出せると思います。

(ここまで 3 分)

怪しいクエリを見つけたら？

ハードウェア障害とかでなければ、クエリの改善や index の追加をしないといけないパターンが多いと思います。上記の方法で大体怪しいクエリは見つけられているでしょうから、それらがなぜ問題を引き起こしているのかを分析します。

と、ここから先はそのクエリの種類によって分析は多岐に渡ると思います。特に index の使われ方やそれによるロックのされ方などは奥が深く、僕も未だに完全に理解しているとは言えません。とはいえ、入り口の部分はシンプルです。よく見る項目はこんな感じでしょうか。

• show table status
• explain
• show create table ...

show table status

怪しげなクエリの関わるテーブルの基本情報は押さえておきましょう。show table statusの結果ではRows,Data_length,Index_lengthが見るべきものです。Rowsは統計情報に基づくのであまり正確ではありませんがオーダーをつかむには十分です。Data_length + Index_lengthが InnoDB で占めているサイズになります。これらが大きいテーブルは buffer pool から大幅にはみ出している可能性があるので、深刻な劣化を引き起こす場合が多いです。

explain

言わずもがな、クエリ分析の中心格です。詳しいことは奥野さんの鍵本を見てください。

カジュアルな分析であれば、keyとrowsに注目しましょう。特に select では意図した index が使われているか、それによって適切に行数が絞りこまれているかが重要です。もし変な index が使われているならforce indexというヒント句をアプリ側で付けてもらうと良いです。

show create table ...

テーブルの定義(DDL)を確認できます。descでは index の状況が確認できず、show index fromではカラムの状況が確認できないので、僕はいつもどっちも一発で見れるshow create tableを使っています。explain の結果などからクエリのチューニングを考える際に、DDL とにらめっこすることになるでしょうから、これも良く使います。

正直もっと踏み込んだクエリの分析は一朝一夕では身につかないので、常に MySQL/InnoDB について勉強し続けることと、常日頃からクエリのチューニングを考え続けることで経験値を上げていくことが重要です。ここだけカジュアルじゃないよ！

(ここまで 5 分)

いまいち怪しいクエリがわからない＞＜

大抵そういう場合は数が異常なことが多いです。こういう場合になって、初めて統計的な分析を始めればよいでしょう。僕がよくやる方法は、さっきのlong_query_timeを短くして一時的に出力したslow-logか、tcpdumpでキャプチャした結果をpt-query-digest(旧mk-query-digest)に食わせて、総実行時間やクエリ回数の多いもののチューニングができないか考えます。クエリが単純でチューニングの余地がない様な場合、それはアプリ側でキャッシュできることが多い、とかも頭に入れておく必要があります。

• pt-query-digest — Percona Toolkit Documentation

これについて語りだすともう数日分書ける感じなのでこの辺にしておきましょう。

(ここまで 10 分)

結果どうなったか

03:20 riywo: このクエリですね select * from dis_comments where id = 'nekokak' order by created_at desc limit 10000000
03:20 zigorou: う、、、、それは今日撒いたやつ。。。
03:21 hidek: えーｗ
03:21 zigorou: 切り戻します サーセン＞＜
03:21 xaicron: gfx- -
03:21 gfx: なんで！？

こんなやりとりよくありますよね？ね？

おわりに

というわけで、5 分、10 分あれば MySQL のカジュアルなトラブルシューティングはできるんだよ、というお話でした。一刻を争うトラブル対応ですので、速さが最も重要です。今回紹介した方法は特に事前に準備が必要なものでもないので、いきなりポンと渡された MySQL サーバでも十分使えるわけですね。もしあなたの MySQL が次に悲鳴をあげたときはこんな感じでやってみるとサクっと原因が分かったりするかも知れません！

もちろん、障害の種類は多岐にわたるのでいつもこんな簡単にシューティングできるわけではありません。また、障害対応とは別に日々の性能管理も必要でその時にはまた違うところを見るでしょう。シンプルだけど奥が深い、これが DBA の醍醐味ですね！

明日は MySQL のカジュアルさでは世界ナンバーワンのゆるふわ、xaicron 先生の登場ですよ！楽しみですね！

最後にご出演頂いた Hackers of DeNA に謝謝！(サーセンサーセン＞＜)