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

activerecord/CHANGELOG.md

+*   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.

activerecord/lib/active_record/core.rb

@@ -17,6 +17,13 @@ module Core
       # retrieved on both a class and instance level by calling +logger+.
       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.

activerecord/lib/active_record/log_subscriber.rb

@@ -90,6 +90,48 @@ def sql_color(sql)
       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
 

activerecord/test/cases/log_subscriber_test.rb

@@ -33,8 +33,9 @@ def initialize
       super
     end
 
-    def debug(message)
-      @debugs << message
+    def debug(progname = nil, &block)
+      @debugs << progname
+      super
     end
   end
 
@@ -171,6 +172,22 @@ def test_exists_query_logging
     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

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.

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?

railties/test/application/configuration_test.rb

@@ -1317,7 +1317,7 @@ def create
       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 @@ def create
       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 @@ def create
       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 @@ def index
       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|

railties/test/application/initializers/notifications_test.rb

@@ -32,6 +32,7 @@ def wait
 
       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"