Apacheログパーサを書いた
ApacheのログをparseしたいがCPANを見てみるとなんかぴったりなのがない。"Apache Log" で検索した限り、LoggerはいっぱいあるんだけどParserがビミョー。なぜ。見付かったのは以下ふたつのみ。
- Apache::ParseLog - search.cpan.org
- ファイルを全部読み込んで集計までやってくれるらしい、が、そんなのいらない
- そもそもログ行に対して動作するというよりApacheの設定ごと処理するようなもので、モジュールというか解析プログラムの様相
- ApacheLog::Parser - search.cpan.org
- combined 形式のみにマッチする
- 独自書式どころか common とか %D つきとかでも失敗するのが悲しい
- 特に高速ということもない
- Parse::AccessLogEntry - search.cpan.org
- (そういえば試してたので追記 2/9 17:37)
- これもcombinedのみの対応、特に速くない(というか遅い)
最初はログをタブ区切りにしてsplitだけで処理しようかと思ってたんだけど、どっちにしろ通常のcombined形式などのログが混入するのは絶対に避けられないからその対応は必須。あと Apacheのログをタブ区切りにするのは本当にお得か - tagomorisのメモ置き場 に書いたとおり、そこまで高速なわけでもないし。
ということで、書いた。
tagomoris/Apache-Log-Parser · GitHub
PODはざっと書いてあるので、興味のある人はそちらを参照してくださいな。
モジュール名が Apache::Log::Parser としてあるけど、ビミョー。Apache::Log はmod_perl用にロギングのモジュールとして既にCPANに存在するし Apache 以下の名前空間は全体的にmod_perl用に使われてるようだ。
なんだろうな。ApacheLog::XParser とかにしときゃいいのかな。CPANのネーミングのノリはよくわかりません。
機能
以下の機能が欲しくて書いた。
カスタマイズされた書式も処理できること
ユニークユーザを判別するのに mod_usertrack を使ったり、ケータイの端末IDを処理したりしたいので、combinedじゃなくていくつか情報を追加したログを処理させたい。ということで、ログ書式を適当に指定できるようにした。
あ、タブ区切りのログもちゃんと処理できるよ。
複数の書式のログが混在しても正常に動作すること
1台だけログ設定がきちんと行われていないサーバがあったりしたときに完全に無視されるようだとちょっと使えない。
優先順序つきで複数の書式を指定しておけば、順番に試してマッチした書式でparseして結果を返すようにした。実用上 common のログを解析に回して意味があるかというと微妙だけど、まあPVくらいは欲しいよね。
あとデバッグ用に combined に %D (処理に要した時間) だけ追加しておくとかもよくやると思う。末尾に知らない情報が書かれている場合は華麗にスルーするようにしてある。
ダブルクォーテーションの処理
ざっと正規表現を書いただけだと、バックトラックしないものはログ内の文字列にダブルクォーテーションが含まれているときにうまく処理できない(はず)。
なのでそれをきちんと処理できるものが欲しい。できるだけマトモな速度で。
ということで実装してみた(strictモード)が、やっぱりちょっと遅い。ので、ダブルクォートが無いものとしてparseするモード(fastモード)も作った。fastモードはログ行の先頭部分は common と同形式だっていう前提も置いていて、strictに較べると多少高速に動作する。fastモードでparseに失敗したらstrictモードで試すようにすれば実用上はいいんじゃないかな。*1
あと、ダブルクォートでくくられた値は勝手にくくっているダブルクォーテーションを外すようにしてる。可読性のためにつけてるだけで、処理するときにはいらないし。
速度
あんまり悲惨な速度で動かれても困るので、簡単にベンチマークをとった。スクリプトはリポジトリの ex/benchmark.pl に置いてある。
まず普通に common の処理結果。commonにのみマッチする正規表現 (common_regex) との比較。
Apache-Log-Parser tagomoris$ perl -Ilib ex/benchmark.pl
Benchmark: running common_fast, common_regex, common_strict, custom_fast, custom_strict, default_fast, default_strict for at least 3 CPU seconds...
common_fast: 3 wallclock secs ( 3.14 usr + 0.00 sys = 3.14 CPU) @ 36769.75/s (n=115457)
common_regex: 4 wallclock secs ( 3.13 usr + 0.00 sys = 3.13 CPU) @ 98366.77/s (n=307888)
common_strict: 3 wallclock secs ( 3.13 usr + 0.01 sys = 3.14 CPU) @ 20223.57/s (n=63502)
custom_fast: 3 wallclock secs ( 3.16 usr + 0.00 sys = 3.16 CPU) @ 29977.53/s (n=94729)
custom_strict: 3 wallclock secs ( 3.27 usr + 0.00 sys = 3.27 CPU) @ 6472.17/s (n=21164)
default_fast: 3 wallclock secs ( 3.18 usr + 0.01 sys = 3.19 CPU) @ 33178.37/s (n=105839)
default_strict: 3 wallclock secs ( 3.19 usr + 0.00 sys = 3.19 CPU) @ 9951.72/s (n=31746)
Rate custom_strict default_strict common_strict custom_fast default_fast common_fast common_regex
custom_strict 6472/s -- -35% -68% -78% -80% -82% -93%
default_strict 9952/s 54% -- -51% -67% -70% -73% -90%
common_strict 20224/s 212% 103% -- -33% -39% -45% -79%
custom_fast 29978/s 363% 201% 48% -- -10% -18% -70%
default_fast 33178/s 413% 233% 64% 11% -- -10% -66%
common_fast 36770/s 468% 269% 82% 23% 11% -- -63%
common_regex 98367/s 1420% 888% 386% 228% 196% 168% --common_regex に対して common_fast (commonにのみマッチするよう指定したfastモードのパーサ) が -63% で default_fast (common/combinedにマッチする) が -66% というのは、まあそんなに悪くない、かな？ という感じ。strict が遅いのは諦めましょう。
続けて combined での比較で、対象は正規表現イッパツ (combined_regex) と ApacheLog::Parser (apachelog_parser)。ちなみにApacheLog::Parserは処理の中心そのものはcombinedのみにマッチする正規表現がひとつだけ書かれてる。
Benchmark: running apachelog_parser, combined_regex, custom_fast, custom_strict, default_fast, default_strict for at least 3 CPU seconds...
apachelog_parser: 3 wallclock secs ( 3.21 usr + 0.00 sys = 3.21 CPU) @ 26375.70/s (n=84666)
combined_regex: 4 wallclock secs ( 3.09 usr + 0.01 sys = 3.10 CPU) @ 77118.06/s (n=239066)
custom_fast: 4 wallclock secs ( 3.22 usr + 0.00 sys = 3.22 CPU) @ 28170.81/s (n=90710)
custom_strict: 3 wallclock secs ( 3.18 usr + 0.00 sys = 3.18 CPU) @ 6453.46/s (n=20522)
default_fast: 3 wallclock secs ( 3.23 usr + 0.00 sys = 3.23 CPU) @ 31774.61/s (n=102632)
default_strict: 3 wallclock secs ( 3.15 usr + 0.00 sys = 3.15 CPU) @ 13030.16/s (n=41045)
Rate custom_strict default_strict apachelog_parser custom_fast default_fast combined_regex
custom_strict 6453/s -- -50% -76% -77% -80% -92%
default_strict 13030/s 102% -- -51% -54% -59% -83%
apachelog_parser 26376/s 309% 102% -- -6% -17% -66%
custom_fast 28171/s 337% 116% 7% -- -11% -63%
default_fast 31775/s 392% 144% 20% 13% -- -59%
combined_regex 77118/s 1095% 492% 192% 174% 143% --正規表現との比較については、commonのときとあまり変わらず。apachelog_parserに(わずかだが)勝ってるのでまあいいかなーという感じか。
続けて最後に、カスタムログ書式として combined + %v + mod_usertrack cookie + %D というもので比較。比較対象の正規表現は2種類で custom_regex はこのログ書式にのみマッチするもので custom_regex2 はこのカスタムログ書式とcombinedの両方にマッチするもの。
Benchmark: running custom_fast, custom_regex, custom_regex2, custom_strict for at least 3 CPU seconds...
custom_fast: 3 wallclock secs ( 3.24 usr + 0.00 sys = 3.24 CPU) @ 25287.04/s (n=81930)
custom_regex: 3 wallclock secs ( 3.17 usr + 0.00 sys = 3.17 CPU) @ 59079.50/s (n=187282)
custom_regex2: 4 wallclock secs ( 3.24 usr + 0.00 sys = 3.24 CPU) @ 48999.69/s (n=158759)
custom_strict: 3 wallclock secs ( 3.24 usr + 0.00 sys = 3.24 CPU) @ 10647.22/s (n=34497)
Rate custom_strict custom_fast custom_regex2 custom_regex
custom_strict 10647/s -- -58% -78% -82%
custom_fast 25287/s 137% -- -48% -57%
custom_regex2 49000/s 360% 94% -- -17%
custom_regex 59079/s 455% 134% 21% --
Apache-Log-Parser tagomoris$ ログの行が長くなり複雑性が増すにつれて差が縮まってはいる。
とはいえ正規表現一発の方が速いのは確か、というより追加の処理があれこれある(hashrefへの変換とか！)ので遅いのは当たり前なんだけど。
まあ桁が違うというほどの差でもないから、いいかなーという感じかな。
さて
CPANに上げるべきか、と思ったが名前をどうしようか悩んでる。どーしようかな。
(2/14追記)
Apacheが出力するログのなかに、値が無い場合に "-" ではなく "" として出力する場合が(ごく稀に)あるのを発見した。このパターンだとうまく動作しなかったので修正。
……したら、20%くらい遅くなって apachelog_parser を2%下回るようになってしまった。カスタムフィールドの処理があるのでどっちにしろ ApacheLog::Parser が使えるわけじゃないんだが、なんか悲しい。
*1:というか、それをデフォルトの動作にするか？ でもフィルードの指定をどうやらせるかが面倒だな……。
