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に謝謝！(サーセンサーセン＞＜)