概要

ps の表示に各ワーカープロセスが何をやっているか、具体的には以下のような情報を表示するようになっています。

• リクエスト処理数
• 状態 (Read=R, Write=W, Wait=_)
• クライアントIPアドレス
• リクエストメソッド
• リクエストパス
• プロトコル

$ ps | grep server-status
47167  7.8  0.4 S+ 0:00.15 server-status[let] (req=2) R ?       
47164  0.0  0.5 S+ 0:00.35 server-status[let] (req=2) _ 127.0.0.1 local.hatena.ne.jp:5000 GET /debug_toolbar/jquery.js HTTP/1.1       
47163  0.0  0.5 S+ 0:00.34 server-status[let] (req=2) _ 127.0.0.1 local.hatena.ne.jp:5000 GET /favicon.ico HTTP/1.1       
47162  0.0  0.1 S+ 0:00.01 server-status[let] (req=1) _ 127.0.0.1 local.hatena.ne.jp:5000 GET /debug_toolbar/information.gif HTTP/1.1       
47161  0.0  0.1 S+ 0:00.02 server-status[let] (req=1) _ 127.0.0.1 local.hatena.ne.jp:5000 GET /debug_toolbar/jquery.js HTTP/1.1       
47170  0.0  0.1 S+ 0:00.01 server-status[let] (req=1) _ 127.0.0.1 local.hatena.ne.jp:5000 GET /debug_toolbar/toolbar.min.css HTTP/1.1       
47169  0.0  0.3 S+ 0:00.08 server-status[let] (req=1) _ 127.0.0.1 local.hatena.ne.jp:5000 GET /favicon.ico HTTP/1.1       
47168  0.0  0.5 S+ 0:00.28 server-status[let] (req=2) _ 127.0.0.1 local.hatena.ne.jp:5000 GET /debug_toolbar/toolbar.min.css HTTP/1.1       
47166  0.0  0.1 S+ 0:00.04 server-status[let] (req=2) _ 127.0.0.1 local.hatena.ne.jp:5000 GET /debug_toolbar/toolbar.min.js HTTP/1.1       
47165  0.0  0.3 S+ 0:00.07 server-status[let] (req=1) _ 127.0.0.1 local.hatena.ne.jp:5000 GET /favicon.ico HTTP/1.1  

これらの情報により、「なんかバックエンドの調子がおかしい」という場合に、原因究明の指標が増えます。

• ワーカープロセスを全て使いきっているかいないか
  • 使いきっているなら、worker を増やすか、アプリサーバを増やす必要がある
• リクエスト処理数が多いプロセスのメモリ使用量が著しく多くないか
  • リークしている可能性があるので、リークをなおすか max reqs/child を小さくする必要がある
• どこか特定のリクエストで詰まっていないか
  • 地雷リクエストを迅速に発見し対処

などです。アクセスログ解析で解ることもありますが、実際処理しているのがリアルタイムで解るのは多少安心感があります。

Plack::Middleware::ServerStatus

また、mod_status のように http 経由で見れるよう、/server-status を奪ってハンドリングする Middleware も一緒に書きました。これは単に ps の結果をパースして統計をとって出力しているだけです。(ミドルウェアとして実装すべきものなのか微妙な気もしますがこのほうが便利なので)

• /server-status
• /server-status?auto (mod_status のように機械可読なフォーマット)

に表示するようになっています。

http://github.com/cho45/Plack-Middleware-ServerStatus

パフォーマンス

この機能追加でのパフォーマンスの劣化を測定しておきます。ついでに、mod_perl2 も含めた実際のところのベンチもとっておきます。

手元の MacBook 2.4G Core 2 Duo でサーバも ab も動かし、何度か測定して最速の結果を出しています。

とりあえず、最高速がでると思われる Starman (keep-alive) で ab してみます。

ab -c 10 -t 1 -k http://127.0.0.1:5000/

# Starman (master: c1a991a)
perl -Ilib bin/starman --workers 10 ~/project/Plack/eg/dot-psgi/Hello.psgi
Requests per second:    7079.76 [#/sec] (mean)

# Starman (server-status: 7b4430d)
SERVER_STATUS_CLASS=hello starman --workers 10 ~/project/Plack/eg/dot-psgi/Hello.psgi
Requests per second:    6812.11 [#/sec] (mean)

この処理を挟んだことによる多少のパフォーマンス劣化は残念ながら避けられません。(SERVER_STATUS_CLASS を定義しない場合は処理をしないため元のパフォーマンスがでます)

実際使うのは必ず Apache の reverse proxy の裏なので keep-alive をオフにしてみます。(Starman のデフォルトを参考に、1ワーカープロセスあたりのリクエスト数を 1000 にあわせています)

ab -c 10 -t 1 http://127.0.0.1:5000/

# Starman (master: c1a991a)
perl -Ilib bin/starman --workers 10 ~/project/Plack/eg/dot-psgi/Hello.psgi --disable-keepalive
Requests per second:    2889.89 [#/sec] (mean)

# Starman (server-status: 7b4430d)
SERVER_STATUS_CLASS=hello starman --workers 10 ~/project/Plack/eg/dot-psgi/Hello.psgi --disable-keepalive
Requests per second:    2805.02 [#/sec] (mean)

# Starlet (master: c3100dd)
PLACK_ENV=production perl -Ilib =plackup -s Starlet -p 5000 --max-workers=10 ~/project/Plack/eg/dot-psgi/Hello.psgi --max-reqs-per-child 1000
Requests per second:    2645.74 [#/sec] (mean)

# Starlet (server-status: 68608ef)
PLACK_ENV=production SERVER_STATUS_CLASS=let perl -Ilib =plackup -s Starlet -p 5000 --max-workers=10 ~/project/Plack/eg/dot-psgi/Hello.psgi --max-reqs-per-child 1000
Requests per second:    2533.56 [#/sec] (mean)

# mod_perl2 MaxRequestsPerChild=1000 (http://gist.github.com/412767 )
Requests per second:    2975.45 [#/sec] (mean)

このケースだと mod_perl2 > Starman > Starlet になっています。

さらに、1つのワーカプロセスが処理するリクエストの数を減らしてみます。
実際のところ、この値を少なくせざるを得ないケース (=メモリリークしてる) が多々あり、安定性重視のため、128 ぐらいに設定されていたりします。

# Starman (master: c1a991a)
perl -Ilib bin/starman --workers 10 ~/project/Plack/eg/dot-psgi/Hello.psgi --disable-keepalive --max-requests 128
Requests per second:    2320.12 [#/sec] (mean)

# Starman (server-status: 7b4430d)
SERVER_STATUS_CLASS=hello starman --workers 10 ~/project/Plack/eg/dot-psgi/Hello.psgi --disable-keepalive --max-requests 128
Requests per second:    2319.89 [#/sec] (mean)

# Starlet (master: c3100dd)
PLACK_ENV=production perl -Ilib =plackup -s Starlet -p 5000 --max-workers=10 ~/project/Plack/eg/dot-psgi/Hello.psgi --max-reqs-per-child 128
Requests per second:    2309.88 [#/sec] (mean)

# Starlet (server-status: 68608ef)
PLACK_ENV=production SERVER_STATUS_CLASS=let perl -Ilib =plackup -s Starlet -p 5000 --max-workers=10 ~/project/Plack/eg/dot-psgi/Hello.psgi --max-reqs-per-child 128
Requests per second:    2250.82 [#/sec] (mean)

# mod_perl2 MaxRequestsPerChild=128
Requests per second:    898.81 [#/sec] (mean)

このケースだと Starman >= Starlet > mod_perl2 になっています。

mod_perl2 は fork のコストが多大なのか MaxRequestsPerChild を低くすると急激にパフォーマンスが劣化しました。