ActiveRecordProfiler

The active-record-profiler gem adds a log formatter to improve the standard SQL logging and a log subscriber to provide profiler-like tracking of SQL statements generated by application code. The log formatter makes the SQL statements in your logs look like this (imagine it's all in one log line):

Person Load (0.3ms)  SELECT  `people`.* FROM `people`  WHERE `people`.`id` = ? LIMIT 1  [["id", 1]] 
  CALLED BY 'app/controllers/day_controller.rb:282:in `find_person''

If you're using log colorizing, then it's even fancier:

Enhanced Log

Each SQL log entry generated by ActiveRecord will have appended the filename, line number, and function name of the nearest calling application code. The information is determined by walking up the call stack until a filename within the /app/ directory is found. If no such filename can be found, the SQL will be logged with a location of 'Non-application code'.

Additionally, the profiler will keep track of the total time spent by all SQL calls coming from each calling location, as well as the number of time that location accessed the database. Certain SQL calls not under the direct control of the application are not counted in these statistics, such as SHOW FIELDS, SET NAMES, BEGIN, and COMMIT statements which tend to skew the timing statistics and provide less useful information about slow SQL queries.

Periodically, the profiler will dump its statistics out to a file and restart all of its counters/timers. The output file is named for the time, process id, and thread id from which it was written, so that multiple threads/processes can safely write their output simultaneously.

Installation

Add it to your Gemfile, like so:

gem 'active-record-profiler'

Then do bundle install, and then add a new initializer, config/initializers/active_record_profiler.rb:

ActiveRecord::Base.logger =
    ActiveRecordProfiler::Logger.new(ActiveRecord::Base.logger)
ActiveRecordProfiler::LogSubscriber.attach_to :active_record unless Rails.env.test?

The first line adds call-site information to ActiveRecord logging, and the second line enables profiling (except in the test environment, where it would mess up your profiling data).

Configuration

stats_flush_period

Control the (approximate) frequency of statistics flushes (default: 1.hour)

ActiveRecordProfiler.stats_flush_period = 1.hour

Note that only flushed data is available for use in the rake reports (described below). If you are running a multithreaded or multiprocess server (which covers most common rails server types), your data will be incomplete until all those threads/processes/servers have flushed their data. This limitation exists primarily to avoid the overhead of coordinating/locking during the process of serving your application's web requests.

profile_dir

Directory where profile data is recorded. (default: Rails.root,join('log', 'profiler_data')

ActiveRecordProfiler.profile_dir = Rails.root.join('log', 'profiler_data'

sql_ignore_pattern

ActiveRecordProfiler.sql_ignore_pattern = /^SET /x

app_path_pattern

Any calling location that matches this pattern will be tracked individually. Any locations that do not match will be grouped under a single Non-application code label. The default only includes the app, lib, and vendor directories, but that's usually suitable and avoids noise. (default: Regexp.new(Regexp.quote("#{Rails.root.expand_path}/") + "(:?app|lib|vendor)/"))

ActiveRecordProfiler.app_path_pattern = Regexp.new(Regexp.quote("#{Rails.root.expand_path}/"))

trim_root_path

This prefix will be removed from the calling site filepath for brevity. (default: "#{Rails.root.expand_path}/")

ActiveRecordProfiler.trim_root_path = "#{Rails.root.parent.expand_path}/app"

profile_self

This setting controls whether the profiler records information about how much time was spent in the profiling code itself. If you want to know what kind of overhead the profiler is adding, set this to true. (default: false)

ActiveRecordProfiler.profile_self = true

link_location

Whether or not to make the locations in the profiler reports into source code links (only works with editors that can be launched via URL scheme) (default: false):

ActiveRecordProfiler.link_location = true

Command Line Reports

To see a top-100 list of what SQL statements your application is spending its time in, run the following rake task:

rake profiler:aggregate max_lines=100 show_sql=true

This will return a list of the SQL which is taking the most time in your application in this format:

<file path>:<line number>:in <method name>: <total duration>, <call count>, <max single call duration>

This will aggregate all of the profiler data you have accumulated; in order to limit the timeframe of the data, use the prefix option to specify a partial date/time:

rake profiler:aggregate max_lines=100 show_sql=true prefix=2010-06-20-10  # data from June 20 during the 10am hour (roughly)

Each thread running the profiler flushes its stats periodically, and there is a rake task to combine multiple profiler data files together in order to keep the number of data files down to a manageable number. A good way to manage the data files on a server is to set up a cron task to run the following command once per hour or once per day:

rake profiler:aggregate compact=<'hour' or 'date'> RAILS_ENV=qa

Compacting by hour will result in a single file for each hour any process dumped its stats. Compacting by day will result in a single file for each day. When using the prefix option to generate a profiler report, you cannot specify an hour if you have compacted your data by date instead of hour (the prefix matching operates on the file names, which will not have hours if they have been compacted by date).

You can clear out all profiler data using the following command:

rake profiler:clear_data

If you want programmatic access to the profiler data, check out the source code for the rake tasks in lib/active-record-profiler/tasks.rake.

Web Reports

The active-record-profiler gem also includes support for producing reports in your browser, which look something like this:

Web Report UI

In order to make it available, you'll want to mount the engine within your application's routes.rb. Since you don't want the public to have access to your profiler reports, you'll want to limit access to it. You could only mount the profiler's web interface in the development environment:

mount ActiveRecordProfiler::Engine => "/profiler"  if Rails.env.development?

Or, if you are using Devise and have an admin flag on a User model, for example:

authenticated :user, -> user { user.admin? } do
  mount ActiveRecordProfiler::Engine => "/profiler"
end

When you visit the path where you've mounted the web interface, you will by default see a report for the current day. If you just installed active-record-profiler, there probably won't be anything there yet, in which case you should go play with your app for a while and come back later. :) Also note that if the web server you are using has multiple processes or threads, you won't see data from those other processes/threads until they dump their data.