nDiki : SpeedyCGI

root権限、Apache 管理者権限がなくてもインストールが可能な、Perl スクリプト常駐プログラム。 Perl CGI プログラムの高速化に利用できるが、CGI プログラムに限らず通常のスクリプトの高速化にも使うことができる。

nDiki (DiKicker) も SpeedyCGI を使用している。

www.naney.org speedy_backend メモリ キャッシュ Memcached エラー Wiki hns CGI::Carp Makefile.PL バグ 日記 Devel::Size IPC::ShareLite Storable データベース AutoLoader FreeBSD 開発 NaneyOrgWiki Perl モジュール Perl でキャッシュ処理 メール mod_perl IPC::Shareable spam Log::Log4perl::Appender::Synchronized Log::Log4perl アクセスログ メモリリーク

■ SpeedyCGI 外す

一昨日この日記も SpeedyCGI 下で動かすようにしてみたのだが、なんかおかしい。 mod_rewrite しているせい? よくわからんが、違う日付の内容が表示されたりするので元に戻す。

• Apache でミラー proxy (2002-04-17)
• サーバの負荷が高くなったら DiKicker が 503 を返して沈静化を... (2007-04-05)
• [ WiKicker ] SpeedyCGI 対応するも…… (2003-11-09)
• [ WiKicker ] SpeedyCGI 化の様子 (2003-11-10)
• やっぱ hns (2003-11-20)

■ [ 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 とか無いのかな。 自分で書くしかない?

• www.naney.org サーバ断続的にダウン (2006-04-30)
• サーバ高負荷状態につき DiKicker 機能修正とサーバ設定変更 (2006-03-03)
• Windows 上での Apache 2.0.53 では PATH_INF... (2005-04-10)
• [ WiKicker ] SpeedyCGI 対応するも…… (2003-11-09)
• [ WiKicker ] 「最近のアクセスログ」処理思案 (2004-01-17)

■ 過去の今ごろ

過去の6月30日より。

• AutoLoader に手を出す
  • SpeedyCGI を使ってスクリプトを使い回しているので、AutoLoader で徐々にローディングされた方が最初の実行での処理が短くなって良いのではないかと。きちんと評価したわけではないので実際のところは不明。

• サーバの負荷が高くなったら DiKicker が 503 を返して沈静化を... (2007-04-05)
• [ WiKicker ] SpeedyCGI 対応するも…… (2003-11-09)
• [ WiKicker ] SpeedyCGI 化の様子 (2003-11-10)
• [ Perl ] Log::Log4perlのはまりどころ (2004-03-02)
• 設定処理まわりの改良 (2004-01-03)

■ [ WiKicker ] 分あたり100アクセスオーバー

たまにあるテレビ放送後の猛烈アクセス。

RecentLogでチェックしてみたところ、1分あたりの処理数が100を超えていた。 ここ最近は、いっても40台だったから驚き。

レスポンスは悪かったものの load average は極端には上がっていなかった。SpeedyCGI のパラメータの調整がいい感じだったようだ。 ほとんど(編集ではなく)閲覧のみのアクセスだったことで、Memcached によるキャッシュもかなり有効に働いていたと思われる。

• www.naney.org サーバ断続的にダウン (2006-04-30)
• [ WiKicker ] WikiPage のHTMLレンダリング結果のキ... (2004-02-14)
• [ WiKicker ] Memcachedのメモリ使用量 (2004-02-15)
• 私的10大ニュース2004 [ web ] (2004-12-31)
• Cache::Memcached 1.13 の Perl 5.005_03 対応 (2004-06-05)

■ 過去の今ごろ

過去の10月16日より。

• Sys::CpuLoad
  • SpeedyCGI 下だったら使った方が平均的には速いかも。

• サーバの負荷が高くなったら DiKicker が 503 を返して沈静化を... (2007-04-05)
• [ WiKicker ] SpeedyCGI 対応するも…… (2003-11-09)
• [ WiKicker ] SpeedyCGI 化の様子 (2003-11-10)
• [ Perl ] Log::Log4perlのはまりどころ (2004-03-02)
• 過去の今ごろ (2004-06-30)

■ サーバ高負荷状態につき 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 は無下にする訳にもいかないしなぁ。

• [ Perl ] Log::Log4perlのはまりどころ (2004-03-02)
• さらにサーバ負荷状態悪化。対応に追われる。 (2006-03-04)
• Rubric でプライベート SBS を立てるも 0.140 では日本語に不具合 (2006-07-22)
• www.naney.org サーバ断続的にダウン (2006-04-30)
• [ WiKicker ] SpeedyCGI 対応するも…… (2003-11-09)

■ 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 過ぎだかに落ちたあとは復帰する様子がないので(管理者が落ちたかな?)、今日はあきらめ。

• [ Perl ] Log::Log4perlのはまりどころ (2004-03-02)
• [ WiKicker ] 「最近のアクセスログ」処理思案 (2004-01-17)
• サーバ高負荷状態につき DiKicker 機能修正とサーバ設定変更 (2006-03-03)
• [ WiKicker ] SpeedyCGI 対応するも…… (2003-11-09)
• [ www.naney.org ] サーバ重い (2004-01-20)

■ SpeedyCGI 以下で WiKicker がうまく動かない?

WiKicker ベースのシステムが稼働しているホストが FreeBSD 5.2.1-RELEASE から FreeBSD 6.1-RELEASE に更新されるのにともない、再インストール作業を行った。

動作確認をしたところ CGI プログラムは動くものの Perl モジュール中の DATA セクションが読めていないようなエラー表示がされた。

もしやと思い SpeedyCGI を外したら正常動作。

SpeedyCGI 下で動くことを考えて、DATA セクションを1度しか読まないようにコーディングしてあるはずなのだが、はて。

他の作業もあり細かいチェックができなかったのでもしかしたら違うところでの問題かもしれないが、ちょっと厄介。

• [ WiKicker ] SpeedyCGI 対応するも…… (2003-11-09)
• [ WiKicker ] SpeedyCGI (2003-10-17)
• CGI プログラム、Out of memory! に泣く (2001-01-04)
• [ Perl ] Log::Log4perlのはまりどころ (2004-03-02)
• Windows 上での Apache 2.0.53 では PATH_INF... (2005-04-10)

■ 自動リンク機能改善による悪影響

www.naney.org がどうもまた最近重い。

load average が 30 前後まで上がっている。 しばらくするとだんだん落ちついてくるのだが、3 以下になったところでまた 30 前後までまた一気に上がるというのを繰り返している。 load average で振る舞いを変えるのは WiKicker / DiKicker の特徴なので、これはうちが原因かも。

調べてみると SpeedyCGI のフロントエンドのプロセスが順番待ちで大量に起動している。

どうやら先日追加した自動リンクの機能改善にかかわるコード修正による、若干の処理速度の低下がまずいようだ。

速度が上がるようにちょっと修正してみたけれどまだ駄目なようなので、しかたなく単語の連接チェック部分を一時コメントアウトして対応。

今後、自動リンクまわりの更なる高速化がする必要がありそう。

• DiKicker に grep 検索機能を追加 (2007-02-02)
• [ Perl ] Log::Log4perlのはまりどころ (2004-03-02)
• DiKicker の出力する HTML コードを小さく (2006-10-05)
• [ WiKicker ] SpeedyCGI 対応するも…… (2003-11-09)
• サーバ高負荷状態につき DiKicker 機能修正とサーバ設定変更 (2006-03-03)

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

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

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

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

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

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

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

• [ DiKicker ] ロック獲得リトライをさらに減らす (2007-03-14)
• サーバ高負荷状態につき DiKicker 機能修正とサーバ設定変更 (2006-03-03)
• [ Perl ] Log::Log4perlのはまりどころ (2004-03-02)
• www.naney.org サーバ断続的にダウン (2006-04-30)
• 私的10大ニュース2004 [ web ] (2004-12-31)