A Rails log parser to show how your actions are performing

I've been battling with some performance issues on a Rails project I'm working on and I wanted to see which actions could be the culprit. I wrote a quick log parser which will read a log file and print out the call time information by controller#action. It supports sorting by various columns and outputs the results in pretty table format (similar to mysql) View usage information by running:

ruby_log_parser.rb --help

Example
andrew:~$ ruby rails_log_parser.rb --sort median < log/development.log
+----------------------+-------+------------+------+------+------+--------+
| Uri                  | Calls | Total Time | Max  | Min  | Avg  | Median |
+----------------------+-------+------------+------+------+------+--------+
| TestController#index |     7 |       9316 | 1748 | 1053 | 1330 |   1221 |
| TestController#show  |     1 |        764 |  764 |  764 |  764 |    764 |
+----------------------+-------+------------+------+------+------+--------+

The code
You can find the parser here: 
http://github.com/andrewtimberlake/scripts/tree/master/rails/utils/rails_log_parser.rb

I have also stripped out the table pretty printing here:
http://gist.github.com/41938

Usage:
require 'tabalize_array'

arr = [
  ['John', 18],
  ['Jack', 21],
  ['Mary', 22],
  ['Jane', 24]
]
arr.tabalize(['Name', 'Age'], [:left, :right], STDOUT)

Comments

Sylvain said:

Hi Andrew ! Thank you for sharing your parser ! But I have an issue, when I launch it, I have no result. I finally understand that my log model was not the same as yours for the "Completed in" line. Mine looks like this : Completed in 0.05651 (17 reqs/sec) | Rendering: 0.02178 (38%) | DB: 0.01467 (25%) | 200 OK [http://localhost/url] "Rendering" instead of "View" Have you an idea how to change your regular expression on line 13 to make it works ? Many thanks by advance !

Andrew Timberlake said:

Sylvian, thanks for having a look at the code. The short answer to your question, the regular expression is: /Completed\s*in\s*([^\s]+)\s*\([^\)]+\)\s*\|\s*Rendering:\s*([\d\.]+)\s*\([^\)]+\)\s*\|\s*DB:\s*([\d\.]+)\s*\([^\)]+\)\s*\|\s*(\d+)\s*\w+\s*\[([^\]]+)\]/i This is the older Rails format and it displays the execution times in percentages of seconds, not milliseconds. I have updated the code to run on both log file formats as well as adding a --limit <num> flag to limit the results to the top <num> entries. It's updated on Github so the link above will take you to the latest code. Hope that helps.

Sylvain said:

Thank you very much Andrew, now it works fine !

Kennon said:

This is exactly what I've been looking for for awhile now! Thanks alot, it works great!

Andrew Timberlake said:

@sylvain, @kennon - I'm glad it's helpful

Slava said:

Here is another project working on rails request parsing. http://github.com/wvanbergen/request-log-analyzer/tree/master

Willem van Bergen said:

Nice to see that you are also working on a log parser to analyze performance. Clearly, there is a demand for such a tool. I am one of the authors of request-log-analyzer (see above). If you want to team up so we're not duplicating efforts, please contact me!

A Rails log parser to show how your actions are performing

Example

The code

Comments

Have your say