nDiki : speedy_backend

[ WiKicker ] SpeedyCGI 対応するも……

WiKicker の高速化のために SpeedyCGI 対応作業。

• Singleton パターンの除去
• リクエスト処理後にデータベースunlock処理を必ず実施するようにする
• DATAハンドルの読み込みを最初にキャッシュ

等を行う。 手元では動くようになった。

で今度は 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

としてみたら動いた。 よっしゃ。 これでリクエスト毎のプログラムのローディングの必要がなくなるので、レスポンスの遅さが改善されるはず。 パラメータは

• -M30 (MaxBackends: これ以上だとサーバによろしくない?)
• -t300 (Timeout: デフォルトの 3600=1時間だと長いかな。不要なプロセスは早めに止めておきたい)
• -r30 (MaxRuns: まだバグ・メモリリーク等があるかもしれないので30回呼ばれたらバックエンドを re-exec するように)

としておく。様子をみて微調整。 これからは、WiKicker を更新したら Wiki CGI スクリプトを touch する事を忘れないようにしなくては(SpeedyCGI にバックエンドを再起動させなおさせるため)。

[ WiKicker ] SpeedyCGI 化の様子

今のところ問題なく動いている様子。 レスポンスも良くなった感じ。 通常時で4つ程度、繁忙時で25程度 CGI プログラムが speedy_backend で常駐しているようだ。

[ Perl ] Log::Log4perlのはまりどころ

WiKicker / DiKicker の Log::Log4perl 対応作業。

• www.naney.org は Apache の VirtualHost としてエラーログも個別に吐かれている
• エラーログは自分のホームディレクトリに吐かれるものの、root 所有である
• ディレクトリは自分に所有権があり、エラーログが肥大化したら消す事もできるのだが、Apache をリスタートする権利がないので(週に1度のシステム側のローテーションが起きるまで)二度とエラーログが見れなくなる。

ということで、warn -> Apache のエラーログに流れている警告メッセージも、Log::Log4perl の方に流して、好きに消せるようにしておくことにする。

Log::Log4perl->init_once

SpeedyCGI 下で動かす事を想定して初期化は、init_once で行うようにする。 可能な限り早く初期化すべきなので、設定ファイル名/設定文字列はプロパティファイルに記述しておくのではなく、CGI プログラムで最初に生成する Controller オブジェクトの初期化パラメータで指定するように。

$SIG{__WARN__} を設定

$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との絡み

CGI::Carp も $SIG{__WARN__} を上書きするので同時に使えない。 以前に use していたのが残っていてはまる。

Log::Log4perl::Appender::Synchronized で core dump ?

NaneyOrgWiki、nDiki でロギングしはじめたところ、CGI プログラムの処理はきちんと成功しているもののその後(?) speedy_backend が core dump してしまう事があるようだ。 最初は $::SIG{__WARN__} の設定あたりに問題があるのかと思ったが、Log::Log4perl::Appender::Synchronized を使わないようにしたところ core を吐かなくなった。

IPC::Shareable、IPC::Semaphoreなんて使っているしやっぱりこれが怪しい。 とりあえず外しておくことにする。

しかし何らかの方法でシンクロしておかないとログファイルが壊れるはずだから、本当はどうにかしなければならないな。 もっと簡単に flock とかで排他制御する Appender とか無いのかな。 自分で書くしかない?

サーバ高負荷状態につき DiKicker 機能修正とサーバ設定変更

www.naney.org をホスティングしているサーバが重いと思ったら、同じサーバ上のあるユーザの CGI プログラムが5プロセス無限ループしてるっぽい……。 load average 20前後。

あおりを受けて、nDiki が大変なことになっている。

nDiki は SpeedyCGI を使っているのだが、バックエンドの speedy_backend が捌ききれず、フロントエンドの speedy が大量に待ちに入ってしまっている。

MaxBackends を調整しても駄目(下手にバックエンドプロセス数を増やしても、結局処理が追いつかない)。

ということで急遽対策。

高負荷時にはてなブックマークへのアクセスを停止

load average が高い時には、はてなブックマーク上の検索結果を表示させるために行なっているはてなブックマークへのアクセスを休止するように変更。 24時間に設定してあるキャッシュの有効期限が切れていても、高負荷の時にはアクセスにいかないようにする。

これで DiKicker の処理時間を短縮。相手側サーバへの負担も軽減。

Google Desktop からのアクセスを一時的に拒否

おかげ様でここ最近 nDiki の RSS へのアクセス数が増えてきている。 ありがたい事である。

しかしながら DiKicker の RSS レスポンスは、あまり賢くなく毎回データベースから最新記事情報を抽出して生成しているため、それほど処理が速くない。

なのでアクセス頻度を高くしている RSS リーダがどこかで同時に起動しているとちょっとしんどい。 特にここ最近 Google Desktop からのアクセス数が増えている感じ。

さすがに今日はサーバの負荷が高く処理が追いつかなくてどうしようもないので、一時的に Google Desktop を拒否することに。

.htaccess に設定を追加。

 BrowserMatch "Google Desktop" denybrowser
 deny from env=denybrowser

近日中に、RSS 処理を改善してすぐに解除する予定。

robots.txt に Crawl-delay: を追加

効果があるかどうかは不明だが、Crawl-delay: に対応するというクローラ (Slurp、msnbot) 向け設定を追加。

 User-agent: Slurp
 Crawl-delay: 20

 User-agent: msnbot
 Crawl-delay: 20

アクセス数としては Googlebot と Slurp がダントツ。 しかし Google は無下にする訳にもいかないしなぁ。

www.naney.org サーバ断続的にダウン

朝 www.naney.org の過去記事を確認しつつ作業をしていたら、9:00 前に急にアクセスできなくなった。 ping も通らない。 9:20 ぐらいに 1度復帰したが、また10:00 前にダウン。

それから何度も落ちては復帰を繰り返すようになってしまっている。 SSH で接続している途中にも突然刺ささるし、傍から見ていても原因が良くわからない。

昨日 WiKicker をアップデートしたから「もしかしてうちが原因?」とちょっと心配もしたりするのだが、無限ループに入ったりメモリを使い尽すようなコードが追加してはいないはずだしなぁ(ローカルでのテストではそのような現象は見られない)。

落ちる直前まで見ていてもそれほど load average が高いわけでもないようだしなぁ。

とまぁ、しばらく様子を見ているうちに NaneyOrgWiki と nDiki が Internal Server Error。 止められた。 正確には SpeedyCGI のフロントエンド speedy コマンドの実行権限を管理者に落とされた。

• (大半はロボットによるものなのだけれども) NaneyOrgWiki と nDiki のどちらか(あるいは両方)に常にアクセスがあってスクリプトが動いている
• top すると他のユーザの CGI プログラムは 'perl' か 'perl 5.00503' と表示されるのに対し、これらは speedy、speedy_backend と表示されるため、管理者の目を引きやすい

ということもあって疑われたと推測。

一応こちらでも SpeedyCGI を使わないで直接 Perl で実行するように変更してみたり、Memcached を起動するのをやめてみたりなど設定を変更してみたりするのだけれど、関係なく落ちる落ちる。

管理者がシステムの設定を変えていないで発生するようになったのなら、ハードウェア障害が起きているんじゃないかと想像してしまうのだが、実際どうなんだろうか。

結局夜 23:00 過ぎだかに落ちたあとは復帰する様子がないので(管理者が落ちたかな?)、今日はあきらめ。

サーバの負荷が高くなったら DiKicker が 503 を返して沈静化を待つようにした

www.naney.org を収容しているサーバの負荷が高い状態。

1. Referer spam 弾きを強化。
2. 1日半前ぐらいに1度リブートしたようで、Memcached が起動していなかったので起動。

という対処をしたけれどそれでもなかなか負荷が落ちつかない。

傾向としては SpeedyCGI のバックエンド側(speedy_backend)が MaxBackends まで起動して処理が追いつかないと、起動しているフロントエンド側 (speedy) がどんどん増えてしまうという状況のようだ。

DiKicker の高速化も順次着手しているのだけれど追いつきそうにもないので、loave average が高い時は頑張らずに無条件に 503 を返すように修正して対応(以前ハイパー日記システムの時にも同じことをした)。

本当は SpeedyCGI フロントエンドの数に応じて負荷の軽い処理に切り換える等工夫したいんだけれど、フロントエンドの数を取得する方法は簡単にはなさそうなんだよなあ。