MySQL + ioDrive + XFSにおけるbinlogローテート問題

前回の問題とはまた別件で、今度はbinlogのローテート切り替わりタイミングに更新クエリが停滞する、という問題を調べることになりました。

調査の過程で何を誤ったか、Twitterという魔法陣から最強クラスの重鎮魔神を召喚してしまい、恐れ多くも原因の特定と対応方針の決定ができてヘコヘコな感じでございます。



binlogローテート時の障害

数十分に１回、更新クエリが停滞してアプリケーションにエラーログが残るということから、他のエンジニアが、どうもbinlogの切り替わり時にそれが起きているっぽいことを特定してくれました。発生時は1～3秒は更新機能が停止するので、結構なレベルの障害ということでした。

binlogは1GBでローテートするように設定していたのですが、dstat -d でwrite容量を見ていると、確かに切り替わり時に800～900MBの書き込みを確認できました。

このことから、binlogが定期的にDisk Flushされておらず、一気にFlushしていることが問題なのではないか、という方向性で調べていきました。


テスト環境

CentOS 5.6 + ioDrive Duo + Fusion-io driver 2.3.1

となかなか古めかしい環境ですが、この問題はioDrive2でも同様に起こっていました。


HDDとioDriveの比較調査

後で、結果的にはファイルシステムの問題とわかるのですが、この時点では同サーバにある HDD(ext3) と ioDrive(xfs) それぞれにbinlogを置いて比較してみました。HDDでは5秒間隔でFlushされているっぽいのに対し、ioDriveでは一切Flushされない……

binlogではなく、適当なログ追記プログラムで書き込んでも同様で、ioDriveではいつまで経ってもFlushされず、データはどうやって保全されているのか、ioDrive様はFlushしなくても秘密の場所に保全しているのか、Flushが見えないようにドライバが隠しているのか！とか、またioDriveを邪推する悪い癖が始まりました。

5秒間隔のFlushは、pdflushによるもので、この辺が参考になります。
  • Kodama’s tips page – Linux ディスクキャッシュの開放
  • Linux I/O のお話 write 編 – naoyaのはてなダイアリー

    • 自分の調査で、binlog切り替わり時に重くしないための施策の当たりは大体ついていましたが、少なくとも、ioDrive使用時には pdflush と無関係のように見えるので、この辺の挙動を無視しておくと危ない気がしたため、大先生にブーメランを投げてみました。


    @hasegaw 降臨イベント

    ioDriveのことは通常、サポート窓口にメールするべきなのですが、SNSの良い所というか悪い所というべきか、Twitterの画面にはioDriveのスペシャリスト @hasegaw 氏が映っていて、この人なら丁寧に質問したらすぐ返ってくるっしょ！的なノリで投げてみたら……（※質問内容は下記Tweetでつなげて見れます）


    なんと、本体を召喚してしまいました……


    　　　　　　　　　　　　　　　　　　　　　　　彼に質問する前に言っておくッ！
    　　　　　　　　　　　　　　　おれは今、彼の能力をほんのちょっぴりだが体験した
    　　　　　　　　　　　　　い…いや…体験したというよりはまったく理解を超えていたのだが……
    　　　　　　　　 ,. -‐””'””¨¨¨ヽ
    　　　　 　 　 (.＿＿_,,,… -ｧァﾌ|　　　　　あ…ありのまま 今　起こった事を話すぜ！
    　 　 　 　 　 |i i|　 　 }!　}} /／|
    　　　　 　 　 |l､{　 　j}　/,,ｨ//｜　　『おれは彼にTwitterで質問したと思ったら
    　　　　　　　 i|:!ヾ､_ﾉ／ u {:}//ﾍ　　　いつのまにか目の前に現れていた』
    　　　　　　　 |ﾘ u’ }　 ,ﾉ　_,!V,ﾊ |
    　　 　 　 ／´fト､_{ﾙ{,ィ’ｅﾗ　, ﾀ人　　　　オンラインで質問したと思っていたら
    　　　　 /’ 　 ヾ|宀| {´,)⌒/ |<ヽﾄiゝ　　　　オンサイト対応に切り替わっていやがった…
    　　　　,ﾞ　 ／ )ヽ iLﾚ 　u' |　| ヾｌﾄﾊ〉
    　　 　 |／_／　 ﾊ !ニ⊇　'／:} 　V:::::ヽ　　　　頭がどうにかなりそうだった…
    　　　 /／ 二二二7'T'' ／u'　__ /:::::::/｀ヽ
    　　　/'´r　-―一ｧ‐ﾞＴ´　'"´ ／::::／-‐ 　＼　　　マサカリだとかブーメランだとか
    　　 / // 　 广¨´ 　/'　　 ／:::::／´￣｀ヽ ⌒ヽ　　　そんなチャチなもんじゃあ　断じてねえ
    　　ﾉ ' /　 ノ:::::    ー-､___／:::::／/ 　 　 　 ヽ　　}
    _／｀丶　/::::::::::::::::::::::::::￣`ー-{:::...　　　 　　　ｲ　 もっと恐ろしいものの片鱗を味わったぜ…


    さすがFusionIO社のスペシャルテクニカルサポートは格が違った！
    Tweet質問からわずか2時間で現地に足を運ぶクォリティ！！

    皆さんもオンラインで質問をする時は『覚悟』を。
    でも『覚悟』をもって「質問したッ！」を使うよりも
    「質問してやるッ！」って言ってた方が幸せな時もあるかもしれません。


    原因の究明

    @hasegaw 大先生が無事ご到着なされ、早速、状況報告と原因究明の作業へ入りました。色々と調べましたが、『ioDriveに定期的Flushがされない』問題の答えとしては、

  • KernelとFilesystem、そしてioDriveドライバの相性問題によるもの

    • ということになりました。

    今回で言えば、
    　CentOS 5.6 でKernelが 2.6.18-238.el5 、
    　FilesystemはXFS (rw,noatime,nodiratime,nobarrier) で、
    　iomemory-vsl (2.6.18-238.el5) は 2.3.1.123-1.0

    のうち、RedHat系のKernelは色々パッチが当たって、何が原因か追い難いという点と、この頃のioDriveドライバはまだまだ各種KernelやFilesystemとの問題が多く残っているので、3.x系の最近のものだと、かなり自信を持って対応できている、ということでした。

    これ以外にもXFSの他の問題点を解説していただいたり、急にFusionIO製品の話に切り替わったり、私含めて３名で脳みそパンパンになるくらい楽しくお話を聞かせていただきました！


    解決方法

    肝心のbinlog切り替わり時における、binlogサイズ丸ごとwrite I/O発生問題の解決方法ですが、2点あります。

    binlogサイズの調整

    binlogをあまり細かく小さくすると、それはそれで余計なコストが発生して
    何かしらのリスクが増えることになる可能性がありますが、

    基本的にはこのサイズがシステムに影響することはほとんどないので、
    現行の 1GB を 512MB, 256MB 程度に引き下げることで、
    一括書き込みが発生すると想定した場合の、リスクを低減します。

    明示的なbinlogのDisk Flush

    MySQLの設定にある sync_binlog = 0 は、binlogのDisk FlushのタイミングはOSに任せるというものです。これにより、今回は運悪くOSとioDriveの相性問題により、細かい間隔でFlushされず一括されるハメになりました。

    sync_binlog は1以上にすることで、その回数の更新が発生するたびにDisk Flushしてくれるようになります。よく、sync_binlog = 1 にすることでbinlogデータの保全を謀り、その代わりにwrite I/Oが重くなるという話題がされますが、そういう目的ではなく、

    OSの仕様に依存せず、MySQLのシステムとして明示的に数秒間隔でFlushするために、1以上に設定します。ただし、1だとioDriveといえど 0.5%～1.0% のiowaitが発生してしまうので、100, 1000, 10000 といった数値にすると、iowaitの追加無しに定期的にFlushされ、切り替わりのタイミングで大量のwrite I/Oが発生することはなくなります。

    どの数値がベストかは言い切れないところですが、DynamicにSETできるので、1, 2, 4, 8 ... と切り替えてみれば、大体どのように影響度が変わるかはわかります。

    その他の環境で

    今回の環境以外も多少試しましたが、
    Debian7＋ioDrive＋XFS ではログ書き込み後の10～20秒後にFlushされたり、
    Debian7＋HDD＋XFS では普通に5秒間隔でFlushされたり、といった感じでした。

    @hasegaw 先生がわざわざ CentOS Live CD で試してくれたパターンでは、
    ext3 では5秒Flush、XFSではファイルclose時にFlushだったり、
    最近の製品だと即座にFlushされ続けたりと、また別の挙動報告をいただけました。



    OSを変えたり、ioDriveのパーティションをext4にしたり、とかは対策としては行き過ぎだし、それでも結果が不明確なので、本件に関しては sync_binlog での調整が安定的だと思います。

    トラブルシューティングはわりと好きな方ですが、
    他社エンジニアさんと取り組むのは非常に刺激になってよいですね。
    今回はちょっと刺激が強すぎましたけど！

    最後になりましたが、@hasegaw さん ご協力ありがとうございました。
    またのご来訪をお待ちしておりますが、できるだけそうならないように頑張ります！

    Posted on 2014/05/20   カテゴリー: ioDrive, MySQL タグ: , , , パーマリンク