mod_request_dumperでApacheのrequest_recをMongoDBに入れてみた

昨日、思いつきで作ったmod_request_dumperですが、使い道を探るべく、Apache内部のrequest_rec構造体のデータをMongoDBに入れてみようと思いました。

MongoDBへの突っ込み方は簡単

まずは、mod_request_dumperに関してですが、一昨日に実装していた時は任意のファイルにしかrequest_recのデータを書き出せなかったのですが、昨日CustomLogのようにパイプで渡せるように実装を追加しました。その結果、ファイルに書きだしたファイルを新たに取り出さなくても、直接パイプでデータをリアルタイムで連携できるようになりました。

そこで早速、JSONならではの使い道として、MongoDBにデータを突っ込んでみました。MongoDBのインストールの方法は沢山あるので、今回の記事では省きます。MongoDBをyumでインストールして起動しました。

/etc/init.d/mongod start

その後、以下のようにmod_request_dumperの設定をhttp.confにしました。

LoadModule request_dumper_module /usr/lib/httpd/modules/mod_request_dumper.so
DumpRequestLog "| mongoimport -d apache -c request_rec"
Dumplogtransaction On

この設定によって、ap_hook_log_transaction（コンテンツの処理が終わってアクセスログを書き出すフェイズ）において、Apache内部で処理されているrequest_rec構造体のデータを、MongoDBのapacheデータベースのrequest_recコレクションに、JSONデータとしてどんどんimportされていきます。

この設定で、Apacheを起動すると、以下のようなプロセスの状態となります。

  root 11347 0.0 0.0 17720 5792  ? Ss 20:00 0:00 /usr/sbin/httpd
  root 11349 0.0 0.1 41800 11564 ? S 20:00 0:00 \_ mongoimport -d apache -c request_rec
apache 11350 0.0 0.0 17984 3940  ? S 20:00 0:00 \_ /usr/sbin/httpd
apache 11351 0.0 0.0 18248 4252  ? S 20:00 0:00 \_ /usr/sbin/httpd
apache 11352 0.0 0.0 17984 3972  ? S 20:00 0:00 \_ /usr/sbin/httpd
apache 12895 0.0 0.0 17720 3064  ? S 20:09 0:00 \_ /usr/sbin/httpd

では、実際に色々アクセスしてみて、MongoDBにデータがimportされていってるかを確認してみましょう。

MongoDB上でrequest_recのデータを見る

まずはMongoDBに入ります。

$ mongo

MongoDB shell version: 2.0.5
connecting to: test
>

データベースの確認をしてみましょう。

> show dbs
apache 0.0625GB
local (empty)
>

では、request_recを突っ込んでいるDBにスイッチします。

> use apache
switched to db apache
>

例えば、一つ目のrequest_recの情報を表示させてみましょう。すると、以下のようになります。

> db.request_rec.findOne()
{
        "_id" : ObjectId("4fbb722f188be4a76059608b"),
        "filename" : "/var/www/html/index.html",
        "uri" : "/index.html",
        "user" : "null",
        "content_type" : "text/html",
        "protocol" : "HTTP/1.0",
        "vlist_validator" : "null",
        "ap_auth_type" : "null",
        "unparsed_uri" : "/",
        "canonical_filename" : "/var/www/html/index.html",
        "path_info" : "null",
        "hostname" : "example.com",
        "method" : "GET",
        "the_request" : "GET / HTTP/1.0",
        "range" : "null",
        "handler" : "null",
        "args" : "null",
        "status_line" : "200 OK",
        "content_encoding" : "null",
        "assbackwards" : 0,
        "proxyreq" : 0,
        "header_only" : 0,
        "proto_num" : 1000,
        "status" : 200,
        "method_number" : 0,
        "chunked" : 0,
        "read_body" : 0,
        "read_chunked" : 0,
        "no_cache" : 0,
        "no_local_copy" : 0,
        "used_path_info" : 2,
        "eos_sent" : 1,
        "request_time" : -217390477,
        "connection" : {
                "remote_ip" : "192.168.0.11",
                "remote_host" : "null",
                "remote_logname" : "null",
                "local_ip" : "192.168.10.112",
                "local_host" : "null",
                "keepalives" : 0,
                "data_in_input_filters" : 0
        },
        "server" : {
                "error_fname" : "logs/error_log",
                "defn_name" : "null",
                "server_scheme" : "null",
                "server_admin" : "root@localhost",
                "path" : "null",
                "server_hostname" : "example.com",
                "loglevel" : 4,
                "is_virtual" : 0,
                "keep_alive_max" : 100,
                "keep_alive" : 0,
                "pathlen" : 0,
                "limit_req_line" : 8190,
                "limit_req_fieldsize" : 8190,
                "limit_req_fields" : 100,
                "process" : {
                        "short_name" : "httpd",
                        "argc" : 1
                }
        },
        "time" : "Tue May 22 20:02:06 2012",
        "pid" : 11350,
        "hook" : "ap_hook_log_transaction"
}
>

きちんとデータがimportされていますね。例えば、現在の総アクセス数（dumpの箇所が一か所の場合）は以下のように調べられます。

> db.request_rec.find().count()
1101

また、ステータスコード200を返している数は、以下のように調べます。

> db.request_rec.find({status:200}).count()
63

ステータスコードの割合やある条件下（特定のファイルやユーザ）での割合も簡単に導出できそうです。さらに、/var/www/html/index.hmlというファイルへのアクセス数は以下になります。

> db.request_rec.find({filename:"/var/www/html/index.html"}).count()
52

アクセスログからだと、rewriteされていた場合等、実際にアクセスしているファイルが何なのかは調べにくいですが、request_recを見てやれば一発ですね。とあるファイルに対するアクセスで500を返していた数も以下のように簡単にカウントできます。

> db.request_rec.find({status:500,filename:"/var/www/html/index.html"}).count()
114

アクセス先のホスト名も、例えばVirtualHostで複数運用していた場合も全体の内、特定のホスト名にどれだけアクセスしているのかも簡単に分かりますね。

> db.request_rec.find().count()
1101

> db.request_rec.find({hostname:"example.com"}).count()
212
>

パフォーマンス劣化

非常に軽い静的ファイル（例えばit worksと表示するindex.html等）へのアクセスに対して、mod_request_dumper＋MongoDBを組み込んだ時とそうでない時を比較するのが、性能劣化の最大値を取得するってとり早い方法です。そこで実際に試してみた所、約1/3から1/4程度にスループットが低下していました。

これは一見悪い結果のように見えるのですが、非常に軽い静的ファイルで1/4くらいであれば、経験上、その他の動的コンテンツやそれなりの大きさの静的コンテンツではそこまでボトルネックにならない値だと考えています。性能劣化としては、1リクエスト毎にスレッドの生成破棄を行う程度の劣化率だと思われます。詳しくは、mod_process_securityの検証結果を見て頂けると良いかと思います。

色々とApacheの解析ができそう

今回はあくまで、MongoDBに突っ込む事が目的でそれをどう扱うかはまだ考えられていないので、これぐらいにしておこうと思います。

request_rec内には、アクセスログではとらえられないような様々なデータが格納されていますので、リクエストが来た時、コンテンツを処理する時、レスポンスを返す時、などの各種フックフェイズでrequest_recをDumpすれば、それらを駆使してより深い解析やパラメータ単位での比率を導出しグラフ化・トレースができそうです。

動的コンテンツの場合は、args内に引数の情報が格納されていたり、様々な構造体のデータが格納されてますので、細やかな解析ができそうです。まだまだ、request_recのデータで対応していないメンバの値は沢山ありますので、これから随時追加していきたいと思っています。

これは結構楽しいかもしれません。アクセスログ解析ではできないような事をやれるのではないかと考えています。