Merge pull request #26815 from olivierlacan/log-query-source

Log the original call site for an ActiveRecord query

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