最近Railsがガンガン出力するproduction.logを解析してどのアクションがリクエスト多いのか、DBがボトルネックになってるアクションはないか、などを調べているんですが、production.logがどんどん肥大化して、解析ツールの開発イテレーションを回す際の効率が悪くなってきました。
また似たようなツールをやたらめったらコピペで作ってきたため、開発効率も悪くなってきたので、ここでAPIを整理しつつ、あわよくばログをなめる部分を高速化できないものかと考えました。
シンプルに正規表現をつかって変化する箇所を切り出していたのですが、これではかなり重いのは自明ですし、がんばって文字列をパースするパーサを作ってもrubyではあまりスピードは出なそう、でもrubyで書きたいし....
ということで、一度パースしたデータを読込みに効率よさそうな形式に変換することで、次以降の解析を高速化しようと考えました。RubyのMarshalモジュールのdump/loadを使うのもよさそうでしたが、個人的にMessagePackというライブラリが気になっていたので、試してみました。特にウリ文句もread時のデシリアライズ性能がよいとのことでしたので、結果的にはマッチする用途だったのかなと思います。
んで今回つくったrails_log.rbというライブラリなのですが、以下のようにして使うことを想定してます。
require "rails_log"
# 普通のログファイルを生で解析
rlog = RailsLog.new("/hogege/log/production.log")
rlog.each do |row|
# rowを使っていろいろ数えたりする
end
# binファイルに変換
rlog = RailsLog.new("...")
rlog.convert_to_bin
# binファイルを変換(はやい)
rlog = RailsLog.new("...")
rlog.bin_each do |row|
# rowを使っていろいろ数えたりする
end
2つのイテレータeachとbin_eachが解析用のメソッドで、ブロック引数(この例ではともにrowとしている)はHashオブジェクトで、以下のようなキーと値を持ってます。
- :controller_action - HogeController#action_nameのような文字列
- :format - "html"とか"json"(レスポンスの出力フォーマット)
- :ip - リクエストしてきたクライアントのIPアドレス(文字列)
- :datetime - リクエストされたアクセス時刻(Timeオブジェクト)
- :http_method - GETとかPOSTとか
- :params - paramsの中身(Hash)
- :time_total - アクション処理にかかった総時間(単位msec, FixNum)
- :time_view - View処理にかかった時間
- :time_db - DB処理にかかった時間
- :http_response - "200 OK"とかそういう文字列
- :request_uri -
"http://mogera.bpsinc.jp/fuga/hoge/?p1=value1&p2=valuevalue22"のような文字列
出力フォーマットがjsonなリクエストと、そうでないリクエストの数を数えるには以下のようにします。
rlog = RailsLog.new("production.log")
c_json, c_other = 0, 0
rlog.each do |row|
if row[:format] == "json" then
c_json += 1
else
c_other += 1
end
end
# 数字をつかってなにかする
ただこれでは遅いというのが、当初の開発動機ですので、MessagePackを応用した形式に変換してから解析してみましょう。
# まず変換(これには多少時間がかかる)
raw_log = RailsLog.new("production.log")
raw_log.convert_to_bin("production.log.bin")
# 解析
bin_log = RailsLog.new("production.log.bin")
c_json, c_other = 0, 0
bin_log.bin_each do |row|
if row[:format] == "json" then
c_json += 1
else
c_other += 1
end
end
# 以降はbin_eachですばやく解析できる
注意
キーのリストにある以外の値は全て葬りさられますので、元のファイルはバイナリファイルを作成しても手元に残しておくことをおすすめします。(ロガーオブジェクトで出力したデバッグメッセージなど)
パフォーマンス
実験環境: Core2Duo E8500, Mem2GB, VM(KVM), Ubuntu Linux 32bit, ruby1.8.7 enterprise
ログファイル: 約1.4GB, 44万5000リクエストのログ
- binファイルに変換: だいたい150秒ぐらいかかりました。変換後のバイナリデータの容量は約185MBになりました。
- eachによる生ログの解析(変換前): eachを全部回すのにだいたい40秒程度
- bin_eachによる変換されたログの解析: bin_eachを全部回すのにだいたい5秒程度 => 8倍程度の高速化
- Java版によるログの解析: (環境が違うので参考まで: MacOSX10.6 CPU C2D 2.66GHz, Mem4GB)約2.3秒 => 15倍以上の高速化
常用していきたいruby版でも8倍ほど早くなりました。
ダウンロード
- rails_log.rb - ログ解析フレームワークとMessagePackを用いたバイナリ形式への変換機能の提供
- rails_log-java.zip - ログ解析フレームワーク(バイナリのみ)の提供
まとまらないまとめ
ログ解析なんてどうせ数日に1回とか、1日1回なので遅くてもいいや、という話もありますが、解析ツールを開発するときに実際のデータで素早く解析できる、eachとbin_eachを入れ替えるだけでアルゴリズムを触らず生のログファイル/変換済みのバイナリ形式ファイルと対応を切り替えることができるので割と気に入ってます。
またJava版も勢いで作ってみたものの、やはりかなり早かったので自己満足してしまいました。
MessagePackプロジェクトの皆さんにも感謝です!
参考リンク
- MessagePack Project - RPC機能も試してみたいですね!
プログラムはご自由にお使い頂いて結構ですので、よければ皆さんもお試しください。