細かい書き込み連発で CPU Wait% が異常上昇 : 管理人@Yoski

2011年02月08日

ブログ書くのがものすごく久しぶりなので、とりあえず肩慣らしがてら技術メモ。

先日、とあるサーバーでものすごい性能低下があって、みると CPU wait% が異常に高い。

もう全体の80% 以上が wait%。

で、この wait% ってのは主にローカルディスクが原因なのだけど、ディスクの性能限界まではまだ結構余裕があるから原因がよく分からないでいた。

のが解決したのでメモ。

PHP では error_log という便利な関数があって、ファイルにガンガン文字列を追記してくれる。
もちろんファイルじゃなくてもいいけど、多くはファイルに対してログなどを残すのに大変便利。

これがまた超高速で fwrite なんかより断然速い。しかもスレッドセーフ。 fwrite みたいに「途中までしか書き込めませんでした」なんて弱音を吐くこともない。

そして PHP 5.2.13 からはファイルへの書き込みに限って binary safe になったので、単なるテキストログを吐くだけじゃなくてストリーミング的なバイナリ出力にも使えたりするから応用範囲が広い。広すぎる。

まぁ、できるから使っちゃいました的なのはどうなのよ、error_log なんだからその名の通りエラーをログるときに使えよ、という意見はあるものの、ついつい他の用途でも使ってしまうこともあるわけです。

で、調子にのってログ的な記録をガンガン吐く形にしていて、そういうサブプロセスが 100 個くらい同時に動く状態になっていたところ wait% の異常上昇という現象が起こりました。

ベンチとってみると、ディスクの性能限界の 10〜15% くらいしか使ってない。オカシイ。何かがオカシイ。

error_log がいかんのか、と思い、きっちりファイルハンドル保持して fwrite にしたところで様子変わらず。

こりゃ、ディスク書きこむあたりで pdflush あたりがえらいことになってるんだろな、と思ったのだけど、歴代の人がチューニングしてきた kernel パラメータをいじるのは気が引ける。

であれば、ソフトウェア的に解決できるんじゃないかな、と思って pdflush のタイミングと同じく「5秒に一回まとめてファイルに書き出し」するように変更してみました。

もちろん書き出しの総バイト数や、並列動作しているプロセス数は変更なし。

で、結果、劇的に改善されて、もう wait 0% の底辺でぺったり張り付いて安定動作するようになりました、と。

と、まぁ、100個単位のプロセスがガンガンそれぞれ別ファイルに細かい書き出しをガリガリ行うと pdflush パニくるから、まとめてどっかん書き込みしたほうがディスクや CPU wait% 的にやさしいよ、というお話でした。

・・・いやしかし本当にそうなのか？実際、このあたり内部的に何がおこってるかわからないけど（いや正確には、この程度で wait% があがるような設計になっている原因がどこにあるのか突き止められなかったのだけど）、ま、解決策としてはHDD の特性からたまたまかもですね。

※このあたりの書き込みタイミングとかについては naoyaさんのこの記事に詳しい。

ちなみにサーバーは Core2 Quad Q8400 にメモリ8GB という構成。ディスクは non-RAID で 57MByte/s のシーケンシャル書き込み性能。

ということで、なんとなく忘れるのももったいない気がしたので、ちょいとメモでした。

投稿者 aka : 2011年02月08日 00:09 　/ 2011年02月 / メモ

このエントリーのトラックバックURL:
http://133.242.136.64/mt-tb-sf.cgi/851

えーと、OS は・・。

投稿者 noname : 日時 2011年02月08日 18:15

おっと、CentOS 5.5 です

投稿者 yoski : 日時 2011年02月08日 18:20

確かに人々がオンラインの会社の顔新ブランドを開始する多くの課題の一つは、自分のWebサイトに訪問者を得ることです。

投稿者 lighting manufacturers in the UK : 日時 2011年08月25日 18:42