ActiveRecordProfiler ==================== ** Note: ** This gem is in transition from an old Rails 2.x plugin and still has some issues to iron out. In particular, using the notification system to track ActiveRecord query durations isn't as straightforward as it seems, so the times recorded by the profiler don't match the times ActiveRecord reports in the logs. It's still handy for tracking where your N+1 queries are coming from, thoug.... 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](./screenshots/enhanced-log.png?raw=true) 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 ## Any SQL statements matching this pattern will not be tracked by the profiler output, though it will still appear in the enhanced SQL logging. (default: `/^(SHOW FIELDS |SET SQL_AUTO_IS_NULL|SET NAMES |EXPLAIN |BEGIN|COMMIT|PRAGMA )/`) 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: ::in : , , 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](./screenshots/web-reports.png?raw=true) 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](https://github.com/plataformatec/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. Miscellaneous ============= Copyright (c) 2010 Gist, Inc. Copyright (c) 2015 Benjamin Turner