request-log-analyzerでRailsのログを解析する

wvanbergen/request-log-analyzer
がなかなか使えそうなので、ご紹介。

how to install

gem i request-log-analyzer

how to use

ログ食わせるだけ。

$ request-log-analyzer log/development.log


遅い処理を特定するのにはいい感じ。
・Request duration - by mean
・View rendering time - by mean
・Database time - by mean

Request-log-analyzer, by Willem van Bergen and Bart ten Brinke - version 1.12.1
Website: http://railsdoctors.com

development.log:         100% [==============================================================================] Time: 00:00:00


Request summary
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
Parsed lines:        1189                  
Skipped lines:       12                    
Parsed requests:     821                   
Skipped requests:    0                     
Warnings:            no_current_request: 12

First request:       2011-09-25 13:14:01
Last request:        2012-02-20 21:46:09
Total time analyzed: 149 days           


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


Most requested
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
#.                                   ┃ 697 hits ┃ 84.9% ┃ ░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░
ProjectsController#list.JS           ┃  49 hits ┃  6.0% ┃ ░░░░
ProjectsController#index.HTML        ┃  31 hits ┃  3.8% ┃ ░░░
ProjectsController#list.HTML         ┃  30 hits ┃  3.7% ┃ ░░
CategoriesController#show.HTML       ┃   8 hits ┃  1.0% ┃ ░
ProjectsController#index.JS          ┃   3 hits ┃  0.4% ┃ 
CategoriesController#index.HTML      ┃   1 hits ┃  0.1% ┃ 
ProjectsController#most_popular.HTML ┃   1 hits ┃  0.1% ┃ 
ProjectsController#show.HTML         ┃   1 hits ┃  0.1% ┃ 


HTTP methods
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
GET ┃ 821 hits ┃ 100.0% ┃ ░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░

HTTP statuses returned
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
200 ┃ 112 hits ┃ 90.3% ┃ ░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░
500 ┃  12 hits ┃  9.7% ┃ ░░░░░░░░░░

━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
Request duration - by sum                                   ┃ Hits ┃    Sum ┃   Mean ┃ StdDev ┃    Min ┃    Max ┃    95 %tile
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
ProjectsController#index.HTML                               ┃   31 ┃ 26.88s ┃  0.87s ┃  0.48s ┃  0.30s ┃  2.05s ┃ 0.30s-2.05s
ProjectsController#list.JS                                  ┃   49 ┃ 14.31s ┃  0.29s ┃  0.18s ┃  0.20s ┃  1.49s ┃ 0.20s-1.51s
ProjectsController#list.HTML                                ┃   30 ┃  9.75s ┃  0.33s ┃  0.24s ┃  0.25s ┃  1.57s ┃ 0.25s-1.58s
CategoriesController#show.HTML                              ┃    8 ┃  6.19s ┃  0.77s ┃  0.23s ┃  0.22s ┃  0.91s ┃ 0.22s-0.92s
ProjectsController#index.JS                                 ┃    3 ┃  4.46s ┃  1.49s ┃  0.50s ┃  0.91s ┃  1.80s ┃ 0.90s-1.83s
ProjectsController#most_popular.HTML                        ┃    1 ┃  1.13s ┃  1.13s ┃  0.00s ┃  1.13s ┃  1.13s ┃ 1.11s-1.15s
ProjectsController#show.HTML                                ┃    1 ┃  0.71s ┃  0.71s ┃  0.00s ┃  0.71s ┃  0.71s ┃ 0.71s-0.73s
CategoriesController#index.HTML                             ┃    1 ┃  0.34s ┃  0.34s ┃  0.00s ┃  0.34s ┃  0.34s ┃ 0.34s-0.35s

━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
Request duration - by mean                                  ┃ Hits ┃    Sum ┃   Mean ┃ StdDev ┃    Min ┃    Max ┃    95 %tile
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
ProjectsController#index.JS                                 ┃    3 ┃  4.46s ┃  1.49s ┃  0.50s ┃  0.91s ┃  1.80s ┃ 0.90s-1.83s
ProjectsController#most_popular.HTML                        ┃    1 ┃  1.13s ┃  1.13s ┃  0.00s ┃  1.13s ┃  1.13s ┃ 1.11s-1.15s
ProjectsController#index.HTML                               ┃   31 ┃ 26.88s ┃  0.87s ┃  0.48s ┃  0.30s ┃  2.05s ┃ 0.30s-2.05s
CategoriesController#show.HTML                              ┃    8 ┃  6.19s ┃  0.77s ┃  0.23s ┃  0.22s ┃  0.91s ┃ 0.22s-0.92s
ProjectsController#show.HTML                                ┃    1 ┃  0.71s ┃  0.71s ┃  0.00s ┃  0.71s ┃  0.71s ┃ 0.71s-0.73s
CategoriesController#index.HTML                             ┃    1 ┃  0.34s ┃  0.34s ┃  0.00s ┃  0.34s ┃  0.34s ┃ 0.34s-0.35s
ProjectsController#list.HTML                                ┃   30 ┃  9.75s ┃  0.33s ┃  0.24s ┃  0.25s ┃  1.57s ┃ 0.25s-1.58s
ProjectsController#list.JS                                  ┃   49 ┃ 14.31s ┃  0.29s ┃  0.18s ┃  0.20s ┃  1.49s ┃ 0.20s-1.51s

━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
View rendering time - by sum                                ┃ Hits ┃    Sum ┃   Mean ┃ StdDev ┃    Min ┃    Max ┃    95 %tile
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
ProjectsController#index.HTML                               ┃   26 ┃ 12.66s ┃  0.49s ┃  0.43s ┃  0.16s ┃  1.74s ┃ 0.16s-1.75s
ProjectsController#list.JS                                  ┃   49 ┃  9.94s ┃  0.20s ┃  0.12s ┃  0.13s ┃  1.02s ┃ 0.13s-1.03s
ProjectsController#list.HTML                                ┃   30 ┃  6.75s ┃  0.22s ┃  0.17s ┃  0.16s ┃  1.10s ┃ 0.16s-1.11s
ProjectsController#index.JS                                 ┃    3 ┃  2.46s ┃  0.82s ┃  0.48s ┃  0.27s ┃  1.11s ┃ 0.26s-1.11s
ProjectsController#most_popular.HTML                        ┃    1 ┃  0.97s ┃  0.97s ┃  0.00s ┃  0.97s ┃  0.97s ┃ 0.96s-0.99s
CategoriesController#index.HTML                             ┃    1 ┃  0.25s ┃  0.25s ┃  0.00s ┃  0.25s ┃  0.25s ┃ 0.25s-0.26s
ProjectsController#show.HTML                                ┃    1 ┃  0.04s ┃  0.04s ┃  0.00s ┃  0.04s ┃  0.04s ┃ 0.04s-0.04s
CategoriesController#show.HTML                              ┃    1 ┃  0.02s ┃  0.02s ┃  0.00s ┃  0.02s ┃  0.02s ┃ 0.02s-0.02s

━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
View rendering time - by mean                               ┃ Hits ┃    Sum ┃   Mean ┃ StdDev ┃    Min ┃    Max ┃    95 %tile
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
ProjectsController#most_popular.HTML                        ┃    1 ┃  0.97s ┃  0.97s ┃  0.00s ┃  0.97s ┃  0.97s ┃ 0.96s-0.99s
ProjectsController#index.JS                                 ┃    3 ┃  2.46s ┃  0.82s ┃  0.48s ┃  0.27s ┃  1.11s ┃ 0.26s-1.11s
ProjectsController#index.HTML                               ┃   26 ┃ 12.66s ┃  0.49s ┃  0.43s ┃  0.16s ┃  1.74s ┃ 0.16s-1.75s
CategoriesController#index.HTML                             ┃    1 ┃  0.25s ┃  0.25s ┃  0.00s ┃  0.25s ┃  0.25s ┃ 0.25s-0.26s
ProjectsController#list.HTML                                ┃   30 ┃  6.75s ┃  0.22s ┃  0.17s ┃  0.16s ┃  1.10s ┃ 0.16s-1.11s
ProjectsController#list.JS                                  ┃   49 ┃  9.94s ┃  0.20s ┃  0.12s ┃  0.13s ┃  1.02s ┃ 0.13s-1.03s
ProjectsController#show.HTML                                ┃    1 ┃  0.04s ┃  0.04s ┃  0.00s ┃  0.04s ┃  0.04s ┃ 0.04s-0.04s
CategoriesController#show.HTML                              ┃    1 ┃  0.02s ┃  0.02s ┃  0.00s ┃  0.02s ┃  0.02s ┃ 0.02s-0.02s

━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
Database time - by sum                                      ┃ Hits ┃    Sum ┃   Mean ┃ StdDev ┃    Min ┃    Max ┃    95 %tile
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
ProjectsController#index.HTML                               ┃   26 ┃  7.64s ┃  0.29s ┃  0.08s ┃  0.24s ┃  0.66s ┃ 0.24s-0.66s
ProjectsController#list.JS                                  ┃   49 ┃  2.48s ┃  0.05s ┃  0.06s ┃  0.04s ┃  0.43s ┃ 0.04s-0.44s
ProjectsController#list.HTML                                ┃   30 ┃  1.70s ┃  0.06s ┃  0.07s ┃  0.04s ┃  0.44s ┃ 0.04s-0.44s
ProjectsController#index.JS                                 ┃    3 ┃  1.59s ┃  0.53s ┃  0.13s ┃  0.38s ┃  0.61s ┃ 0.38s-0.61s
CategoriesController#show.HTML                              ┃    1 ┃  0.66s ┃  0.66s ┃  0.00s ┃  0.66s ┃  0.66s ┃ 0.65s-0.67s
ProjectsController#show.HTML                                ┃    1 ┃  0.53s ┃  0.53s ┃  0.00s ┃  0.53s ┃  0.53s ┃ 0.52s-0.54s
ProjectsController#most_popular.HTML                        ┃    1 ┃  0.10s ┃  0.10s ┃  0.00s ┃  0.10s ┃  0.10s ┃ 0.10s-0.11s
CategoriesController#index.HTML                             ┃    1 ┃  0.08s ┃  0.08s ┃  0.00s ┃  0.08s ┃  0.08s ┃ 0.08s-0.08s

━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
Database time - by mean                                     ┃ Hits ┃    Sum ┃   Mean ┃ StdDev ┃    Min ┃    Max ┃    95 %tile
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
CategoriesController#show.HTML                              ┃    1 ┃  0.66s ┃  0.66s ┃  0.00s ┃  0.66s ┃  0.66s ┃ 0.65s-0.67s
ProjectsController#index.JS                                 ┃    3 ┃  1.59s ┃  0.53s ┃  0.13s ┃  0.38s ┃  0.61s ┃ 0.38s-0.61s
ProjectsController#show.HTML                                ┃    1 ┃  0.53s ┃  0.53s ┃  0.00s ┃  0.53s ┃  0.53s ┃ 0.52s-0.54s
ProjectsController#index.HTML                               ┃   26 ┃  7.64s ┃  0.29s ┃  0.08s ┃  0.24s ┃  0.66s ┃ 0.24s-0.66s
ProjectsController#most_popular.HTML                        ┃    1 ┃  0.10s ┃  0.10s ┃  0.00s ┃  0.10s ┃  0.10s ┃ 0.10s-0.11s
CategoriesController#index.HTML                             ┃    1 ┃  0.08s ┃  0.08s ┃  0.00s ┃  0.08s ┃  0.08s ┃ 0.08s-0.08s
ProjectsController#list.HTML                                ┃   30 ┃  1.70s ┃  0.06s ┃  0.07s ┃  0.04s ┃  0.44s ┃ 0.04s-0.44s
ProjectsController#list.JS                                  ┃   49 ┃  2.48s ┃  0.05s ┃  0.06s ┃  0.04s ┃  0.43s ┃ 0.04s-0.44s

Process blockers (> 1 sec duration)
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
ProjectsController#index.HTML        ┃ 6 hits ┃ 54.5% ┃ ░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░
ProjectsController#index.JS          ┃ 2 hits ┃ 18.2% ┃ ░░░░░░░░░░░░░
ProjectsController#most_popular.HTML ┃ 1 hits ┃  9.1% ┃ ░░░░░░
ProjectsController#list.HTML         ┃ 1 hits ┃  9.1% ┃ ░░░░░░
ProjectsController#list.JS           ┃ 1 hits ┃  9.1% ┃ ░░░░░░

Parse warnings
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
Parsable lines were encountered without a header line before it. It
could be that logging is not setup correctly for your application.
Visit this website for logging configuration tips:
http://github.com/wvanbergen/request-log-analyzer/wikis/configure-logging


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!



コンソールだと色が変わってみやすい。