DEV: Add output_sql_to_stderr! to MethodProfiler (#12445)

This PR adds MethodProfiler.output_sql_to_stderr! for easier debugging of SQL queries and their timings from the console.

This is almost the same as ensure_discourse_instrumentation! but should not
be used in production (save for debugging in the console), and is only instrumenting
PostgresSQL queries.

This is almost the same as ensure_discourse_instrumentation! but should not
be used in production. This logs all SQL queries run and their durations
between start and stop.

It also works for super long running queries. If you interrupt the long-running
query the latest query data will still be logged after stopping the profiler.

Usage:

```
MethodProfiler.output_sql_to_stderr!(filter_transactions: true)
MethodProfiler.start

# some code that runs queries

timings = MethodProfiler.stop
```
This commit is contained in:
Martin Brennan 2021-03-19 17:48:30 +10:00 committed by GitHub
parent b432a4acd8
commit fb0b4e26a9
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23

View File

@ -38,6 +38,50 @@ class MethodProfiler
klass.class_eval patches klass.class_eval patches
end end
def self.patch_with_debug_sql(klass, methods, name, no_recurse: false)
patches = methods.map do |method_name|
recurse_protection = ""
if no_recurse
recurse_protection = <<~RUBY
return #{method_name}__mp_unpatched_debug_sql(*args, &blk) if @mp_recurse_protect_#{method_name}
@mp_recurse_protect_#{method_name} = true
RUBY
end
<<~RUBY
unless defined?(#{method_name}__mp_unpatched_debug_sql)
alias_method :#{method_name}__mp_unpatched_debug_sql, :#{method_name}
def #{method_name}(*args, &blk)
#{recurse_protection}
query = args[0]
should_filter = #{@@instrumentation_debug_sql_filter_transactions} &&
(query == "COMMIT" || query == "BEGIN" || query == "ROLLBACK")
if !should_filter
STDERR.puts "debugsql (sql): " + query
end
begin
start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
#{method_name}__mp_unpatched_debug_sql(*args, &blk)
ensure
duration = Process.clock_gettime(Process::CLOCK_MONOTONIC) - start
if !should_filter
STDERR.puts "debugsql (sec): " + duration.round(3).to_s
end
#{"@mp_recurse_protect_#{method_name} = false" if no_recurse}
end
end
end
RUBY
end.join("\n")
klass.class_eval patches
end
def self.transfer def self.transfer
result = Thread.current[:_method_profiler] result = Thread.current[:_method_profiler]
Thread.current[:_method_profiler] = nil Thread.current[:_method_profiler] = nil
@ -64,6 +108,24 @@ class MethodProfiler
data data
end end
##
# This is almost the same as ensure_discourse_instrumentation! but should not
# be used in production. This logs all SQL queries run and their durations
# between start and stop.
#
# filter_transactions - When true, we do not record timings of transaction
# related commits (BEGIN, COMMIT, ROLLBACK)
def self.output_sql_to_stderr!(filter_transactions: false)
Rails.logger.warn("Stop! This instrumentation is not intended for use in production outside of debugging scenarios. Please be sure you know what you are doing when enabling this instrumentation.")
@@instrumentation_debug_sql_filter_transactions = filter_transactions
@@instrumentation_setup_debug_sql ||= begin
MethodProfiler.patch_with_debug_sql(PG::Connection, [
:exec, :async_exec, :exec_prepared, :send_query_prepared, :query, :exec_params
], :sql)
true
end
end
def self.ensure_discourse_instrumentation! def self.ensure_discourse_instrumentation!
@@instrumentation_setup ||= begin @@instrumentation_setup ||= begin
MethodProfiler.patch(PG::Connection, [ MethodProfiler.patch(PG::Connection, [