mirror of
https://github.com/discourse/discourse.git
synced 2024-12-12 20:53:44 +08:00
fb0b4e26a9
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 ```
151 lines
4.7 KiB
Ruby
151 lines
4.7 KiB
Ruby
# frozen_string_literal: true
|
|
|
|
# see https://samsaffron.com/archive/2017/10/18/fastest-way-to-profile-a-method-in-ruby
|
|
class MethodProfiler
|
|
def self.patch(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(*args, &blk) if @mp_recurse_protect_#{method_name}
|
|
@mp_recurse_protect_#{method_name} = true
|
|
RUBY
|
|
end
|
|
|
|
<<~RUBY
|
|
unless defined?(#{method_name}__mp_unpatched)
|
|
alias_method :#{method_name}__mp_unpatched, :#{method_name}
|
|
def #{method_name}(*args, &blk)
|
|
unless prof = Thread.current[:_method_profiler]
|
|
return #{method_name}__mp_unpatched(*args, &blk)
|
|
end
|
|
#{recurse_protection}
|
|
begin
|
|
start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
|
|
#{method_name}__mp_unpatched(*args, &blk)
|
|
ensure
|
|
data = (prof[:#{name}] ||= {duration: 0.0, calls: 0})
|
|
data[:duration] += Process.clock_gettime(Process::CLOCK_MONOTONIC) - start
|
|
data[:calls] += 1
|
|
#{"@mp_recurse_protect_#{method_name} = false" if no_recurse}
|
|
end
|
|
end
|
|
end
|
|
RUBY
|
|
end.join("\n")
|
|
|
|
klass.class_eval patches
|
|
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
|
|
result = Thread.current[:_method_profiler]
|
|
Thread.current[:_method_profiler] = nil
|
|
result
|
|
end
|
|
|
|
def self.start(transfer = nil)
|
|
Thread.current[:_method_profiler] = transfer || {
|
|
__start: Process.clock_gettime(Process::CLOCK_MONOTONIC)
|
|
}
|
|
end
|
|
|
|
def self.clear
|
|
Thread.current[:_method_profiler] = nil
|
|
end
|
|
|
|
def self.stop
|
|
finish = Process.clock_gettime(Process::CLOCK_MONOTONIC)
|
|
if data = Thread.current[:_method_profiler]
|
|
Thread.current[:_method_profiler] = nil
|
|
start = data.delete(:__start)
|
|
data[:total_duration] = finish - start
|
|
end
|
|
data
|
|
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!
|
|
@@instrumentation_setup ||= begin
|
|
MethodProfiler.patch(PG::Connection, [
|
|
:exec, :async_exec, :exec_prepared, :send_query_prepared, :query, :exec_params
|
|
], :sql)
|
|
|
|
MethodProfiler.patch(Redis::Client, [
|
|
:call, :call_pipeline
|
|
], :redis)
|
|
|
|
MethodProfiler.patch(Net::HTTP, [
|
|
:request
|
|
], :net, no_recurse: true)
|
|
|
|
MethodProfiler.patch(Excon::Connection, [
|
|
:request
|
|
], :net)
|
|
true
|
|
end
|
|
end
|
|
|
|
end
|