Percona Server 5.5にて10秒間隔でDisk I/Oが重くなる問題

久しぶりにDBAとしてお手伝いした時の汚いメモになります。

Percona Server5.5+ioDriveのMySQLで、イベント時やピークタイムにアプリケーションからのDB利用が重くなる、ということで調査から対応方法まで考えてみました。



問題点の大雑把な特定

高トラフィック時に、RubyからMySQLの接続やクエリがちょこちょこ重くなり、レスポンス速度に影響が出る、とのこと。で調査開始。今回のPercona Serverのバージョンは 5.5.34 でした。

  • top -d1 で触診してみると、謎の10秒間隔でiowaitが5~10%に上がることを確認
  • 5分平均のiowaitグラフを見ても、ピーク時は50~60%であることを確認。ioDriveでこれはイカン
  • dstat で見ると、平時はwrite数MB/s~十数MB/sのところが、やはり10秒間隔でwrite 数百MBを確認。ピーク時はこれが500MB超えとのこと
  • iotop -d1 で見ると、特定のMySQLスレッドが10秒間隔で数百MB/sを出している
  • CPU負荷も、特定のMySQLスレッドが60%
  • 他のアプリケーションのDBを見ても10秒間隔の特徴を発見
  • MASTER/SLAVE 共に同現象

  • 以上のことから、アプリケーションからのクエリやデータ性質の問題ではなく、ほぼMySQLサーバの書き込みフラッシュのタイミングの問題であると断定しました。


    問題を起こしている機能の特定

    ここから問題点を一気に絞り込むために、write I/Oの書き込み先となっているファイルが何かを調べることにしました。使ったのがコレ。SH2さん様々やでホンマに。

  • SystemTapでMySQLのDisk I/Oを分析する – SH2の日記
  • SystemTapでMySQL 5.5のDisk I/Oを分析する – SH2の日記

  • 少々危なっかしいモノと噂でしたが、テスト環境で動かしたら無事に書き込みファイルが表示されたので、本番で実行すると・・・ログ量が多すぎて表示されませんでした!!でも、MySQL SLAVEが止まったり再起動もしませんでした。

    なので、perlスクリプトはやめて、systemtapだけ動かし、得たIDから /proc/$mysqld-pid/fd/$fd-id のシンボリックリンクを直接見て判断しましたところ、SLAVEが平時に書き込んでいたファイルがコレらで、
  • socket:[1268430]
  • /fio/mysql/ib_logfile1
  • /fio/mysql/master.info
  • /fio/mysql_log/relay/info
  • /fio/mysql_log/relay/relay.003784
  • /fio/mysql_log/bin/bin.001259

  • 10秒に1回、大量に書き込まれたのがコレと特定できました。
  • /fio/mysql/ibdata1

  • このファイルに1回に書き込むサイズは 1048576 (きっかり 1MB)で、その時は1つのタイミングで80回ほど連続して書き込まれていました。秒に直すと 150MB/s という感じだったので、約0.5秒で書き込み終わっていたというわけです。さすがioDrive。

    innodb_file_per_table によりテーブルファイルは分割しているので、ibdata1 に書き込んでいる犯人を探すことになりました。

    (訂正前)ただ、mysqldプロセスが書き込むファイルを全て出しているのに、アプリ用DBのテーブルファイルが出現しなかった理由は不明なままです。ibdata1 に書いているように見えて・・・各テーブルファイルにどうやって書き込んでいるのか・・・


    (訂正後)sh2先生の2つ目の記事を見ていなかったために、テーブルファイルが表示されなかったようです。真スクリプトで実行すると、read/writeに加えて、aio_writeが表示され、テーブル別のibdファイルに書き込まれていることを確認できました



    ibdata1 に書き込まれる内容

    innodb_data_file_path = ibdata1:10M:autoextend なので、ibdata1 は肥大していくわけですが、innodb_file_per_table なのに肥大する理由を調べてみました。

  • Why is the ibdata1 file continuously growing in MySQL?
  • MySQL ibdata1が肥大化する理由(記事の意訳) | Ore no homepage
  • mysql – ibdata1 grows exponentially when innodb_file_per_table is configured – Database Administrators Stack Exchange
  • XtraDB / InnoDB internals in drawing

  • innodb_file_per_table 時にibdata1に書き込む内容はこんな感じ。
  • Data Dictionary
  • Double Write Buffer
  • Safety Net to Prevent Data Corruption
  • Helps Bypass OS for Caching
  • Insert Buffer (Streamlines Changes to Secondary Indexes)
  • Rollback Segments
  • Undo Logs
  • Click Here to see a Pictorial Representation of ibdata1

  • ここでは把握まで。


    dirty pageのフラッシュ

    別の切り口で、Diskに書き込まれていないブロック数を表す、dirty pageを SHOW GLOBAL STATUS で見てみました。新し目のPerconaだと、pagesに加えてbytesも取得できます。1ブロック16KBなので無くても算出できますけど。

    このブロック数であるpagesが 0~8000 に変わり、10秒間に1度リセットされていました。

    設定の innodb_max_dirty_pages_pct を見ると、メモリ内の変更箇所のパーセンテージがこの設定値を超えたらフラッシュ~ とか書いてますけど、実際にはトランザクションログファイルまで書かれた状態でも dirty な状態って感じみたいですね。

    じゃあなぜ10秒間隔なのかを追っていきます。


    データファイルへ書き出されるタイミング

    ここから3つ拝借。
  • innodb | LAMP勉強ブログ
  • 次にここから1秒・10秒間隔の処理を拝借。

  • [PDF] Life of a dirty page InnoDB disk IO : Mark Callaghan
  • 色々あるものの、我々はHDDの時代からこれをPerconaで愛用してきました。

    本来、1秒毎にフラッシュするところを、0.1秒間隔にしてくれる正義の味方でした。
    しかし、これが効いていないことになる。

    innodb_adaptive_flushing_method estimate にしても、innodb_adaptive_flushing OFF にしても、変わらないどころか酷くなる傾向にある。

    これが今回の最大の悲しい発見でした。keep_averageさんはどうしちゃったのか。
    そして10秒毎の強制タスクに助けられていたという現実に、
    ioDriveはエンジニアの眼を曇らせることを再認識。

    10秒間隔のフラッシュになってしまっていたことに、長い間、気づけていなかった。グラフは5分平均値だし、10秒間隔で多少重くなってもioDriveのせい(おかげ)でiowait最大値が低くて気づけない…… サービスが一定以上活気づいてようやく気づく無力感!!


    対応策その1

    ウチの冗長構成では、MASTERに障害が起きたらSLAVEが昇格して、二度と元MASTERにフェイルバックしないので、InnoDBのDoubleWriteは不要でした。なのに、わかっていたけど、innodb_doublewrite ON だったので、OFFにしてみたところ、当然のように書き込み容量が半分になりました。

    しかし、なぜか iowait でいえば、もう1つのSLAVEと比べると良くなったり、むしろ倍悪くなったり。そしてこれも当然ですが、dirty pages の数や、10秒間隔には関係ないので、ioDriveに優しく寿命が倍になるだけ。

    ということで保留。


    対応策その2

    完全に勘で試した設定 innodb_checkpoint_age_target(そろそろフィーリングエンジニアとか呼ばれてもおかしくない)。
  • Improved InnoDB I/O Scalability — Percona Server 5.5 Documentation

  • SHOW ENGINE INNODB STATUS で表示される、Checkpoint age の最大値を制限することができます。その設定値は、Checkpoint age target として表示され、デフォ値はだいぶ大きくなっています。

    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じゃないので適当でスイマセン…)


    まとめ

    うーん、どっかまだ間違った知識がありそうだけど……今回得た知識をまとめます。

  • SystemTap最高!なんにでも使えるじゃん!!
  • innodb_adaptive_flushing_method keep_average がいつの間にか効かなくなってた? => 原因不明
  • keep_average が効いていないにしても、1秒に1回のフラッシュも発動していなかった => 原因不明
  • 10秒に1回の強制フラッシュに助けられていた
  • innodb_doublewrite OFF はホントに書き込み容量が半分になるが、iowaitが何故か怪しい
  • innodb_checkpoint_age_target で確実にトランザクションログのフラッシュ間隔を調整できる。ただし、間隔はトラフィック流量次第

  • MySQL5.6, 5.7 だとさらにcheckpoint周りに手が入っていて、本家もPerconaも設定項目が変わっているので、あまり深追いしたくない感じ。

    理想では、溜まりすぎてもDiskI/O負荷が上がるし、細かすぎても書き込み量が増えるしなので、一定秒数や一定ログ量条件ではなく、アプリケーションごとに最適なバランスでフラッシュしてくれるといいのですが、5.6以降でよしなに改良されてないですかね……

    はぁ・・・それにしてもioDriveの導入で、アプリケーションのクエリの質がたるむのは予想内だったけど、まさかサーバ側の異変にも気付けていなかったのが軽くショックじゃて。まだまだわたしには功夫が足りないわ。