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?

Fredkin

This question is similar to: Log caller application stack trace together with each sql query. If you believe it’s different, please edit the question, make it clear how it’s different and/or how the answers on that question are not helpful for your problem. – Dragrope

Answer 1

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

Merill

do u know where to get the plugin for rails 2.x, the svn repo named on their website seems to be down. – Fredkin

Unfortunately, I don't see this working in Rails 4.0. – Coccidiosis

I used github.com/brunofacca/active-record-query-trace credit to https://mcmap.net/q/1471309/-log-caller-application-stack-trace-together-with-each-sql-query – Dragrope

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.

Bannister

"the actual lines that trigger your SQL queries could be buried in helpers, models, or anywhere else the view code calls out to." what im trying to find out is, from which model oder helper etc.. exactly... Is it possible to find that out? from what module or class is that part of the log created? (40.9ms) SELECT COUNT() FROM "studies" (49.6ms) SELECT COUNT(DISTINCT "activities"."whodiddit") FROM "activities" (35.3ms) SELECT COUNT() FROM "involvements" – Fredkin

Could you post some code and parts of your log? Getting to the bottom of where the SQL queries are coming from isn't too hard just looking at the code, but I need you to post some actual code, or at least the associated log. All I can do with your current question is to give you general advice because your question is pretty generic in nature. – Bannister

From the log I posted, I can tell you that the SQL is happening in the controller (or one of the methods it calls), and not the view, simply because the SQL gets logged before the log line where the view is rendered. Figuring that out is mostly about understanding the flow of a Rails call. A request comes it, it's routed to a controller action, the action code is run, the views are rendered (which means the view and the embedded code in the view is executed), and that's pretty much it. The log is in chronological order of what gets executed when. – Bannister

You can put some log output lines around the areas where you think the SQL is getting run, and slowly narrow it down until you find the exact line where it's happening. It could also be that you're not eager loading when you could be, or something fairly straight forward like that. I need to see your log, however. – Bannister

ok, nice to know...:-) This should be helpful for my next steps, if i get stuck, i will post some examples. Thx – Fredkin

Answer 3

You can use instrumentation:

ActiveSupport::Notifications.subscribe("sql.active_record") do
  puts caller.grep(/#{Rails.root}/)
end

Laniary