Merge branch 'ajk-improve-query-backtrace-logging' into 'master'

Ensure we prefix each line when logging the SQL

See merge request gitlab-org/gitlab!59186

spec/support/helpers/query_recorder.rb

@@ -3,37 +3,53 @@
 module ActiveRecord
   class QueryRecorder
     attr_reader :log, :skip_cached, :cached, :data
-    UNKNOWN = %w(unknown unknown).freeze
 
-    def initialize(skip_cached: true, query_recorder_debug: false, &block)
-      @data = Hash.new { |h, k| h[k] = { count: 0, occurrences: [], backtrace: [] } }
+    UNKNOWN = %w[unknown unknown].freeze
+
+    def initialize(skip_cached: true, log_file: nil, query_recorder_debug: false, &block)
+      @data = Hash.new { |h, k| h[k] = { count: 0, occurrences: [], backtrace: [], durations: [] } }
       @log = []
       @cached = []
       @skip_cached = skip_cached
-      @query_recorder_debug = query_recorder_debug
+      @query_recorder_debug = ENV['QUERY_RECORDER_DEBUG'] || query_recorder_debug
+      @log_file = log_file
       # force replacement of bind parameters to give tests the ability to check for ids
       ActiveRecord::Base.connection.unprepared_statement do
         ActiveSupport::Notifications.subscribed(method(:callback), 'sql.active_record', &block)
       end
     end
 
-    def show_backtrace(values)
-      Rails.logger.debug("QueryRecorder SQL: #{values[:sql]}")
+    def show_backtrace(values, duration)
+      values[:sql].lines.each do |line|
+        print_to_log(:SQL, line)
+      end
+      print_to_log(:DURATION, duration)
       Gitlab::BacktraceCleaner.clean_backtrace(caller).each do |line|
-        Rails.logger.debug("QueryRecorder backtrace:  --> #{line}")
+        print_to_log(:backtrace, line)
+      end
+    end
+
+    def print_to_log(label, line)
+      msg = "QueryRecorder #{label}:  --> #{line}"
+
+      if @log_file
+        @log_file.puts(msg)
+      else
+        Rails.logger.debug(msg)
       end
     end
 
     def get_sql_source(sql)
-      matches = sql.match(/,line:(?<line>.*):in\s+`(?<method>.*)'\*\//)
+      matches = sql.match(%r{,line:(?<line>.*):in\s+`(?<method>.*)'\*/})
       matches ? [matches[:line], matches[:method]] : UNKNOWN
     end
 
-    def store_sql_by_source(values: {}, backtrace: nil)
+    def store_sql_by_source(values: {}, duration: nil, backtrace: nil)
       full_name = get_sql_source(values[:sql]).join(':')
       @data[full_name][:count] += 1
       @data[full_name][:occurrences] << values[:sql]
       @data[full_name][:backtrace] << backtrace
+      @data[full_name][:durations] << duration
     end
 
     def find_query(query_regexp, limit, first_only: false)
@@ -55,14 +71,14 @@ module ActiveRecord
     end
 
     def callback(name, start, finish, message_id, values)
-      store_backtrace = ENV['QUERY_RECORDER_DEBUG'] || @query_recorder_debug
-      backtrace = store_backtrace ? show_backtrace(values) : nil
+      duration = finish - start
 
       if values[:cached] && skip_cached
         @cached << values[:sql]
       elsif !values[:name]&.include?("SCHEMA")
+        backtrace = @query_recorder_debug ? show_backtrace(values, duration) : nil
         @log << values[:sql]
-        store_sql_by_source(values: values, backtrace: backtrace)
+        store_sql_by_source(values: values, duration: duration, backtrace: backtrace)
       end
     end
 

spec/support_specs/helpers/active_record/query_recorder_spec.rb

@@ -11,6 +11,72 @@ RSpec.describe ActiveRecord::QueryRecorder do
     end
   end
 
+  describe 'printing to the log' do
+    let(:backtrace) { %r{QueryRecorder backtrace:  --> (\w+/)*\w+\.rb:\d+:in `.*'} }
+    let(:duration_line) { %r{QueryRecorder DURATION:  --> \d+\.\d+} }
+
+    def expect_section(query, lines)
+      query_lines = lines.take(query.size)
+
+      # the query comes first
+      expect(query_lines).to match(query)
+
+      # followed by the duration
+      expect(lines[query.size]).to match(duration_line)
+
+      # and then one or more lines of backtrace
+      backtrace_lines = lines.drop(query.size + 1).take_while { |line| line.match(backtrace) }
+      expect(backtrace_lines).not_to be_empty
+
+      # Advance to the next section
+      lines.drop(query.size + 1 + backtrace_lines.size)
+    end
+
+    it 'prints SQL, duration and backtrace, all prefixed with QueryRecorder', :aggregate_failures do
+      io = StringIO.new
+
+      control = ActiveRecord::QueryRecorder.new(log_file: io, query_recorder_debug: true) do
+        TestQueries.count
+        TestQueries.first
+        TestQueries.where(<<~FRAGMENT).to_a # tests multi-line SQL
+          version = 'foo'
+           OR
+          version = 'bar'
+        FRAGMENT
+      end
+
+      query_a = start_with(%q[QueryRecorder SQL:  --> SELECT COUNT(*) FROM "schema_migrations"])
+
+      query_b = start_with(%q[QueryRecorder SQL:  --> SELECT "schema_migrations".* FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC LIMIT 1])
+
+      query_c_a = eq(%q[QueryRecorder SQL:  --> SELECT "schema_migrations".* FROM "schema_migrations" WHERE (version = 'foo'])
+      query_c_b = eq(%q(QueryRecorder SQL:  -->  OR))
+      query_c_c = eq(%q(QueryRecorder SQL:  --> version = 'bar'))
+      query_c_d = start_with("QueryRecorder SQL:  --> )")
+
+      expect(control.count).to eq(3)
+
+      lines = io.string.lines.map(&:chomp)
+
+      expect(lines).to all(start_with('QueryRecorder'))
+      lines = expect_section([query_a], lines)
+      lines = expect_section([query_b], lines)
+      lines = expect_section([query_c_a, query_c_b, query_c_c, query_c_d], lines)
+
+      expect(lines).to be_empty
+    end
+  end
+
+  it 'includes duration information' do
+    control = ActiveRecord::QueryRecorder.new do
+      TestQueries.count
+      TestQueries.first
+    end
+
+    expect(control.count).to eq(2)
+    expect(control.data.values.flat_map { _1[:durations] }).to match([be > 0, be > 0])
+  end
+
   describe 'detecting the right number of calls and their origin' do
     it 'detects two separate queries' do
       control = ActiveRecord::QueryRecorder.new query_recorder_debug: true do
@@ -23,10 +89,10 @@ RSpec.describe ActiveRecord::QueryRecorder do
         .to eq(control.data.keys.size)
       # Ensure exactly 2 COUNT queries were detected
       expect(control.occurrences_by_line_method.last[1][:occurrences]
-               .find_all {|i| i.match(/SELECT COUNT/) }.count).to eq(2)
+               .count { |str| str.start_with?('SELECT COUNT') }).to eq(2)
       # Ensure exactly 1 LIMIT 1 (#first)
       expect(control.occurrences_by_line_method.first[1][:occurrences]
-               .find_all { |i| i.match(/ORDER BY.*#{TestQueries.table_name}.*LIMIT 1/) }.count).to eq(1)
+               .count { |str| str.match(/ORDER BY.*#{TestQueries.table_name}.*LIMIT 1/) }).to eq(1)
 
       # Ensure 3 DB calls overall were executed
       expect(control.log.size).to eq(3)