diff options
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" |