WiKicker の高速化のために SpeedyCGI 対応作業。
等を行う。 手元では動くようになった。
で今度は www.naney.org 上でテストしてみたのだが、無念 SpeedyCGI 自体がうまく動かない (FreeBSD 4.4-RELEASE + Perl 5.005_03)。 CGI で呼び出すと
failed to open log file fopen: Permission denied
とエラー。make test でもこけているテストがあったし(t/sh_bang、t/timeout)このサーバじゃ動かんのかな?
CGI スクリプトの先頭に
#!/home/.../bin/speedy -w -- -M30 -t300 -r30 -p/home/.../bin/speedy_backend
のように記述していたのだが path部分が長かったため sh-bang の限界を越えてしまっていたようだ。-p オプションで指定している speedy_backend のパスの方はデフォルトが Makefile.PL 実行時に適切に設定されているはずだから、実際には省略可。
ということで、
#!/home/.../bin/speedy -w -- -M30 -t300 -r30
としてみたら動いた。 よっしゃ。 これでリクエスト毎のプログラムのローディングの必要がなくなるので、レスポンスの遅さが改善されるはず。 パラメータは
としておく。様子をみて微調整。 これからは、WiKicker を更新したら Wiki CGI スクリプトを touch する事を忘れないようにしなくては(SpeedyCGI にバックエンドを再起動させなおさせるため)。
今のところ問題なく動いている様子。 レスポンスも良くなった感じ。 通常時で4つ程度、繁忙時で25程度 CGI プログラムが speedy_backend で常駐しているようだ。
WiKicker / DiKicker の Log::Log4perl 対応作業。
ということで、warn -> Apache のエラーログに流れている警告メッセージも、Log::Log4perl の方に流して、好きに消せるようにしておくことにする。
SpeedyCGI 下で動かす事を想定して初期化は、init_once で行うようにする。 可能な限り早く初期化すべきなので、設定ファイル名/設定文字列はプロパティファイルに記述しておくのではなく、CGI プログラムで最初に生成する Controller オブジェクトの初期化パラメータで指定するように。
$SIG{__WARN__}を設定して、warn のメッセージを Log::Log4perl に送る。 最初はほぼ FAQ の例のまま、以下のように記述。
use Log::Log4perl qw(:easy); BEGIN { $::SIG{__WARN__} = sub { local $Log::Log4perl::caller_depth = $Log::Log4perl::caller_depth + 1; WARN(@_); }; }
しかし期待していた通りに動かず悩む。原因は前述する init_once との絡み。 use Log::Log4perl qw(:easy) した時点でデフォルトの初期化が行われてしまうため、初期化済みになってしまって init_once での設定処理がスキップされていたのが問題。
use Log::Log4perl; BEGIN { $::SIG{__WARN__} = sub { local $Log::Log4perl::caller_depth = $Log::Log4perl::caller_depth + 1; if (Log::Log4perl->initialized) { Log::Log4perl->get_logger->warn(@_); } }; }
と修正。 get_logger も暗黙的に初期化を行うので、init_once する前に warn されるとやはりデフォルトの初期化がおこってしまう。 それではまずいので initialized が真(=初期化済み)の時のみロギングするようにする。 ただしこれだと init_once する前の warn メッセージが失なわれる(STDERR あたりに print するようにすればいいかもしれない)。
CGI::Carp も $SIG{__WARN__} を上書きするので同時に使えない。 以前に use していたのが残っていてはまる。
NaneyOrgWiki、nDiki でロギングしはじめたところ、CGI プログラムの処理はきちんと成功しているもののその後(?) speedy_backend が core dump してしまう事があるようだ。 最初は $::SIG{__WARN__} の設定あたりに問題があるのかと思ったが、Log::Log4perl::Appender::Synchronized を使わないようにしたところ core を吐かなくなった。
IPC::Shareable、IPC::Semaphoreなんて使っているしやっぱりこれが怪しい。 とりあえず外しておくことにする。
しかし何らかの方法でシンクロしておかないとログファイルが壊れるはずだから、本当はどうにかしなければならないな。 もっと簡単に flock とかで排他制御する Appender とか無いのかな。 自分で書くしかない?
www.naney.org をホスティングしているサーバが重いと思ったら、同じサーバ上のあるユーザの CGI プログラムが5プロセス無限ループしてるっぽい……。 load average 20前後。
あおりを受けて、nDiki が大変なことになっている。
nDiki は SpeedyCGI を使っているのだが、バックエンドの speedy_backend が捌ききれず、フロントエンドの speedy が大量に待ちに入ってしまっている。
MaxBackends を調整しても駄目(下手にバックエンドプロセス数を増やしても、結局処理が追いつかない)。
ということで急遽対策。
load average が高い時には、はてなブックマーク上の検索結果を表示させるために行なっているはてなブックマークへのアクセスを休止するように変更。 24時間に設定してあるキャッシュの有効期限が切れていても、高負荷の時にはアクセスにいかないようにする。
これで DiKicker の処理時間を短縮。相手側サーバへの負担も軽減。
おかげ様でここ最近 nDiki の RSS へのアクセス数が増えてきている。 ありがたい事である。
しかしながら DiKicker の RSS レスポンスは、あまり賢くなく毎回データベースから最新記事情報を抽出して生成しているため、それほど処理が速くない。
なのでアクセス頻度を高くしている RSS リーダがどこかで同時に起動しているとちょっとしんどい。 特にここ最近 Google Desktop からのアクセス数が増えている感じ。
さすがに今日はサーバの負荷が高く処理が追いつかなくてどうしようもないので、一時的に Google Desktop を拒否することに。
.htaccess に設定を追加。
BrowserMatch "Google Desktop" denybrowser deny from env=denybrowser
近日中に、RSS 処理を改善してすぐに解除する予定。
効果があるかどうかは不明だが、Crawl-delay: に対応するというクローラ (Slurp、msnbot) 向け設定を追加。
User-agent: Slurp Crawl-delay: 20 User-agent: msnbot Crawl-delay: 20
アクセス数としては Googlebot と Slurp がダントツ。 しかし Google は無下にする訳にもいかないしなぁ。
朝 www.naney.org の過去記事を確認しつつ作業をしていたら、9:00 前に急にアクセスできなくなった。 ping も通らない。 9:20 ぐらいに 1度復帰したが、また10:00 前にダウン。
それから何度も落ちては復帰を繰り返すようになってしまっている。 SSH で接続している途中にも突然刺ささるし、傍から見ていても原因が良くわからない。
昨日 WiKicker をアップデートしたから「もしかしてうちが原因?」とちょっと心配もしたりするのだが、無限ループに入ったりメモリを使い尽すようなコードが追加してはいないはずだしなぁ(ローカルでのテストではそのような現象は見られない)。
落ちる直前まで見ていてもそれほど load average が高いわけでもないようだしなぁ。
とまぁ、しばらく様子を見ているうちに NaneyOrgWiki と nDiki が Internal Server Error。 止められた。 正確には SpeedyCGI のフロントエンド speedy コマンドの実行権限を管理者に落とされた。
ということもあって疑われたと推測。
一応こちらでも SpeedyCGI を使わないで直接 Perl で実行するように変更してみたり、Memcached を起動するのをやめてみたりなど設定を変更してみたりするのだけれど、関係なく落ちる落ちる。
管理者がシステムの設定を変えていないで発生するようになったのなら、ハードウェア障害が起きているんじゃないかと想像してしまうのだが、実際どうなんだろうか。
結局夜 23:00 過ぎだかに落ちたあとは復帰する様子がないので(管理者が落ちたかな?)、今日はあきらめ。
www.naney.org を収容しているサーバの負荷が高い状態。
という対処をしたけれどそれでもなかなか負荷が落ちつかない。
傾向としては SpeedyCGI のバックエンド側(speedy_backend)が MaxBackends まで起動して処理が追いつかないと、起動しているフロントエンド側 (speedy) がどんどん増えてしまうという状況のようだ。
DiKicker の高速化も順次着手しているのだけれど追いつきそうにもないので、loave average が高い時は頑張らずに無条件に 503 を返すように修正して対応(以前ハイパー日記システムの時にも同じことをした)。
本当は SpeedyCGI フロントエンドの数に応じて負荷の軽い処理に切り換える等工夫したいんだけれど、フロントエンドの数を取得する方法は簡単にはなさそうなんだよなあ。
Naney (なにい) です。株式会社MIXIで SNS 事業の部長をしています。
※本サイトの内容は個人的見解であり所属組織とは関係ありません。