nDiki : SpeedyCGI

[ WiKicker ] SpeedyCGI 化の様子

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

SpeedyCGI と環境変数

アクセスログ用 SSI が使用しているモジュールで REQUEST_URI、 HTTP_REFERER、 HTTP_USER_AGENT 環境変数がうまく取れていなない事があるのを発見。

ログをみると取れている時と、取れていない時がある。 何だろう。 でよくよく調べてみたら、SSI では問題なくて同じモジュールを Wiki で使っている時に失敗している模様。

よくわからないが、SpeedyCGI 関連の問題かもと思い main スクリプト上での呼び出し位置を修正したら直った。 呼び出し順に依存するのかなぁ。

あっ、そういえばモジュールのバグ混入(同環境変数を取得後のエスケープ処理で誤って空にしてしまうバグ)とその修正を今し方したのだが、SpeedyCGI がそのバグのある時点のモジュールをロードして動き続けていただけかも。 で、main スクリプトを修正したら SpeedyCGI がそれを検知して Wiki を re-execute したため今度は修正後のモジュールがロードされたため正しい挙動になったと(main スクリプトの修正内容は関係なく、touch された事自体が問題を解決した)。

多分。

[ www.naney.org ] CGI プログラムによるサーバ過負荷

ホスティングサービス会社からメール。 12月16日0:00-0:20にかけて、naney.org に設置しているCGI プログラムが原因でサーバが過負荷になり動作不安定な状態になったため、実行権限を落としたとのこと。

あちゃ。

メールでは naney.org に設定しているハイパー日記システムのうち一方(この日記でない方)が原因との報告だったが、アクセスログをみるとそちへの最終アクセスは 12/15 18:25:19 でどうも違う感じ。 逆にこちらの hns の方に、61.116.156.147 から 23:42:32 - 00:17:37 の間に少なくとも523回のアクセスがあり、どうやらこちらが過負荷の原因になってしまったようだ。

ここ最近1日に1度から数度、普通のISP経由で連続アクセスがある。 UAはIEをなのっているが、ロボットのようでもある。 なかなか弾きにくい相手である。

できれば連続アクセスだけ拒否するようにしたいのだが、そう簡単でもない。

hns は SpeedyCGI では動くようなコードでもなさそうだし。

とりあえず index.cgi を書き換えて サーバの load average が高くなっている状態では 503 Unavailable を即座に返すように修正。

 BEGIN {
   my $average = `uptime`;
   $average =~ /(\d+(?:\.\d+)?),?\s+(\d+(?:\.\d+)?),?\s+(\d+(?:\.\d+)?)/;
   if ($1 > 50) {
     print "Status: 503 Unavailable\r\n\r\n";
     print "Server is busy, please retry later.";
     exit 0;
   }
 }

を追加。load average が 50 (値は調整)を越えたら 503 になるようにしておいた。

ということで、この日記が 503 だったらきっとサーバがイッパイイッパイということです。

私的10大ニュース2003

今年の大事件、マイブームなど。

[web] WiKicker 公開

オリジナル WikiEngine 「WiKicker」を公開し、 www.naney.org での運用を開始。 機能追加、負荷軽減など定期的にメンテナンスを継続中。 今年も1年 Wiki の年だった。

12月からは WiKicker ベースの日記システム「DiKicker」の開発も開始。

[comp] cool programs

• bogofilter ... spam メールが苦にならなくなった & 楽しくなった。
• SpeedyCGI ... WiKicker の高速化にかなり効果
• Unison ... 双方向同期では rsync より便利。

[net] ADSLトラブル

春の数ヶ月間悩まされ続けた。 一度常時接続に慣れてしまうと、もう戻れない。 結局モデムの故障。 その間「@FreeD」も契約してみたが、ADSL復旧に合わせて解約。

[comp] 適応型ソフトウェア開発

仕事でのソフトウェアプロジェクトでの適用を開始しはじめてみた。

[comp] ThinkPad X31 2672-PHJ

3年ぶりのメインノート PC の買い換え。 Pentium M 1.6GHz + 1GBメモリ。 また3年は頑張ってもらわないと。

[camera] TC-1、GR1s 修理

愛用のTC-1が故障したため修理。 修理費16,300円也。 妻の GR1s も修理。

新規に購入したのは、Ai Nikkor 45mm F2.8P(10月12日)、 F3接眼補助レンズ 、 ドンケ F-2 ぐらい。 あまり散財しなかった。

今年は撮影枚数が伸びず。

近所のミニラボが閉店したのも痛い。

[misc] レザークラフト

昨年買ったままだったレザークラフトセットを使ってレザークラフトを始めた。 パスケース、LEDフラッシュライトケース x 2、ツールナイフケース x 2、露出計ケース などを製作。 最近は何も作ってないな。 また何か作りたい。

[misc] LEDフラッシュライト

LEDフラッシュライトに興味を持つ。 SureFire E1e + KL1 、 ARC-AAA 、 Arc LSL-P などを購入。

設定処理まわりの改良

一度読み込んだ Properties ファイルを pool しておき、再読み込み時に変更されていなければ再利用するように修正。SpeedyCGI を使っている場合に有効...のはずだがあまり速度的には変わってないかも。

[ WiKicker ] ピーク時の様子

先日実装したRecentLogページで、ピーク時*1のアクセスについてチェックしてみた。 特定のページだけに集中している訳ではなくて、その時間においても思ったより他のページにもアクセスがあるな。 1分あたりのリクエスト処理数は最大で約38(直前300リクエスト処理時間での平均)ぐらいだった。 同時アクセス数が増えると1リクエストにかかる処理時間も増えるし、これぐらいが今のサーバ/コードでは限界ということかな(SpeedyCGI で MaxBackends を 30 に設定しているため、これ以上は同時に処理しない)。

[ 日記 ] SpeedyCGI による、同時処理数制御

SpeedyCGI はもともとPerlスクリプト起動時の遅さ(インタプリタ起動 + プログラムのコンパイル)を回避するために、一度起動させたPerlプログラムを使いまわすもの。 Apache管理権限のない一般ユーザでもインストールして利用できるしプログラムに問題があった時の対応も簡単なので、重宝している。

もちろん mod_perl でのコーディングと同様、グローバル変数の扱いなど気をつけなければならない点はある。 ハイパー日記システムも残念ながらそれらを意識しては書かれていないのでSpeedyCGI下では、うまく動かない。

このSpeedyCGIだが同時に生成できるバックエンドプロセスの数(-M オプション)と、各バックエンドプロセス(使いまわされるPerlプログラム)の実行回数(-r オプション)を指定できる。 例えば -M15 ならバックエンドの数を最大15になる。 16個目のアクセスがあるとバックエンドのどれかが空くまで待たされる事になる。 また -r の方は実行しているうちにどんどんメモリ使用量が増えてしまうような行儀の悪いプログラムの時などに使用するもので、例えば -r30 としておくとそのバックエンドは30回呼び出されると終了させられる(そして新しいバックエンドがまた作られる)。

で話は長くなったが例えば '-M15 -r1 -t1' というオプションにすれば、何度も実行できないようなコードのCGI プログラムでも、同時処理数制御用として SpeedyCGI が使えるというわけ(-t はバックエンドのタイムアウト指定)。

この日記もロボットの絨毯爆撃などがあるとサーバに高負荷をかけてしまう事があるので、SpeedyCGI で同時処理数を抑えるようにしてみた。 さて効果はあるかな?

[ Perl ] Devel::Size

WiKicker のメモリ使用量が多くなってきた(10MBを越えることも)。 高速化を第一にそこら中で計算結果をキープするようになっているのだが、その辺整理しる必要があるな。

SpeedyCGIを使って複数回のアクセスで使用され続けるため、メモリリークが起きていないかも要確認。

SpeedyCGI 外す

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

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