読者です 読者をやめる 読者になる 読者になる

カイワレの大冒険 Third

技術的なことや他愛もないことをたまに書いてます

アクセスログをスマート解析してくれる「request-log-analyzer」が超絶便利だった件

最近、Ruby率が高くなってきた@masudaKです。

ちょいとアクセスログを眺める機会があったのですが、ワンライナーも限界があるし、なんかいいプラグインでもあるんじゃないかと探したら、良さそうなのがあったので、紹介。

その名も「request-log-analyzer」。Ruby製のログ解析ツールでございます。 プロジェクトページを見ると、Railsのログだけではなく、Apacheのアクセスログや、S3のログ、MySQLのスロークエリログなんかにも対応してるとのこと。

とりあえず、combinedなログを解析したかったので、試しにやってみました。

49.212.129.187 - - [27/May/2013:05:48:01 +0900] "GET /top HTTP/1.1" 200 162 "-" "curl/7.19.7 (x86_64-redhat-linux-gnu) libcurl/7.19.7 NSS/3.13.6.0 zlib/1.2.3 libidn/1.18 libssh2/1.4.2" "-"
49.212.129.187 - - [27/May/2013:05:49:01 +0900] "GET /top HTTP/1.1" 200 162 "-" "curl/7.19.7 (x86_64-redhat-linux-gnu) libcurl/7.19.7 NSS/3.13.6.0 zlib/1.2.3 libidn/1.18 libssh2/1.4.2" "-"

こんなログとか、手元にあるログとか適当に用意してください。

んで、「request-log-analyzer」を入れる。

$ gem install request-log-analyzer --no-ri --no-rdoc

rbenvなりでRubyの環境は作っておいてください。

あとは、以下のように使うだけ。

$ request-log-analyzer default.access.log.sum

(request-log-analyzer --apache-format "%h %l %u %t \"%r\" %>s %b" access.logみたいな使い方もできるみたい)

すると、こんな感じで出力される。

$ time request-log-analyzer default.access.log.sum
Request-log-analyzer, by Willem van Bergen and Bart ten Brinke - version 1.12.9
Website: http://railsdoctors.com

default.access.log.sum:  100% [====================================================================================================================================] Time: 00:00:08

Request summary
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
Processsed File:     /home/masudak/work/parse_accesslog/default.access.log.sum
Parsed lines:        100204
Skipped lines:       0
Parsed requests:     100204
Skipped requests:    0

First request:       2013-05-27 05:48:05
Last request:        2013-05-27 23:31:11
Total time analyzed: 1 days

Request distribution per hour
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
  0:00 ┃    0 hits/day ┃
  1:00 ┃    0 hits/day ┃
  2:00 ┃    0 hits/day ┃
  3:00 ┃    0 hits/day ┃
  4:00 ┃    0 hits/day ┃
  5:00 ┃ 1128 hits/day ┃ ░░
  6:00 ┃ 5640 hits/day ┃ ░░░░░░░░░
  7:00 ┃ 5640 hits/day ┃ ░░░░░░░░░
  8:00 ┃ 5734 hits/day ┃ ░░░░░░░░░
  9:00 ┃ 5640 hits/day ┃ ░░░░░░░░░
 10:00 ┃ 5640 hits/day ┃ ░░░░░░░░░
 11:00 ┃ 5640 hits/day ┃ ░░░░░░░░░
 12:00 ┃ 5640 hits/day ┃ ░░░░░░░░░
 13:00 ┃ 5640 hits/day ┃ ░░░░░░░░░
 14:00 ┃ 5640 hits/day ┃ ░░░░░░░░░
 15:00 ┃ 5640 hits/day ┃ ░░░░░░░░░
 16:00 ┃ 5640 hits/day ┃ ░░░░░░░░░
 17:00 ┃ 5640 hits/day ┃ ░░░░░░░░░
 18:00 ┃ 5640 hits/day ┃ ░░░░░░░░░
 19:00 ┃ 5640 hits/day ┃ ░░░░░░░░░
 20:00 ┃ 5640 hits/day ┃ ░░░░░░░░░
 21:00 ┃ 5640 hits/day ┃ ░░░░░░░░░
 22:00 ┃ 5640 hits/day ┃ ░░░░░░░░░
 23:00 ┃ 3102 hits/day ┃ ░░░░░

HTTP methods
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
GET  ┃ 100110 hits ┃ 99.9% ┃ ░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░
HEAD ┃     94 hits ┃  0.1% ┃

HTTP statuses
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
200 ┃ 100110 hits ┃ 99.9% ┃ ░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░
404 ┃     94 hits ┃  0.1% ┃

Most popular URIs
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
/tekitou                              ┃ 100016 hits ┃ 99.8% ┃ ░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░
http://hogehoge.net/test.php ┃     94 hits ┃  0.1% ┃
/                                      ┃     94 hits ┃  0.1% ┃

User agents
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
curl/7.19.7 (x86_64-redhat-linux-gnu) libcurl/7.19.7 NSS/3.13.6.0 zlib/1.2.3 libidn/1.18 libssh2/1.4.2" "-          ┃ 100016 hits ┃ 99.8% ┃ ░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░
Mozilla/5.0 (Windows; U; Windows NT 6.1; en-US; rv:1.9.2.28) Gecko/20120306 Firefox/3.6.28 (.NET CLR 3.5.30729)" "- ┃     94 hits ┃  0.1% ┃
-" "-                                                                                                               ┃     94 hits ┃  0.1% ┃

Referers
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
None found.

━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
Traffic - by sum                                                                                                ┃   Hits ┃    Sum ┃   Mean ┃ StdDev ┃    Min ┃    Max ┃    95 %tile
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
/tekitou                                                                                                       ┃ 100016 ┃  16 MB ┃  162 B ┃    0 B ┃  162 B ┃  162 B ┃ 161 B-170 B
http://hogehote.net/test.php                                                                          ┃     94 ┃  15 kB ┃  162 B ┃    0 B ┃  162 B ┃  162 B ┃ 161 B-170 B
/                                                                                                               ┃     94 ┃    0 B ┃    0 B ┃    0 B ┃    0 B ┃    0 B ┃     1 B-1 B

━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
Traffic - by mean                                                                                               ┃   Hits ┃    Sum ┃   Mean ┃ StdDev ┃    Min ┃    Max ┃    95 %tile
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
/tekitou                                                                                                       ┃ 100016 ┃  16 MB ┃  162 B ┃    0 B ┃  162 B ┃  162 B ┃ 161 B-170 B
http://hogehoge.net/test.php                                                                          ┃     94 ┃  15 kB ┃  162 B ┃    0 B ┃  162 B ┃  162 B ┃ 161 B-170 B
/                                                                                                               ┃     94 ┃    0 B ┃    0 B ┃    0 B ┃    0 B ┃    0 B ┃     1 B-1 B

Traffic - total: 16 MB

Need an expert to analyze your application?
Mail to contact@railsdoctors.com or visit us at http://railsdoctors.com.
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
Thanks for using request-log-analyzer!

real     0m8.910s
user     0m8.825s
sys     0m0.036s

こんな感じで、トラフィックとか、ステータスコード、リファラーもろもろを綺麗に表示してくれる(このブログのCSSの横幅の限界がきてるので、ローカルで試してみてくださいm(__)m)。

対象のログサイズとか行数はこんな感じ。

$ du -sh default.access.log.sum
19M     default.access.log.sum

$ wc -l default.access.log.sum
100580 default.access.log.sum

標準出力すると、色もついて、今風な感じ。

perlワンライナーで出すのもいいんだけど、どうも限界がある。

$ perl -ne 'if(/(\d\d\:\d\d)/){$c{$1}++}END{for(sort keys %c){print "$_,$c{$_}\n"}}' /usr/local/tomcat/logs/access.log | sort -nr -t ',' -k 2,2 |head
16:34,1091
16:22,489
16:35,394
16:23,220
17:41,22

$ perl -MFile::Basename -lane 'print substr($F[3],1,14) if(((fileparse($F[6],qw(\.[^\.]+$) ))[2]) !~ /.gif|.js|.css/);' /usr/local/apache/logs/access_log | uniq -c
1022 17/May/2013:14
1235 17/May/2013:15
602 17/May/2013:16

ってのを考えると、こういうツールは悪くはないんじゃないかなぁと思ったり。

ちなみに、370MBほどあるアクセスログでやったら、10分かかりました。その上、メモリが少ないサーバでやると、途中でOOM killerに抹殺される可能性があるので、 大きめのログを解析するときは、少しスペックあげることおすすめします。 なので、的確に出したい項目決まってるならワンライナーでいいし、ざっくり概要把握したいなら、こういうのもいいでしょうという感じですな。

是非使ってみてください。