Starman や Starlet で Apache の mod_status 相当の情報を得られるようにする
最近リリースされた Hatena::Let (ラボ) や、1年ぐらい前にリリースしたはてなコピィ (ラボ) は PSGI を喋るように対応した Ridge (はてな社内フレームワーク) を使っています。 (過程で Plack を利用させてもらっています)。今のところは現状それぞれ、let は Starman, copie は mod_perl2 で動いています (copie も mod_perl2 でなくす予定です)。
他のサービスに導入してみて実際のところどれほど嬉しいことがあるのか未知数なため、とりあえずやってみて測定してみる方針にしました (PSGI を喋れるようにしておかないと、そもそも選択肢がないので)。が、実際 production 環境に投入してみようとすると Apache の mod_status 相当の情報を得られることが運用上必須であるとのことだったので、PSGI 実装の Starman, Starlet においてその機能を実現する方法を考えて実装してみました。
本家に取り込める類のものなのかなんとも言えないので、fork してあります。
- http://github.com/cho45/Starman/tree/server-status
- http://github.com/cho45/Starlet/tree/server-status
概要
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 のように機械可読なフォーマット)
に表示するようになっています。
パフォーマンス
この機能追加でのパフォーマンスの劣化を測定しておきます。ついでに、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 を低くすると急激にパフォーマンスが劣化しました。