Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Log the original call site for an ActiveRecord query #26815

Merged
merged 1 commit into from Dec 14, 2017

Conversation

@olivierlacan
Copy link
Contributor

@olivierlacan olivierlacan commented Oct 18, 2016

Summary

This change allows you to immediately pinpoint what line of application code is triggering SQL queries in the development log.

  Rubygem Load (0.4ms)  SELECT  "rubygems".* FROM "rubygems" WHERE "rubygems"."id" = $1 LIMIT 1  [["id", 19969]]
  ↳ app/views/news/_version.html.erb:1:in 

Now you know that a partial is triggering queries, which you may not realize looking at the regular log.

It turns this sort of log output:

Started GET "/news/popular" for ::1 at 2016-10-19 01:01:29 +0200
Processing by NewsController#popular as HTML
  Version Load (62.6ms)  SELECT  "versions".* FROM "versions" INNER JOIN "rubygems" ON "rubygems"."id" = "versions"."rubygem_id" LEFT OUTER JOIN "gem_downloads" ON "gem_downloads"."rubygem_id" = "rubygems"."id" AND "gem_downloads"."version_id" = $1 WHERE ("versions"."created_at" BETWEEN '2016-10-11 23:01:29.746294' AND '2016-10-18 23:01:29.746475') AND "versions"."indexed" = $2  ORDER BY gem_downloads.count DESC, "versions"."created_at" DESC LIMIT 10 OFFSET 0  [["version_id", 0], ["indexed", "t"]]
  Rubygem Load (0.6ms)  SELECT  "rubygems".* FROM "rubygems" WHERE "rubygems"."id" = $1 LIMIT 1  [["id", 19969]]
  Version Load (0.9ms)  SELECT  "versions".* FROM "versions" WHERE "versions"."rubygem_id" = $1 AND "versions"."latest" = $2  ORDER BY "versions"."position" ASC LIMIT 1  [["rubygem_id", 19969], ["latest", "t"]]
  GemDownload Load (0.3ms)  SELECT  "gem_downloads".* FROM "gem_downloads" WHERE "gem_downloads"."version_id" = $1 AND "gem_downloads"."rubygem_id" = $2 LIMIT 1  [["version_id", 882133], ["rubygem_id", 19969]]

Into this:

Started GET "/news/popular" for ::1 at 2016-10-19 00:57:48 +0200
Processing by NewsController#popular as HTML
  Version Load (57.3ms)  SELECT  "versions".* FROM "versions" INNER JOIN "rubygems" ON "rubygems"."id" = "versions"."rubygem_id" LEFT OUTER JOIN "gem_downloads" ON "gem_downloads"."rubygem_id" = "rubygems"."id" AND "gem_downloads"."version_id" = $1 WHERE ("versions"."created_at" BETWEEN '2016-10-11 22:57:48.145796' AND '2016-10-18 22:57:48.145965') AND "versions"."indexed" = $2  ORDER BY gem_downloads.count DESC, "versions"."created_at" DESC LIMIT 10 OFFSET 0  [["version_id", 0], ["indexed", "t"]]
  ↳ app/views/news/show.html.erb:9:in `_app_views_news_show_html_erb___2784629296874387000_70222193538980'
  Rubygem Load (0.4ms)  SELECT  "rubygems".* FROM "rubygems" WHERE "rubygems"."id" = $1 LIMIT 1  [["id", 19969]]
  ↳ app/views/news/_version.html.erb:1:in `_app_views_news__version_html_erb__2744651331114605013_70222191156360'
  Version Load (0.8ms)  SELECT  "versions".* FROM "versions" WHERE "versions"."rubygem_id" = $1 AND "versions"."latest" = $2  ORDER BY "versions"."position" ASC LIMIT 1  [["rubygem_id", 19969], ["latest", "t"]]
  ↳ app/helpers/application_helper.rb:23:in `gem_info'
  GemDownload Load (0.3ms)  SELECT  "gem_downloads".* FROM "gem_downloads" WHERE "gem_downloads"."version_id" = $1 AND "gem_downloads"."rubygem_id" = $2 LIMIT 1  [["version_id", 882133], ["rubygem_id", 19969]]
  ↳ app/models/version.rb:247:in `downloads_count'

Configuration Option

This PR introduces a new ActiveRecord configuration option called verbose_query_logs which can
defaults to false in all environments but will be set to true in new_framework_defaults.rb for
new projects.

Pre-existing Rails apps can enable the feature in development.rb with:

Rails.application.configure do
  # ...
  config.active_record.verbose_query_logs = true
  # ...
end

Other Information

It's likely I'll need some help if this PR is looked at favorably. Obviously this may not be something that everybody wants on all the time or by default.

It's a little more noisy than the usual development log, although in my mind, much more useful to developers. I can't work on AR queries anymore without adding this patch into new Rails apps I'm working on.

I fully intend to add tests of course but having no experience with Rails configuration options or the depths of ActiveRecord, I would welcome some guidance there as well.

/cc @sgrif

backtrace = Rails.backtrace_cleaner.clean(caller)

relevant_caller_line = backtrace.detect do |caller_line|
!caller_line.include?('/initializers/')
Copy link
Contributor Author

@olivierlacan olivierlacan Oct 18, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I definitely want to find a way to make this code more self-evident. I can't remember why initializers are involved.

Loading

Copy link
Contributor

@sgrif sgrif Oct 18, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah I think you can ✂️ this line entirely

Loading

Copy link
Contributor Author

@olivierlacan olivierlacan Oct 18, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Gone!

Loading

@sgrif
Copy link
Contributor

@sgrif sgrif commented Oct 18, 2016

I'm in favor of this change overall. This definitely needs to be configurable, and we also need to not do this in production by default. I think a good solution on both fronts would be to introduce this behind a configuration option, which is generated to default to true in config/environments/development.rb, and is false when unspecified. I don't think we need to do anything for existing apps, beyond a changelog entry and a mention in the upgrade guide.

@rafaelfranca How do you feel about this feature?

Loading

@olivierlacan olivierlacan force-pushed the log-query-source branch 2 times, most recently from ae883dc to ebc601b Oct 18, 2016
@maclover7
Copy link
Member

@maclover7 maclover7 commented Oct 18, 2016

👍 an option for a config option could be config.active_record.log_query_callers, or some variation of that

Loading

backtrace = Rails.backtrace_cleaner.clean caller

relevant_caller_line = backtrace.detect do |caller_line|
!caller_line.include?('/initializers/')
Copy link
Contributor Author

@olivierlacan olivierlacan Oct 18, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Welp @sgrif, turns out this line was what made it work. I can only surmise that it somehow eliminates everything except the non-framework caller lines, but I honestly don't know yet.

Loading

Copy link
Contributor Author

@olivierlacan olivierlacan Oct 18, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Never mind, backtrace.first just works. I don't know why my brain was derping on this one.

Loading

Copy link
Contributor

@sgrif sgrif Oct 18, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Replacing it with relevant_caller_line = backtrace.first doesn't accomplish the same thing?

Loading

Copy link
Contributor

@sgrif sgrif Oct 18, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

jinx

Loading

Copy link
Contributor Author

@olivierlacan olivierlacan Oct 18, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Get out of my head, SEAN.

Loading

Copy link
Contributor Author

@olivierlacan olivierlacan Oct 18, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think the first line (return unless super) does anything useful either since the sql method that calls this runs this on its second line:

return unless logger.debug?

Going to nix it.

Loading

@olivierlacan olivierlacan force-pushed the log-query-source branch 2 times, most recently from 1aca125 to eed1846 Oct 18, 2016
@olivierlacan
Copy link
Contributor Author

@olivierlacan olivierlacan commented Oct 19, 2016

@sgrif Got any tips on introducing a new configuration? I looked around but I'm honestly not familiar with any of this at all.

Loading

@sgrif
Copy link
Contributor

@sgrif sgrif commented Oct 19, 2016

You just need to change the generators and add an initializer to the railtie which reads the config option and assigns it to somewhere readable. The config object will already accept any new keys.

Loading

@nynhex
Copy link

@nynhex nynhex commented Oct 19, 2016

This is really useful but agree that it should be configurable based on environment. Assuming it will be a log level configuration?

Loading

@olivierlacan
Copy link
Contributor Author

@olivierlacan olivierlacan commented Oct 19, 2016

@sgrif That's the part I was stuck at, what should I assign it to? ActiveRecord::LogSubscriber? Seems a bit weird with all the attach_to business going on in there.

@shakycode It overrides debug so it's only available in that log level but I don't see why it couldn't be enabled in environments other than production.

Loading

Copy link
Member

@rafaelfranca rafaelfranca left a comment

I like the feature but I don't like we adding coupling between railties and activerecord here. Let's define a different backtrace cleaner.

Loading

@@ -84,6 +84,15 @@ def sql_color(sql)
def logger
ActiveRecord::Base.logger
end

def debug(progname = nil, &block)
backtrace = Rails.backtrace_cleaner.clean caller
Copy link
Member

@rafaelfranca rafaelfranca Oct 22, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think we should couple Active Record with Railties here. One alternative is define our own cleaner here or doing the same as deprecation is doing https://github.com/rails/rails/blob/master/activesupport/lib/active_support/deprecation/reporting.rb#L82

Loading

Copy link
Contributor Author

@olivierlacan olivierlacan Jan 19, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@rafaelfranca You mean re-implement an _extract_callstack private method the same way the Reporting class does?

Loading

Copy link
Contributor Author

@olivierlacan olivierlacan Apr 20, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@rafaelfranca Is that what you meant?

Loading

Copy link
Member

@rafaelfranca rafaelfranca Apr 20, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah.

Loading

@rafaelfranca
Copy link
Member

@rafaelfranca rafaelfranca commented Oct 22, 2016

That's the part I was stuck at, what should I assign it to? ActiveRecord::LogSubscriber?

Yes, we should set as a class level config of the log subscriber.

Loading

olivierlacan added a commit to orientation/orientation that referenced this issue Apr 8, 2017
I really need to finish my Rails PR for this feature:
rails/rails#26815
@olivierlacan
Copy link
Contributor Author

@olivierlacan olivierlacan commented Apr 20, 2017

@rafaelfranca Looking for some more guidance on this since ActiveRecord's LogSubscriber test very much depends on ActiveSupport's LogSubscriber test helper (which mocks out much of the LogSubscriber).

I feel weird about adding a debug method to the ActiveSupport test helper so it almost seems like ActiveRecord should have its own test helper that perhaps inherits from the ActiveSupport one.

I have no idea if that's kosher or not.

Loading

@rafaelfranca
Copy link
Member

@rafaelfranca rafaelfranca commented Apr 20, 2017

I think that to test it you can use the vanilla ActiveSupport's LogSubscriber test helper. You only need to stop implementing the debug method in

and use the information in the @logger.logged(:debug).

Loading

@@ -1,5 +1,7 @@
module ActiveRecord
class LogSubscriber < ActiveSupport::LogSubscriber
cattr_accessor :log_query_callers
Copy link
Contributor Author

@olivierlacan olivierlacan Apr 25, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@rafaelfranca Let me know if that's what you had in mind. I did allow the LogSubscriber to define whether it logs query callers but that seemed like a tricky thing to set in something like development.rb so I also added an ActiveRecord::Core config that supersedes it.

I couldn't find great examples of high level configs touching low-level configs, and while people can configure the Rails logger, it seems weird to let them reach as far down as the LogSubscriber for ActiveRecord to configure this.

Loading

@olivierlacan olivierlacan force-pushed the log-query-source branch 3 times, most recently from 950038e to 705880d Apr 25, 2017
@olivierlacan
Copy link
Contributor Author

@olivierlacan olivierlacan commented Apr 25, 2017

@rafaelfranca All right, I've made the changes you and @sgrif suggested. Of course there's probably a lot to adjust.

activerecord/test/cases/log_subscriber_test.rb passes but there's probably some more testing (and opinions) needed around the configuration options.

Tested with a Rails app built from the current master branch, this is the output:

Started GET "/users" for 127.0.0.1 at 2017-04-24 23:22:37 -0400
   (0.3ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
  ↳ /Users/olivierlacan/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/web-console-3.4.0/lib/web_console/middleware.rb:135
Processing by UsersController#index as HTML
  Rendering users/index.html.erb within layouts/application
  User Load (0.2ms)  SELECT "users".* FROM "users"
  ↳ app/views/users/index.html.erb:14
  Rendered users/index.html.erb within layouts/application (4.3ms)
Completed 200 OK in 35ms (Views: 12.7ms | ActiveRecord: 0.7ms)

For reference, app/views/users/index.html.erb:14 is:

<% @users.each do |user| %>

Loading

@nateberkopec
Copy link
Contributor

@nateberkopec nateberkopec commented Apr 28, 2017

Whatever happened to adding this to config/environments/development.rb?

Loading

@olivierlacan
Copy link
Contributor Author

@olivierlacan olivierlacan commented Apr 28, 2017

new_framework_defaults.rb is the way of the future, Natey Nate Nate. :-)

Loading

@sgrif
Copy link
Contributor

@sgrif sgrif commented Dec 13, 2017

Looks like we still have a test failure which seems legitimate

Loading

@olivierlacan
Copy link
Contributor Author

@olivierlacan olivierlacan commented Dec 13, 2017

@sgrif Looks like it might be a master failure:

Failed in:
  test/application/initializers/notifications_test.rb

Loading

@matthewd
Copy link
Member

@matthewd matthewd commented Dec 13, 2017

I've considered trying to exclude gem code but often those can be useful to sniff out queries that are caused by gems themselves.

You might need to reconsider what RAILS_GEM_ROOT = File.expand_path("../../../..", __FILE__) + "/" is going to do in an installed gem, then.

Loading

@sgrif
Copy link
Contributor

@sgrif sgrif commented Dec 14, 2017

Loading

@olivierlacan
Copy link
Contributor Author

@olivierlacan olivierlacan commented Dec 14, 2017

@sgrif Pretty sure it's a fluke caused by Bundler could not find compatible versions for gem "activesupport": (Bundler::VersionConflict) but could be wrong. Going to wait for my most recent rebase to run on Travis.

Update: ignore me, that's not it, still digging.

Loading

@olivierlacan
Copy link
Contributor Author

@olivierlacan olivierlacan commented Dec 14, 2017

@sgrif Not super happy about the fix but Railties tests look for SQL notifications in the debug logger and check the size of the output (expects 1 line). Although verbose_query_logs is off by default, those tests copy the development.rb template so I had to reach into that railties to manually disable verbose_query_logs which introduces some test coupling. I don't love it.

The only alternative I have is to not add verbose_query_logs to new application's config/development.rb but that's kind of a bummer. Curious for other opinions.

Loading

This new ActiveRecord configuration option allows you to easily
pinpoint what line of application code is triggering SQL queries in the
development log by appending below each SQL statement log the line of
Ruby code that triggered it.

It’s useful with N+1 issues, and to locate stray queries.

By default this new option ignores Rails and Ruby code in order to
surface only callers from your application Ruby code or your gems.

It is enabled on newly generated Rails 5.2 applications and can be
enabled on existing Rails applications:

```ruby
Rails.application.configure do
  # ...
  config.active_record.verbose_query_logs = true
end
```

The `rails app:upgrade` task will also add it to
`config/development.rb`.

This feature purposely avoids coupling with
ActiveSupport::BacktraceCleaner since ActiveRecord can be used without
ActiveRecord. This decision can be reverted in the future to allow more
configurable backtraces (the exclusion of gem callers for example).
@sgrif
Copy link
Contributor

@sgrif sgrif commented Dec 14, 2017

We could change the test

Loading

@matthewd
Copy link
Member

@matthewd matthewd commented Dec 14, 2017

Yeah, changing the number in assertion seems like it would be a bit confusing [to future readers], but arranging to override the default configuration seems fine -- just as it already does to turn off colors.

Loading

@eileencodes eileencodes merged commit 4bd28ef into rails:master Dec 14, 2017
2 checks passed
Loading
@eileencodes
Copy link
Member

@eileencodes eileencodes commented Dec 14, 2017

I agreed that changing the default configuration was fine based on the fact we do it in other tests. Thanks for your work on this feature @olivierlacan!

Loading

@@ -25,3 +25,6 @@
# Store boolean values are in sqlite3 databases as 1 and 0 instead of 't' and
# 'f' after migrating old data.
# Rails.application.config.active_record.sqlite3.represent_boolean_as_integer = true

# Highlight code that triggered database queries in logs.
Rails.application.config.active_record.verbose_query_logs = Rails.env.development?
Copy link
Member

@matthewd matthewd Dec 14, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This should not be uncommented.

As we generate it into development.rb, I'm actually not sure it should even be here.

Loading

Copy link
Contributor Author

@olivierlacan olivierlacan Jan 5, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@matthewd Should I do a follow-up PR to fix this or can someone with a commit bit fix it?

Loading

Copy link
Member

@matthewd matthewd Jan 5, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you have the time, a PR would be great; otherwise I'll throw it on my todo list ❤️

Loading

Copy link
Member

@matthewd matthewd Jan 5, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh, looks like @eugeneius already took care of it in #31519

Loading

@dhh
Copy link
Member

@dhh dhh commented Jan 12, 2018

@olivierlacan Really nice work. Could you find a way to update this so that the logging in the console doesn't include this? It isn't really helpful there:

irb(main):009:0> Topic.first.messages
  Topic Load (0.1ms)  SELECT  "topics".* FROM "topics" ORDER BY "topics"."id" ASC LIMIT $1  [["LIMIT", 1]]
  ↳ (irb):9
  Message Load (0.3ms)  SELECT  "messages".* FROM "messages" WHERE "messages"."topic_id" = $1 LIMIT $2  [["topic_id", 1], ["LIMIT", 11]]
  ↳ /Users/david/.rbenv/versions/2.5.0/lib/ruby/gems/2.5.0/gems/thor-0.20.0/lib/thor/command.rb:27
=> #<ActiveRecord::Associations::CollectionProxy []>

Loading

claudioclutter added a commit to clutter/mdma that referenced this issue Mar 15, 2018
tnir pushed a commit to tnir/gitlabhq that referenced this issue Aug 10, 2018
This backports the rails/rails#26815
and enables that for non-Rails5 and non-production environments.
@oyeanuj
Copy link

@oyeanuj oyeanuj commented Oct 6, 2018

Hi @olivierlacan, I came here wondering if it is somehow possible to enable this in the console, which I know is quite opposite of @dhh's request. Is this today configurable or would you recommend making it configurable?

As not a rails pro, I tend to test out a lot of my methods in the console before, especially when comparing different solutions and it'd be super useful to be able to enable verbose query logging in the console for those sessions.

thank you!

Loading

@olivierlacan olivierlacan deleted the log-query-source branch Oct 6, 2018
@olivierlacan
Copy link
Contributor Author

@olivierlacan olivierlacan commented Oct 6, 2018

@oyeanuj It's definitely possible and I find it very useful myself since SQL statements are printing out when your logger is in debug mode (Rails.logger.level = 0). I think it might make sense to enable verbose query logs in the console if the log level is 0/debug. I'm curious if David would find that an agreeable middle-ground.

Currently we still forcibly disable verbose_query_logs anytime Rails is booted in console mode as you can see here:

ActiveRecord::Base.verbose_query_logs = false

You can easily add this to a file named (for example) verbose_query_logs_console.rb inside of config/initializers/ in order to override this behavior and turn on verbose query logs in any development console:

class ActiveRecord::Railtie
  console do
    ActiveRecord::Base.verbose_query_logs = true 
  end
end

When calling SQL generating methods directly you'll get some weird output in the console but if you happen to be calling a method that generates a SQL call it will be a lot more helpful:

Loading development environment (Rails 5.2.1)
[1] pry(main)> User.first
  User Load (0.4ms)  SELECT  "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT $1  [["LIMIT", 1]]
  ↳ (pry):1:in `<main>'

Loading

olivierlacan added a commit to orientation/orientation that referenced this issue Oct 6, 2018
Since I finally shipped verbose_query_logs into Rails 5.2!

Also experiment with enabling it in the console. See:
rails/rails#26815 (comment)
@sgrif
Copy link
Contributor

@sgrif sgrif commented Oct 7, 2018

Loading

@dhh
Copy link
Member

@dhh dhh commented Oct 9, 2018

I usually run at :debug for both development and production, so it wouldn't work for me to have that be the default level. I think an initializer or even just writing ActiveRecord::Base.verbose_query_logs = true in the console when you need the extra logging would be a reasonable approach. We could even document that.

Loading

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked issues

Successfully merging this pull request may close these issues.

None yet