The sql_logging Debugging Plug-In

Posted by on Feb 18, 2008 in Blog, News | Tags: , | 10 Comments

One of my current projects involves significantly improving the search function in a Rails application, a thorny problem that led me to come up with the method to quiet down the Rails logger in my SQL log silencer. It turns out, that wasn’t enough. I have expanded quite a bit on that idea by folding in some useful debugging aids from other developers, making them more useful, and adding a SQL query “hit list” after each request completes. I’m releasing it as the sql_logging plug-in.

Installation is the usual (on one line):

$ script/plugin install \
http://svn.lightyearsoftware.com/svn/plugins/sql_logging

I have set up a forum for discussion and support of the plug-in.

So, what does this give you?

Out of the box, you get these new things:

  • A count of the number of rows returned and a rough count of bytes for each SELECT query
  • A summary at the end of the request of the total number of queries, bytes returned and SQL executions
  • Each SQL execution includes a clean-up backtrace to show you exactly what part of your code triggered the query
  • A summary at the end of the request showing a “top 10” list of queries

The last one is particular useful. Queries are grouped by their backtrace, and then sorted by either number of executions, rows returned or bytes returned. This provides an excellent way to target your performance optimization work.

When sorted by executions, you very quickly see where the same code is triggering a query over and over, and can spend your optimization time trying to reduce this by adding the model to an earlier query (via :include) or by getting more rows at a time by batching up loads (WHERE id IN (...)). Here’s a sample:

Completed in 13.01586 (0 reqs/sec) | Rendering: 2.69928 (20%) | DB: 8.68216 (66%), 154 selects, 1728.1 KB, 166 execs
Top 10 SQL executions:
  Executed 95 times, returning 180 rows (230.5 KB):
    app/models/merge_keyword.rb:34:in `get_merges_by_keyword'
    app/models/merge_keyword.rb:30:in `each'
    app/models/merge_keyword.rb:30:in `get_merges_by_keyword'
    app/models/merge.rb:107:in `search'
    app/models/merge.rb:105:in `each'
    app/models/merge.rb:105:in `search'
    app/controllers/search_controller.rb:98:in `results'
  Executed 22 times, returning 30 rows (1.3 KB):
    app/models/merge.rb:80:in `attribute'
    app/views/merges/_result_line.rhtml:2:in `_run_rhtml_47app47views47merges47_result_line46rhtml'
    app/views/search/results.rhtml:172:in `_run_rhtml_47app47views47search47results46rhtml'
    app/views/search/results.rhtml:170:in `each'
    app/views/search/results.rhtml:170:in `each_with_index'
    app/views/search/results.rhtml:170:in `_run_rhtml_47app47views47search47results46rhtml'
  Executed 20 times, returning 30 rows (1.2 KB):
    app/models/merge.rb:80:in `attribute'
    app/helpers/application_helper.rb:40:in `merge_detail_link'
    app/views/merges/_result_line.rhtml:26:in `_run_rhtml_47app47views47merges47_result_line46rhtml'
    app/views/search/results.rhtml:172:in `_run_rhtml_47app47views47search47results46rhtml'
    app/views/search/results.rhtml:170:in `each'
    app/views/search/results.rhtml:170:in `each_with_index'
    app/views/search/results.rhtml:170:in `_run_rhtml_47app47views47search47results46rhtml'

By sorting by rows or bytes returned, you may be able to determine that you need to let the database do more of the filtering work. It may be inefficient to have the database return a pile of rows to your application, only to discard a bunch of them.

The silencer from my previous post is in there, too, along with a new silencer that quiets only the backtrace for the duration of the block:

silence_sql do
  # ...
end
 
silence_sql_backtrace do
  # ...
end

I must give a big hat tip to Adam Doppelt and Nathaniel Talbott. Adam’s SQL logging enhancements formed the basis for the logging enhancements here. I made them a little more generic so they worked with both MySQL and PostgreSQL, as well as tracking executions for things that don’t return data. Nathaniel’s QueryTrace plug-in has been around for a while, and I originally tried making this new plug-in simply work with it, but in the end decided to fold the functionality in so the “top 10” list didn’t duplicate the backtrace cleaning code. I also added a regexp to the cleaner so it excludes the plug-in’s code from the backtrace.

There are a few more goodies in the plug-in, so look at the README for more details.

Update: I fixed a few bugs and added a feature. The plug-in now ignores queries whose name ends with ” Column”. These are internal Rails queries and their inclusion skewed the results.

The new feature tracks the execution time of SQL, and lets you sort the top-10 list by either total time for all instances of the SQL or the median execution time. Total time is also now the default sorting method, as this is probably the best way to attack SQL optimization: whatever is taking up the biggest percentage of your time in the database is a good place to start.

Update 2: The plug-in works on Rails 2.0.2 now.

10 Comments

  1. Andy
    March 4, 2008

    thanks for the great work.

    it’d be nice if you keep track of top X queries in every category(most time spent on execution, most bytes returned, etc) in lat X days instead of just per request. Then we just really know which ones need tuning application-wise.

  2. Steve
    March 5, 2008

    Hi, Andy. While I understand why you’re asking for that, it isn’t very appropriate for anything but the smallest of Rails applications. In order to track what you’re asking for, you’d need to store that kind of information in the database itself so you could collect the data over a variable number of back-end processes and across restarts. Then you’d have to augment the plug-in to not collect data on the SQL that queries/updates the statistics in order to keep things relevant. Finally, you’ll need some kind of cron job that purges old rows so your database does fill up with data about your SQL instead of your application’s data.

    This is well beyond the scope of a simple plug-in like sql_logging.

    It’s an interesting idea, and something I’ve seen in larger organizations in the past. Who knows, maybe I’ll find a need to do something like this in the future.

  3. JM
    March 5, 2008

    FYI, I’m having trouble reaching your SVN repository.

  4. AC
    March 7, 2008

    I encounter a missing file error when attempting to run my application…

    ~ piston import http://svn.lightyearsoftware.com/svn/plugins/sql_logging vendor/plugins/sql_logging

    Exported r659 from ‘http://svn.lightyearsoftware.com/svn/plugins/sql_logging’ to ‘vendor/plugins/sql_logging’

    ~ ./script/console

    Loading development environment (Rails 2.0.2)
    /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/1.8/rubygems/custom_require.rb:27:in `gem_original_require’: no such file to load — pg (MissingSourceFile)
    from /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/1.8/rubygems/custom_require.rb:27:in `require’
    … 34 levels…
    from /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/1.8/irb/init.rb:251:in `load_modules’
    from /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/1.8/irb/init.rb:21:in `setup’
    from /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/1.8/irb.rb:54:in `start’
    from /usr/bin/irb:13

  5. Steve
    March 7, 2008

    AC: Unfortunately, I think the useful information is buried in the “… 34 levels …” part of that backtrace. Mind hacking up your script/server to look like this and sending me the output?

    #!/usr/bin/env ruby
    begin
    require File.dirname(__FILE__) + ‘/../config/boot’
    require ‘commands/server’
    rescue Exception => e
    puts e.backtrace
    end

  6. AC
    March 9, 2008

    ~ ./script/server -p 4000
    => Booting Mongrel (use ‘script/server webrick’ to force WEBrick)
    => Rails application starting on http://0.0.0.0:4000
    => Call with -d to detach
    => Ctrl-C to shutdown server
    ** Starting Mongrel listening at 0.0.0.0:4000
    ** Starting Rails with development environment…
    Exiting
    /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/1.8/rubygems/custom_require.rb:27:in `gem_original_require’
    /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/1.8/rubygems/custom_require.rb:27:in `require’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:496:in `require’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:342:in `new_constants_in’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:496:in `require’
    vendor/rails/activesupport/lib/active_support/core_ext/kernel/requires.rb:7:in `require_library_or_gem’
    vendor/rails/activesupport/lib/active_support/core_ext/kernel/reporting.rb:11:in `silence_warnings’
    vendor/rails/activesupport/lib/active_support/core_ext/kernel/requires.rb:5:in `require_library_or_gem’
    vendor/rails/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb:4
    /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/1.8/rubygems/custom_require.rb:27:in `gem_original_require’
    /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/1.8/rubygems/custom_require.rb:27:in `require’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:496:in `require’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:342:in `new_constants_in’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:496:in `require’
    vendor/plugins/sql_logging/lib/sql_logging/postgresql.rb:1
    /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/1.8/rubygems/custom_require.rb:27:in `gem_original_require’
    /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/1.8/rubygems/custom_require.rb:27:in `require’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:496:in `require’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:342:in `new_constants_in’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:496:in `require’
    vendor/plugins/sql_logging/lib/sql_logging/summary.rb:123
    /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/1.8/rubygems/custom_require.rb:27:in `gem_original_require’
    /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/1.8/rubygems/custom_require.rb:27:in `require’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:496:in `require’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:342:in `new_constants_in’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:496:in `require’
    vendor/plugins/sql_logging/init.rb:1:in `evaluate_init_rb’
    ./script/../config/../vendor/rails/railties/lib/rails/plugin.rb:79:in `evaluate_init_rb’
    vendor/rails/activesupport/lib/active_support/core_ext/kernel/reporting.rb:11:in `silence_warnings’
    ./script/../config/../vendor/rails/railties/lib/rails/plugin.rb:75:in `evaluate_init_rb’
    ./script/../config/../vendor/rails/railties/lib/rails/plugin.rb:39:in `load’
    ./script/../config/../vendor/rails/railties/lib/rails/plugin/loader.rb:33:in `load_plugins’
    ./script/../config/../vendor/rails/railties/lib/rails/plugin/loader.rb:32:in `each’
    ./script/../config/../vendor/rails/railties/lib/rails/plugin/loader.rb:32:in `load_plugins’
    vendor/rails/railties/lib/initializer.rb:173:in `load_plugins’
    vendor/rails/railties/lib/initializer.rb:89:in `process’
    vendor/rails/railties/lib/initializer.rb:49:in `send’
    vendor/rails/railties/lib/initializer.rb:49:in `run’
    vironment.rb:13
    /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/1.8/rubygems/custom_require.rb:27:in `gem_original_require’
    /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/1.8/rubygems/custom_require.rb:27:in `require’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:496:in `require’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:342:in `new_constants_in’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:496:in `require’
    /Library/Ruby/Gems/1.8/gems/mongrel-1.1.3/bin/../lib/mongrel/rails.rb:147:in `rails’
    /Library/Ruby/Gems/1.8/gems/mongrel-1.1.3/bin/mongrel_rails:113:in `cloaker_’
    /Library/Ruby/Gems/1.8/gems/mongrel-1.1.3/lib/mongrel/configurator.rb:149:in `call’
    /Library/Ruby/Gems/1.8/gems/mongrel-1.1.3/lib/mongrel/configurator.rb:149:in `listener’
    /Library/Ruby/Gems/1.8/gems/mongrel-1.1.3/bin/mongrel_rails:99:in `cloaker_’
    /Library/Ruby/Gems/1.8/gems/mongrel-1.1.3/lib/mongrel/configurator.rb:50:in `call’
    /Library/Ruby/Gems/1.8/gems/mongrel-1.1.3/lib/mongrel/configurator.rb:50:in `initialize’
    /Library/Ruby/Gems/1.8/gems/mongrel-1.1.3/bin/mongrel_rails:84:in `new’
    /Library/Ruby/Gems/1.8/gems/mongrel-1.1.3/bin/mongrel_rails:84:in `run’
    /Library/Ruby/Gems/1.8/gems/mongrel-1.1.3/lib/mongrel/command.rb:212:in `run’
    /Library/Ruby/Gems/1.8/gems/mongrel-1.1.3/bin/mongrel_rails:281
    vendor/rails/activesupport/lib/active_support/dependencies.rb:489:in `load’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:489:in `load’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:342:in `new_constants_in’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:489:in `load’
    vendor/rails/railties/lib/commands/servers/mongrel.rb:64
    /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/1.8/rubygems/custom_require.rb:27:in `gem_original_require’
    /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/1.8/rubygems/custom_require.rb:27:in `require’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:496:in `require’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:342:in `new_constants_in’
    vendor/rails/activesupport/lib/active_support/dependencies.rb:496:in `require’
    vendor/rails/railties/lib/commands/server.rb:39
    ./script/server:4:in `require’
    ./script/server:4

  7. Steve
    March 10, 2008

    AC: I haven’t been able to find a source file called “pg” on my system anywhere and the plug-in appears to load and work fine in the absence of a PostgreSQL gem. I’m wondering if you don’t have an old gem or something lying around that’s causing problems.

    I’m happy to continue helping you troubleshoot this, but if you don’t mind, send me an email so the comments here aren’t overwhelmed with our back-and-forth.

  8. Srijith
    June 13, 2008

    Hi
    i am using sql_logging plugin but i am getting error
    undefined local variable or method `rows’ for #
    what does it mean.Please reply soon.

  9. Rob Anderton
    September 12, 2008

    Hi,

    Firstly, thanks for this really useful plugin, it’s been a big help in identifying potential bottlenecks as we develop our apps.

    Unfortunately a recent commit to edge Rails (http://github.com/rails/rails/commit/de0e7507de826bf77fd57cc2a51e27388cb62ff7) has broken the plugin. Quite simple to fix though: the active_record_runtime method no longer takes a parameter, so simply removing it from the redefined method in the plugin fixed it. I’ve pastied a patch here: http://pastie.org/271509 (you’ll have to ignore the whitespace changes!)

    Thanks,
    Rob

  10. Steve
    September 12, 2008

    Hi, Rob. Thanks for the heads-up about edge Rails and the patch. I’ll need to verify it still works with older Rails releases, but once that’s done I’ll check in a fix.