Permalink
Browse files

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

Log the original call site for an ActiveRecord query
  • Loading branch information...
eileencodes committed Dec 14, 2017
2 parents 245c1da + 3876def commit 4bd28efc189cf58891ece9d57d44994039054ca0
View
@@ -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.
@@ -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.
@@ -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
@@ -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
@@ -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.
@@ -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?
@@ -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|
@@ -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"

0 comments on commit 4bd28ef

Please sign in to comment.