MySQL's slow query log is a very handy tool to detect which SQL queries are running slowly in a production app.
So what about rails applications? Often, test data only contains a small amount of data. Over time more users use the site and generate more data. A page that usually renders in 100ms could be taking 3-5 seconds, or more!
I present, SlowActions. The goal was to analyze a standard log file to detect actions that render slowly. It had to be easy to use and also not require modification of rails' logging mechanism. Observe:
$> slow-actions --actions development.log
Cost Average Max
- UsersController : game_history (22 entries, 0% Error)
Total: 11275.447 3642.437 12728.0
Render: 7.20300 2.32700 17.2450
DB: 10.5020 3.39200 10.0000
- QuestionsController : refresh_index_table (89 entries, 0% Error)
Total: 908.494 202.348 307.000
Render: 0.00000 0.00000 0.00000
DB: 32.5880 7.25800 10.0000
More info after the break ....
So, what are we looking at? These are the top two (because I cut off the rest) results for looking at all the log entries times sorted by their Cost. The first line is the Controller followed by the Action. In parenthesis is the number of entries in the log file and the percent of those entries that had an error.
The second line is the total time from request to the data being sent to the user. There is a column for Cost, Avg, and Max. Max is the maximum time this action ever took. Avg is the average amount of time the action took (not counting errors). Cost = Avg * Math.Log(# entries).
The Cost can be thought of as that action's share of the slowness of the site. An action that is only run once a month and takes 5 seconds is not as bad as an action run 200 times per day that takes 1 second. The Log helps smooth things out a bit.
There are a bunch of filters that you can put on the command:
$> slow-actions (--actions | --controllers | --sessions) log_file [log_file ...]
You may also specify:
--min-cost=FLOAT
--min-avg=FLOAT
--min-max=FLOAT
--start-date=YYYY-MM-DD
--end-date=YYYY-MM-DD
You can choose to output the actions and/or controllers (in a tree format) and/or the session ids (to see which users have it the worst, this is great to find out what is causing a slow action). You can also specify multiple log files, in case you rotate your logs.
You can choose a cutoff cost/avg/max, which means that you could make nice short little emails to yourself every night from your app.
You can also specify a date range, because after you fix a bug, you want to see what kind of effect it had.
I took care to put in some basic RDoc to help people use slow-actions in their own tests or tasks. For example, you could run this in irb:
require 'rubygems'
require 'slow_actions'
@sa = SlowActions.new
@sa.parse_file('/path/to/my/log')
puts @sa.print_actions
Have I convinced you? Then get SlowActions off GitHub and download it and run it on your app, you'll be surprised!
