From fb0b4e26a960c4eb06733a570a213fe63b453c20 Mon Sep 17 00:00:00 2001
From: Martin Brennan <mjrbrennan@gmail.com>
Date: Fri, 19 Mar 2021 17:48:30 +1000
Subject: [PATCH] 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
```
---
 lib/method_profiler.rb | 62 ++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 62 insertions(+)

diff --git a/lib/method_profiler.rb b/lib/method_profiler.rb
index 3e4c841419b..fd6588c6bc7 100644
--- a/lib/method_profiler.rb
+++ b/lib/method_profiler.rb
@@ -38,6 +38,50 @@ class MethodProfiler
     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
@@ -64,6 +108,24 @@ class MethodProfiler
     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, [