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

4 files changed, 80 insertions, 3 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