Merge branch 'perfbar_grouping' into 'master'

Group performance bar SQL queries by location

See merge request gitlab-org/gitlab!52678

doc/administration/logs.md

@@ -1006,7 +1006,7 @@ installations from source.
 Performance bar statistics (currently only duration of SQL queries) are recorded in that file. For example:
 
 ```json
-{"severity":"INFO","time":"2020-12-04T09:29:44.592Z","correlation_id":"33680b1490ccd35981b03639c406a697","filename":"app/models/ci/pipeline.rb","filenum":"395","method":"each_with_object","request_id":"rYHomD0VJS4","duration_ms":26.889,"type": "sql"}
+{"severity":"INFO","time":"2020-12-04T09:29:44.592Z","correlation_id":"33680b1490ccd35981b03639c406a697","filename":"app/models/ci/pipeline.rb","method_path":"app/models/ci/pipeline.rb:each_with_object","request_id":"rYHomD0VJS4","duration_ms":26.889,"count":2,"type": "sql"}
 ```
 
 These statistics are logged on .com only, disabled on self-deployments.

lib/gitlab/performance_bar/stats.rb

@@ -27,27 +27,40 @@ module Gitlab
       end
 
       def log_sql_queries(id, data)
-        return [] unless queries = data.dig('data', 'active-record', 'details')
-
-        queries.each do |query|
-          next unless location = parse_backtrace(query['backtrace'])
+        queries_by_location(data).each do |location, queries|
+          next unless location
 
-          log_info = location.merge(
+          duration = queries.sum { |query| query['duration'].to_f }
+          log_info = {
+            method_path: "#{location[:filename]}:#{location[:method]}",
+            filename: location[:filename],
             type: :sql,
             request_id: id,
-            duration_ms: query['duration'].to_f
-          )
+            count: queries.count,
+            duration_ms: duration
+          }
 
           logger.info(log_info)
         end
       end
 
+      def queries_by_location(data)
+        return [] unless queries = data.dig('data', 'active-record', 'details')
+
+        queries.group_by do |query|
+          parse_backtrace(query['backtrace'])
+        end
+      end
+
       def parse_backtrace(backtrace)
         return unless match = /(?<filename>.*):(?<filenum>\d+):in `(?<method>.*)'/.match(backtrace.first)
 
         {
           filename: match[:filename],
-          filenum: match[:filenum].to_i,
+          # filenum may change quite frequently with every change in the file,
+          # because the intention is to aggregate these queries, we group
+          # them rather by method name which should not change so frequently
+          # filenum: match[:filenum].to_i,
           method: match[:method]
         }
       end

spec/lib/gitlab/performance_bar/stats_spec.rb

@@ -22,10 +22,12 @@ RSpec.describe Gitlab::PerformanceBar::Stats do
 
         expect(logger).to receive(:info)
           .with({ duration_ms: 1.096, filename: 'lib/gitlab/pagination/offset_pagination.rb',
-                  filenum: 53, method: 'add_pagination_headers', request_id: 'foo', type: :sql })
+                  method_path: 'lib/gitlab/pagination/offset_pagination.rb:add_pagination_headers',
+                  count: 1, request_id: 'foo', type: :sql })
         expect(logger).to receive(:info)
-          .with({ duration_ms: 0.817, filename: 'lib/api/helpers.rb',
-                  filenum: 112, method: 'find_project', request_id: 'foo', type: :sql }).twice
+          .with({ duration_ms: 1.634, filename: 'lib/api/helpers.rb',
+                  method_path: 'lib/api/helpers.rb:find_project',
+                  count: 2, request_id: 'foo', type: :sql })
 
         subject
       end