Merge pull request rails#49095 from Shopify/activerecord-lazy-query-source

Optimize ActiveRecord::LogSubscriber#query_source_location

Author: byroot

activerecord/lib/active_record/log_subscriber.rb

@@ -140,15 +140,25 @@ def debug(progname = nil, &block)
       end
 
       def log_query_source
-        source = extract_query_source_location(caller)
+        source = query_source_location
 
         if source
           logger.debug("  ↳ #{source}")
         end
       end
 
-      def extract_query_source_location(locations)
-        backtrace_cleaner.clean(locations.lazy).first
+      if Thread.respond_to?(:each_caller_location)
+        def query_source_location
+          Thread.each_caller_location do |location|
+            frame = backtrace_cleaner.clean_frame(location)
+            return frame if frame
+          end
+          nil
+        end
+      else
+        def query_source_location
+          backtrace_cleaner.clean(caller(1).lazy).first
+        end
       end
 
       def filter(name, value)

activerecord/test/cases/log_subscriber_test.rb

@@ -204,7 +204,7 @@ def test_verbose_query_with_ignored_callstack
     ActiveRecord.verbose_query_logs = true
 
     logger = TestDebugLogSubscriber.new
-    def logger.extract_query_source_location(*); nil; end
+    def logger.query_source_location; nil; end
 
     logger.sql(Event.new(0, sql: "hi mom!"))
     assert_equal 1, @logger.logged(:debug).size

activesupport/lib/active_support/backtrace_cleaner.rb

@@ -54,6 +54,24 @@ def clean(backtrace, kind = :silent)
     end
     alias :filter :clean
 
+    # Returns the frame with all filters applied.
+    # returns +nil+ if the frame was silenced.
+    def clean_frame(frame, kind = :silent)
+      frame = frame.to_s
+      @filters.each do |f|
+        frame = f.call(frame.to_s)
+      end
+
+      case kind
+      when :silent
+        frame unless @silencers.any? { |s| s.call(frame) }
+      when :noise
+        frame if @silencers.any? { |s| s.call(frame) }
+      else
+        frame
+      end
+    end
+
     # Adds a filter from the block provided. Each line in the backtrace will be
     # mapped against this filter.
     #

railties/test/backtrace_cleaner_test.rb

@@ -8,7 +8,7 @@ def setup
     @cleaner = Rails::BacktraceCleaner.new
   end
 
-  test "should consider traces from irb lines as User code" do
+  test "#clean should consider traces from irb lines as User code" do
     backtrace = [ "(irb):1",
                   "/Path/to/rails/railties/lib/rails/commands/console.rb:77:in `start'",
                   "bin/rails:4:in `<main>'" ]
@@ -17,7 +17,7 @@ def setup
     assert_equal 1, result.length
   end
 
-  test "should show relative paths" do
+  test "#clean should show relative paths" do
     backtrace = [ "./test/backtrace_cleaner_test.rb:123",
                   "/Path/to/rails/activesupport/some_testing_file.rb:42:in `test'",
                   "bin/rails:4:in `<main>'" ]
@@ -26,7 +26,7 @@ def setup
     assert_equal 1, result.length
   end
 
-  test "can filter for noise" do
+  test "#clean can filter for noise" do
     backtrace = [ "(irb):1",
                   "/Path/to/rails/railties/lib/rails/commands/console.rb:77:in `start'",
                   "bin/rails:4:in `<main>'" ]
@@ -36,10 +36,35 @@ def setup
     assert_equal 2, result.length
   end
 
-  test "should omit ActionView template methods names" do
+  test "#clean should omit ActionView template methods names" do
     method_name = ActionView::Template.new(nil, "app/views/application/index.html.erb", nil, locals: []).send :method_name
     backtrace = [ "app/views/application/index.html.erb:4:in `block in #{method_name}'"]
     result = @cleaner.clean(backtrace, :all)
     assert_equal "app/views/application/index.html.erb:4", result[0]
   end
+
+  test "#clean_frame should consider traces from irb lines as User code" do
+    assert_equal "(irb):1", @cleaner.clean_frame("(irb):1")
+    assert_nil @cleaner.clean_frame("/Path/to/rails/railties/lib/rails/commands/console.rb:77:in `start'")
+    assert_nil @cleaner.clean_frame("bin/rails:4:in `<main>'")
+  end
+
+  test "#clean_frame should show relative paths" do
+    assert_equal "./test/backtrace_cleaner_test.rb:123", @cleaner.clean_frame("./test/backtrace_cleaner_test.rb:123")
+    assert_nil @cleaner.clean_frame("/Path/to/rails/railties/lib/rails/commands/console.rb:77:in `start'")
+    assert_nil @cleaner.clean_frame("bin/rails:4:in `<main>'")
+  end
+
+  test "#clean_frame can filter for noise" do
+    assert_nil @cleaner.clean_frame("(irb):1", :noise)
+    frame = @cleaner.clean_frame("/Path/to/rails/railties/lib/rails/commands/console.rb:77:in `start'", :noise)
+    assert_equal "/Path/to/rails/railties/lib/rails/commands/console.rb:77:in `start'", frame
+    assert_equal "bin/rails:4:in `<main>'", @cleaner.clean_frame("bin/rails:4:in `<main>'", :noise)
+  end
+
+  test "#clean_frame should omit ActionView template methods names" do
+    method_name = ActionView::Template.new(nil, "app/views/application/index.html.erb", nil, locals: []).send :method_name
+    frame = @cleaner.clean_frame("app/views/application/index.html.erb:4:in `block in #{method_name}'", :all)
+    assert_equal "app/views/application/index.html.erb:4", frame
+  end
 end