久しぶりにDBAとしてお手伝いした時の汚いメモになります。
Percona Server5.5＋ioDriveのMySQLで、イベント時やピークタイムにアプリケーションからのDB利用が重くなる、ということで調査から対応方法まで考えてみました。
問題点の大雑把な特定
高トラフィック時に、RubyからMySQLの接続やクエリがちょこちょこ重くなり、レスポンス速度に影響が出る、とのこと。で調査開始。今回のPercona Serverのバージョンは 5.5.34 でした。以上のことから、アプリケーションからのクエリやデータ性質の問題ではなく、ほぼMySQLサーバの書き込みフラッシュのタイミングの問題であると断定しました。
問題を起こしている機能の特定
ここから問題点を一気に絞り込むために、write I/Oの書き込み先となっているファイルが何かを調べることにしました。使ったのがコレ。SH2さん様々やでホンマに。少々危なっかしいモノと噂でしたが、テスト環境で動かしたら無事に書き込みファイルが表示されたので、本番で実行すると・・・ログ量が多すぎて表示されませんでした！！でも、MySQL SLAVEが止まったり再起動もしませんでした。
なので、perlスクリプトはやめて、systemtapだけ動かし、得たIDから /proc/$mysqld-pid/fd/$fd-id のシンボリックリンクを直接見て判断しましたところ、SLAVEが平時に書き込んでいたファイルがコレらで、
10秒に1回、大量に書き込まれたのがコレと特定できました。
このファイルに1回に書き込むサイズは 1048576 (きっかり 1MB)で、その時は1つのタイミングで80回ほど連続して書き込まれていました。秒に直すと 150MB/s という感じだったので、約0.5秒で書き込み終わっていたというわけです。さすがioDrive。
innodb_file_per_table によりテーブルファイルは分割しているので、ibdata1 に書き込んでいる犯人を探すことになりました。
ibdata1 に書き込まれる内容
innodb_data_file_path = ibdata1:10M:autoextend なので、ibdata1 は肥大していくわけですが、innodb_file_per_table なのに肥大する理由を調べてみました。innodb_file_per_table 時にibdata1に書き込む内容はこんな感じ。
ここでは把握まで。
dirty pageのフラッシュ
別の切り口で、Diskに書き込まれていないブロック数を表す、dirty pageを SHOW GLOBAL STATUS で見てみました。新し目のPerconaだと、pagesに加えてbytesも取得できます。1ブロック16KBなので無くても算出できますけど。|
1 2 |
Innodb_buffer_pool_pages_dirty 2093 Innodb_buffer_pool_bytes_dirty 34291712 |
このブロック数であるpagesが 0～8000 に変わり、10秒間に1度リセットされていました。
設定の innodb_max_dirty_pages_pct を見ると、メモリ内の変更箇所のパーセンテージがこの設定値を超えたらフラッシュ～ とか書いてますけど、実際にはトランザクションログファイルまで書かれた状態でも dirty な状態って感じみたいですね。
じゃあなぜ10秒間隔なのかを追っていきます。
データファイルへ書き出されるタイミング
ここから3つ拝借。|
1 2 3 4 5 6 7 8 9 10 |
1. バッファプールのダーティ(更新された)な部分が、 innodb_max_dirty_pages_pctに達した時(単位は%) 2. バッファプールのダーティな部分がトランザクションログの合計サイズに近くなってきた時 (innodb_log_file_size * innodb_log_file_in_group) ※innodb_log_file_in_groupでは、 トランザクションログ(ib_logfile)の数を指定する事が可能(デフォルト値は2) 3. innodbへの負荷が低い場合 |
次にここから1秒・10秒間隔の処理を拝借。
|
1 2 3 |
4. Tasks to do once per second - Force transaction log to disk 5. Tasks to do once per 10 seconds - Force transaction log to disk |
色々あるものの、我々はHDDの時代からこれをPerconaで愛用してきました。
|
1 2 |
innodb_adaptive_flushing ON innodb_adaptive_flushing_method keep_average |
本来、1秒毎にフラッシュするところを、0.1秒間隔にしてくれる正義の味方でした。
しかし、これが効いていないことになる。
innodb_adaptive_flushing_method estimate にしても、innodb_adaptive_flushing OFF にしても、変わらないどころか酷くなる傾向にある。
これが今回の最大の悲しい発見でした。keep_averageさんはどうしちゃったのか。
そして10秒毎の強制タスクに助けられていたという現実に、
ioDriveはエンジニアの眼を曇らせることを再認識。
10秒間隔のフラッシュになってしまっていたことに、長い間、気づけていなかった。グラフは5分平均値だし、10秒間隔で多少重くなってもioDriveのせい（おかげ）でiowait最大値が低くて気づけない…… サービスが一定以上活気づいてようやく気づく無力感！！
対応策その１
ウチの冗長構成では、MASTERに障害が起きたらSLAVEが昇格して、二度と元MASTERにフェイルバックしないので、InnoDBのDoubleWriteは不要でした。なのに、わかっていたけど、innodb_doublewrite ON だったので、OFFにしてみたところ、当然のように書き込み容量が半分になりました。しかし、なぜか iowait でいえば、もう１つのSLAVEと比べると良くなったり、むしろ倍悪くなったり。そしてこれも当然ですが、dirty pages の数や、10秒間隔には関係ないので、ioDriveに優しく寿命が倍になるだけ。
ということで保留。
対応策その２
完全に勘で試した設定 innodb_checkpoint_age_target（そろそろフィーリングエンジニアとか呼ばれてもおかしくない）。SHOW ENGINE INNODB STATUS で表示される、Checkpoint age の最大値を制限することができます。その設定値は、Checkpoint age target として表示され、デフォ値はだいぶ大きくなっています。
|
1 2 3 4 5 6 7 8 9 10 11 12 |
--- LOG --- Log sequence number 1438977671851 Log flushed up to 1438977509986 Last checkpoint at 1438975943668 Max checkpoint age 1738750649 Checkpoint age target 1684414692 Modified age 1728183 Checkpoint age 1728183 0 pending log writes, 0 pending chkp writes 1525946706 log i/o's done, 209.91 log i/o's/second |
Checkpoint age は watch -n1 で観測すると、0 ～ 250万 でした。
この、10秒間に1回、250万が書き込まれているところを、innodb_checkpoint_age_target = 250000 にすることで1秒に1回25万が書き込まれることになり、25000 なら0.1秒に1回となるわけです。
実際、これは期待通りに短期の間隔でフラッシュしてくれるようになり、負荷が均一化されました。
ただ、これによる問題点が2つあります。
1つ目は、keep_averageの強制0.1秒と異なり、トラフィック量によってその間隔が変化してしまうということ。アプリの性質や、その時々に応じて、ピーク時のcheckpointから設定値を調整しなくてはいけません。Dynamic yes なのでSETできる分マシですが、自動化するのもアレな所ですし・・・
2つ目は、フラッシュ間隔が短いほど、書き込む総容量が増えてしまうということです。innodb_checkpoint_age_target = 1 などで遊んでみたら、かなりの書き込み容量になってしまいました。
これはおそらくですが、まとめて書き込むほどに、同じ行へのUPDATEがまとまるからです。極端に言えば、ある特定の1行へのUPDATEが10回あったとして、10秒間隔なら最終結果1回のDisk反映で済んでも、0.1秒間隔ならバラバラで10回の反映になる、といった感じでしょう、多分。（真のDBAじゃないので適当でスイマセン…）
まとめ
うーん、どっかまだ間違った知識がありそうだけど……今回得た知識をまとめます。MySQL5.6, 5.7 だとさらにcheckpoint周りに手が入っていて、本家もPerconaも設定項目が変わっているので、あまり深追いしたくない感じ。
理想では、溜まりすぎてもDiskI/O負荷が上がるし、細かすぎても書き込み量が増えるしなので、一定秒数や一定ログ量条件ではなく、アプリケーションごとに最適なバランスでフラッシュしてくれるといいのですが、5.6以降でよしなに改良されてないですかね……
はぁ・・・それにしてもioDriveの導入で、アプリケーションのクエリの質がたるむのは予想内だったけど、まさかサーバ側の異変にも気付けていなかったのが軽くショックじゃて。まだまだわたしには功夫が足りないわ。
