Ruby on Rails ログ解析　〜request-log-analyzer〜

この記事はアピリッツの技術ブログ「DoRuby」から移行した記事です。情報が古い可能性がありますのでご注意ください。

rick No31です。
今回は、railsログを解析するgemの紹介です

環境

request-log-analyzer 1.12.10
ruby 1.9.3p484
rails 3.0.19

Install方法

$ gem install request-log-analyzer

実行方法

$ request-log-analyzer –format rails3 log/development.log.20131212

オプション

// 解析するコントローラーを指定
–select controller TopController
// 解析するアクションを指定
–select action index
// 特定コントローラーを除外
–reject controller TopController
// html出力
–output HTML –file hoge.html

分析結果

※横棒は長いため比率関係なく短くしています
// リクエストのサマリー
Request summary
ーーーーーーーーーーー
// 解析したファイル
Processsed File: xx/log/development.log.20131212
// 解析した行数
Parsed lines: 1103450
// スキップした行数
Skipped lines: 55814
// 解析したリクエスト
Parsed requests: 276218
// スキップしたリクエスト
Skipped requests: 0
// 警告数
Warnings: no_current_request: 55814, teaser_check_failed: 73, unfinished_request_on_eof: 1
// 最初のリクエスト日時
First request: 2013-12-12 00:00:12
// 最後のリクエスト日時
Last request: 2013-12-12 23:59:11
// 解析した期間
Total time analyzed: 1 days
ーーーーーーーーーーー

// 時間あたりのリクエスト数
Request distribution per hour
0:00 ┃ 16532 hits/day ┃ ░░░░░░░░░░░░░░
1:00 ┃ 10732 hits/day ┃ ░░░░░░░░░
2:00 ┃ 6915 hits/day ┃ ░░░░░░
3:00 ┃ 4140 hits/day ┃ ░░░░
4:00 ┃ 2641 hits/day ┃ ░░
5:00 ┃ 1882 hits/day ┃ ░░
6:00 ┃ 3322 hits/day ┃ ░░░
7:00 ┃ 3991 hits/day ┃ ░░░
8:00 ┃ 6072 hits/day ┃ ░░░░░
9:00 ┃ 8218 hits/day ┃ ░░░░░░░
10:00 ┃ 8585 hits/day ┃ ░░░░░░░
11:00 ┃ 9568 hits/day ┃ ░░░░░░░░
12:00 ┃ 11037 hits/day ┃ ░░░░░░░░░░
13:00 ┃ 10558 hits/day ┃ ░░░░░░░░░
14:00 ┃ 10930 hits/day ┃ ░░░░░░░░░
15:00 ┃ 10990 hits/day ┃ ░░░░░░░░░░
16:00 ┃ 10870 hits/day ┃ ░░░░░░░░░
17:00 ┃ 18972 hits/day ┃ ░░░░░░░░░░░░░░░░
18:00 ┃ 17312 hits/day ┃ ░░░░░░░░░░░░░░░
19:00 ┃ 16320 hits/day ┃ ░░░░░░░░░░░░░░
20:00 ┃ 19573 hits/day ┃ ░░░░░░░░░░░░░░░░░
21:00 ┃ 23065 hits/day ┃ ░░░░░░░░░░░░░░░░░░░░
22:00 ┃ 22965 hits/day ┃ ░░░░░░░░░░░░░░░░░░░░
23:00 ┃ 21028 hits/day ┃ ░░░░░░░░░░░░░░░░░░

// リクエストの多い順
Most requested
xxController#index.XML ┃ 213045 hits ┃ 77.1% ┃ ░░░░░░░░░░░░░░░░░░
xxController#index.JSON ┃ 24953 hits ┃ 9.0% ┃ ░░░░░░░░░░░░░░░░░
#. ┃ 3120 hits ┃ 1.1% ┃ ░░

//HTTPメソッド毎のリクエスト数
HTTP methods
POST ┃ 193989 hits ┃ 70.2% ┃ ░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░
GET ┃ 82221 hits ┃ 29.8% ┃ ░░░░░░░░░░░░░░░░░░░
HEAD ┃ 8 hits ┃ 0.0% ┃

// HTTPのステータス毎のリクエスト数
HTTP statuses returned
200 ┃ 225536 hits ┃ 100.0% ┃ ░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░
302 ┃ 2 hits ┃ 0.0% ┃
500 ┃ 1 hits ┃ 0.0% ┃

// リクエストの所要時間の合計
Request duration – by sum┃ Hits ┃ Sum ┃ Mean ┃ StdDev ┃ Min ┃ Max ┃ 95 %tile
xxController#index.XML┃ 171190 ┃ 4h21m19s ┃ 0.09s ┃ 0.05s ┃ 0.00s ┃ 5.73s ┃ 0.05s-0.23s
xxController#index.JSON┃ 9626 ┃ 27m38s ┃ 0.17s ┃ 0.09s ┃ 0.00s ┃ 0.79s ┃ 0.05s-0.36s
#.┃ 2518 ┃ 4m15s ┃ 0.10s ┃ 0.07s ┃ 0.00s ┃ 1.00s ┃ 0.01s-0.32s

// リクエストの所要時間の平均
Request duration – by mean┃ Hits ┃ Sum ┃ Mean ┃ StdDev ┃ Min ┃ Max ┃ 95 %tile
xxController#index.JSON┃ 9626 ┃ 27m38s ┃ 0.17s ┃ 0.09s ┃ 0.00s ┃ 0.79s ┃ 0.05s-0.36s
xxController#index.HTML┃ 1 ┃ 0.13s ┃ 0.13s ┃ 0.00s ┃ 0.13s ┃ 0.13s ┃ 0.13s-0.13s
#.┃ 2518 ┃ 4m15s ┃ 0.10s ┃ 0.07s ┃ 0.00s ┃ 1.00s ┃ 0.01s-0.32s

// 一部のレンダリング時間の合計
Partials rendering time – by sum┃ Hits ┃ Sum ┃ Mean ┃ StdDev ┃ Min ┃ Max ┃ 95 %tile
layouts/_hoge.html.erb┃ 14 ┃ 0.41s ┃ 0.03s ┃ 0.05s ┃ 0.00s ┃ 0.17s ┃ 0.00s-0.17s

// 一部のレンダリング時間の平均
Partials rendering time – by mean┃ Hits ┃ Sum ┃ Mean ┃ StdDev ┃ Min ┃ Max ┃ 95 %tile
layouts/_hoge.html.erb┃ 14 ┃ 0.41s ┃ 0.03s ┃ 0.05s ┃ 0.00s ┃ 0.17s ┃ 0.00s-0.17s

// ビューのレンダリング時間の合計
View rendering time – by sum┃ Hits ┃ Sum ┃ Mean ┃ StdDev ┃ Min ┃ Max ┃ 95 %tile
xxController#index.XML┃ 170223 ┃ 1m03s ┃ 0.00s ┃ 0.00s ┃ 0.00s ┃ 0.13s ┃ 0.00s-0.00s
xxController#suggest.JSON┃ 23254 ┃ 7.93s ┃ 0.00s ┃ 0.00s ┃ 0.00s ┃ 0.06s ┃ 0.00s-0.00s
#.┃ 2503 ┃ 0.99s ┃ 0.00s ┃ 0.00s ┃ 0.00s ┃ 0.00s ┃ 0.00s-0.00s

// ビューのレンダリング時間の平均
View rendering time – by mean┃ Hits ┃ Sum ┃ Mean ┃ StdDev ┃ Min ┃ Max ┃ 95 %tile
xxController#index.HTML┃ 1 ┃ 0.09s ┃ 0.09s ┃ 0.00s ┃ 0.09s ┃ 0.09s ┃ 0.09s-0.09s
#.┃ 2503 ┃ 0.99s ┃ 0.00s ┃ 0.00s ┃ 0.00s ┃ 0.00s ┃ 0.00s-0.00s

// DBからの応答時間の合計
Database time – by sum┃ Hits ┃ Sum ┃ Mean ┃ StdDev ┃ Min ┃ Max ┃ 95 %tile
xxController#index.XML┃ 170223 ┃ 14m39s ┃ 0.01s ┃ 0.01s ┃ 0.00s ┃ 0.83s ┃ 0.00s-0.01s
xxController#index.JSON┃ 15672 ┃ 3m34s ┃ 0.01s ┃ 0.04s ┃ 0.00s ┃ 0.49s ┃ 0.00s-0.14s
#.┃ 2503 ┃ 14.58s ┃ 0.01s ┃ 0.01s ┃ 0.00s ┃ 0.30s ┃ 0.00s-0.01s

// DBからの応答時間の平均
Database time – by mean┃ Hits ┃ Sum ┃ Mean ┃ StdDev ┃ Min ┃ Max ┃ 95 %tile
xxController#index.HTML┃ 1 ┃ 0.04s ┃ 0.04s ┃ 0.00s ┃ 0.04s ┃ 0.04s ┃ 0.04s-0.04s
xxController#index.JSON┃ 15672 ┃ 3m34s ┃ 0.01s ┃ 0.04s ┃ 0.00s ┃ 0.49s ┃ 0.00s-0.14s
#.┃ 2503 ┃ 14.58s ┃ 0.01s ┃ 0.01s ┃ 0.00s ┃ 0.30s ┃ 0.00s-0.01s

// 停止したプロセス
Process blockers (> 1 sec duration)
xxController#index.XML ┃ 2 hits ┃ 66.7% ┃ ░░░░░░░░░░░░░░░░░░░░░░░░░
#. ┃ 1 hits ┃ 33.3% ┃ ░░░░░░░░░░░░░░

// 遷移エラー
Routing Errors