Commit 262292f2 authored by Jan Provaznik's avatar Jan Provaznik

Group performance bar SQL queries

Instead of logging each query separately, queries are grouped
by its location (formed by filename and method name). The main
reason is that in Kibana it's not easy to group results by multiple
fields (the only option is using script field)
parent 8017511f
......@@ -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.
......
......@@ -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
......
......@@ -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
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment