Log call site for all queries

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).

8 files changed, 97 insertions, 7 deletions

diff --git a/activerecord/CHANGELOG.md b/activerecord/CHANGELOG.md
index ceef240257..c88a4e7695 100644
--- a/activerecord/CHANGELOG.md
+++ b/activerecord/CHANGELOG.md
@@ -1,3 +1,15 @@
+*   Log database query callers
+
+    Add `verbose_query_logs` configuration option to display the caller
+    of database queries in the log to facilitate N+1 query resolution
+    and other debugging. Excludes Ruby and Rails callers but not gems.
+
+    Enabled in development only for new and upgraded applications. Not
+    recommended for use in the production environment since it relies
+    on Ruby's `Kernel#caller` which is fairly slow.
+
+    *Olivier Lacan*
+
 *   Fix conflicts `counter_cache` with `touch: true` by optimistic locking.
 
     ```
@@ -536,5 +548,4 @@
 
     *Kevin McPhillips*
 
-
 Please check [5-1-stable](https://github.com/rails/rails/blob/5-1-stable/activerecord/CHANGELOG.md) for previous changes.
diff --git a/activerecord/lib/active_record/core.rb b/activerecord/lib/active_record/core.rb
index 481159e501..88810cb328 100644
--- a/activerecord/lib/active_record/core.rb
+++ b/activerecord/lib/active_record/core.rb
@@ -18,6 +18,13 @@ module ActiveRecord
       mattr_accessor :logger, instance_writer: false
 
       ##
+      # :singleton-method:
+      #
+      # Specifies if the methods calling database queries should be logged below
+      # their relevant queries. Defaults to false.
+      mattr_accessor :verbose_query_logs, instance_writer: false, default: false
+
+      ##
       # Contains the database configuration - as is typically stored in config/database.yml -
       # as a Hash.
       #
diff --git a/activerecord/lib/active_record/log_subscriber.rb b/activerecord/lib/active_record/log_subscriber.rb
index 405f3a30c6..ba3419be6c 100644
--- a/activerecord/lib/active_record/log_subscriber.rb
+++ b/activerecord/lib/active_record/log_subscriber.rb
@@ -90,6 +90,48 @@ module ActiveRecord
       def logger
         ActiveRecord::Base.logger
       end
+
+      def debug(progname = nil, &block)
+        return unless super
+
+        if ActiveRecord::Base.verbose_query_logs
+          log_query_source
+        end
+      end
+
+      def log_query_source
+        source_line, line_number = extract_callstack(caller_locations)
+
+        if source_line
+          if defined?(::Rails.root)
+            app_root = "#{::Rails.root.to_s}/".freeze
+            source_line = source_line.sub(app_root, "")
+          end
+
+          logger.debug("  ↳ #{ source_line }:#{ line_number }")
+        end
+      end
+
+      def extract_callstack(callstack)
+        line = callstack.find do |frame|
+          frame.absolute_path && !ignored_callstack(frame.absolute_path)
+        end
+
+        offending_line = line || callstack.first
+
+        [
+          offending_line.path,
+          offending_line.lineno,
+          offending_line.label
+        ]
+      end
+
+      RAILS_GEM_ROOT = File.expand_path("../../../..", __FILE__) + "/"
+
+      def ignored_callstack(path)
+        path.start_with?(RAILS_GEM_ROOT) ||
+        path.start_with?(RbConfig::CONFIG["rubylibdir"])
+      end
   end
 end
 
diff --git a/activerecord/test/cases/log_subscriber_test.rb b/activerecord/test/cases/log_subscriber_test.rb
index 208e54ed0b..e2742ed33e 100644
--- a/activerecord/test/cases/log_subscriber_test.rb
+++ b/activerecord/test/cases/log_subscriber_test.rb
@@ -33,8 +33,9 @@ class LogSubscriberTest < ActiveRecord::TestCase
       super
     end
 
-    def debug(message)
-      @debugs << message
+    def debug(progname = nil, &block)
+      @debugs << progname
+      super
     end
   end
 
@@ -171,6 +172,22 @@ class LogSubscriberTest < ActiveRecord::TestCase
     assert_match(/SELECT .*?FROM .?developers.?/i, @logger.logged(:debug).last)
   end
 
+  def test_vebose_query_logs
+    ActiveRecord::Base.verbose_query_logs = true
+
+    logger = TestDebugLogSubscriber.new
+    logger.sql(Event.new(0, sql: "hi mom!"))
+    assert_match(/↳/, @logger.logged(:debug).last)
+  ensure
+    ActiveRecord::Base.verbose_query_logs = false
+  end
+
+  def test_verbose_query_logs_disabled_by_default
+    logger = TestDebugLogSubscriber.new
+    logger.sql(Event.new(0, sql: "hi mom!"))
+    assert_no_match(/↳/, @logger.logged(:debug).last)
+  end
+
   def test_cached_queries
     ActiveRecord::Base.cache do
       Developer.all.load
diff --git a/railties/lib/rails/generators/rails/app/templates/config/environments/development.rb.tt b/railties/lib/rails/generators/rails/app/templates/config/environments/development.rb.tt
index b383228dc0..961e167d24 100644
--- a/railties/lib/rails/generators/rails/app/templates/config/environments/development.rb.tt
+++ b/railties/lib/rails/generators/rails/app/templates/config/environments/development.rb.tt
@@ -46,6 +46,9 @@ Rails.application.configure do
   # Raise an error on page load if there are pending migrations.
   config.active_record.migration_error = :page_load
 
+  # Highlight code that triggered database queries in logs.
+  config.active_record.verbose_query_logs = true
+
   <%- end -%>
   <%- unless options.skip_sprockets? -%>
   # Debug mode disables concatenation and preprocessing of assets.
diff --git a/railties/lib/rails/generators/rails/app/templates/config/initializers/new_framework_defaults_5_2.rb.tt b/railties/lib/rails/generators/rails/app/templates/config/initializers/new_framework_defaults_5_2.rb.tt
index 25dcddb27a..f630d9985a 100644
--- a/railties/lib/rails/generators/rails/app/templates/config/initializers/new_framework_defaults_5_2.rb.tt
+++ b/railties/lib/rails/generators/rails/app/templates/config/initializers/new_framework_defaults_5_2.rb.tt
@@ -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?
diff --git a/railties/test/application/configuration_test.rb b/railties/test/application/configuration_test.rb
index edb6190ed0..d28f7ffc7f 100644
--- a/railties/test/application/configuration_test.rb
+++ b/railties/test/application/configuration_test.rb
@@ -1317,7 +1317,7 @@ module ApplicationTests
       assert_equal 200, last_response.status
     end
 
-    test "config.action_controller.action_on_unpermitted_parameters is :log by default on development" do
+    test "config.action_controller.action_on_unpermitted_parameters is :log by default in development" do
       app "development"
 
       force_lazy_load_hooks { ActionController::Base }
@@ -1326,7 +1326,7 @@ module ApplicationTests
       assert_equal :log, ActionController::Parameters.action_on_unpermitted_parameters
     end
 
-    test "config.action_controller.action_on_unpermitted_parameters is :log by default on test" do
+    test "config.action_controller.action_on_unpermitted_parameters is :log by default in test" do
       app "test"
 
       force_lazy_load_hooks { ActionController::Base }
@@ -1335,7 +1335,7 @@ module ApplicationTests
       assert_equal :log, ActionController::Parameters.action_on_unpermitted_parameters
     end
 
-    test "config.action_controller.action_on_unpermitted_parameters is false by default on production" do
+    test "config.action_controller.action_on_unpermitted_parameters is false by default in production" do
       app "production"
 
       force_lazy_load_hooks { ActionController::Base }
@@ -1482,12 +1482,18 @@ module ApplicationTests
       assert_not ActiveRecord::Base.dump_schema_after_migration
     end
 
-    test "config.active_record.dump_schema_after_migration is true by default on development" do
+    test "config.active_record.dump_schema_after_migration is true by default in development" do
       app "development"
 
       assert ActiveRecord::Base.dump_schema_after_migration
     end
 
+    test "config.active_record.verbose_query_logs is false by default in development" do
+      app "development"
+
+      assert_not ActiveRecord::Base.verbose_query_logs
+    end
+
     test "config.annotations wrapping SourceAnnotationExtractor::Annotation class" do
       make_basic_app do |application|
         application.config.annotations.register_extensions("coffee") do |tag|
diff --git a/railties/test/application/initializers/notifications_test.rb b/railties/test/application/initializers/notifications_test.rb
index 23b20d578c..c65c955734 100644
--- a/railties/test/application/initializers/notifications_test.rb
+++ b/railties/test/application/initializers/notifications_test.rb
@@ -32,6 +32,7 @@ module ApplicationTests
 
       logger = ActiveSupport::LogSubscriber::TestHelper::MockLogger.new
       ActiveRecord::Base.logger = logger
+      ActiveRecord::Base.verbose_query_logs = false
 
       # Mimic Active Record notifications
       instrument "sql.active_record", name: "SQL", sql: "SHOW tables"