Backtrace from SQL query to application code?

Question

Is there a way to find which line of code generated a MySQL statement in a Rails development log?

In order to do some performance optimization, I would like to find which part of my app is creating which MySQL queries. When I take a look at my log, I see hundres of queries flashing around on each web request I do, and I need to find out where they come from.

I'm thinking about adding some variables like ____FILE____ and ____LINE____ to the log output.

Is that possible?

Answer 1

https://github.com/lightyear/sql-logging gives you a backtrace for every SQL query plus a bunch of useful statistics.

Answer 2

You have a few options. None of these options will exactly give you a backtrace the same way you get Ruby backtraces on errors, but they will give you the tools and info you need to track down exactly where your SQL queries are coming from.

1. Your typical Rails log entry will look something like this:

   Started GET "/login" for 127.0.0.1 at Thu Sep 27 18:59:08 -0500 2012
     Processing by PublicController#index as HTML
     (40.9ms)  SELECT COUNT(*) FROM "studies" 
     (49.6ms)  SELECT COUNT(DISTINCT "activities"."whodiddit") FROM "activities" 
     (35.3ms)  SELECT COUNT(*) FROM "involvements" 
   

   I'm guessing this is where your hundreds of SQL queries are happening?

   Rendered partials/_faq.haml (6.1ms)
   Rendered public/index.html.haml within layouts/public (114.3ms)
   Completed 200 OK in 595ms (Views: 276.7ms | ActiveRecord: 151.6ms)
   

   So, at the top you've got the HTTP verb GET and the route (/login in my example), and the host from which it came. After that Rails tells you which controller+action gets triggered.

   Note: If you see a line that starts with Rendered... that's your view getting rendered. Any SQL queries that come after a render indicate that the SQL queries are being triggered in your view (e.g. outside your controller). Just a little thing to think about. Depending on what code your view is calling, the actual lines that trigger your SQL queries could be buried in helpers, models, or anywhere else the view code calls out to.

   Processing by PublicController#index as HTML
   

   The as HTML bit at the end tells you what format the request came in as, and therefore which view/format will probably be used in the response.

   So, what this tells you, basically, is that the SQL queries were triggered either as part of the index action in the PublicController, or one of the views that that controller renders as a result of this action being triggered.

2. If there's just too much to parse, you use debugger commands to stop the output at various points, and allow you to inspect what's going on. More on the debugger here.

3. You can use Rails.logger.info "My info message" or Rails.logger.error "My error message" (depending on whether you want it in the default or error log, etc.) to output things directly in your app log.