Commit d8d05022 authored by Alex Kalderimis's avatar Alex Kalderimis

Record logs in query limiting middleware

This test support system helps us detect expensive endpoints. This
change adds sufficient information to assess what the cause of the
excessive queries is. To avoid storing unbounded numbers of queries,
only the first 1.5x the threshold queries are recorded.
parent 23c99671
......@@ -6,9 +6,10 @@ module Gitlab
attach_to :active_record
def sql(event)
unless event.payload.fetch(:cached, event.payload[:name] == 'CACHE')
Transaction.current&.increment
end
return if !Transaction.current || event.payload.fetch(:cached, event.payload[:name] == 'CACHE')
Transaction.current.increment
Transaction.current.executed_sql(event.payload[:sql])
end
end
end
......
......@@ -15,6 +15,7 @@ module Gitlab
# the sake of keeping things simple we hardcode this value here, it's not
# supposed to be changed very often anyway.
THRESHOLD = 100
LOG_THRESHOLD = THRESHOLD * 1.5
# Error that is raised whenever exceeding the maximum number of queries.
ThresholdExceededError = Class.new(StandardError)
......@@ -45,6 +46,7 @@ module Gitlab
@action = nil
@count = 0
@whitelisted = false
@sql_executed = []
end
# Sends a notification based on the number of executed SQL queries.
......@@ -60,6 +62,10 @@ module Gitlab
@count += 1 unless whitelisted
end
def executed_sql(sql)
@sql_executed << sql unless @count > LOG_THRESHOLD
end
def raise_error?
Rails.env.test?
end
......@@ -71,8 +77,11 @@ module Gitlab
def error_message
header = 'Too many SQL queries were executed'
header = "#{header} in #{action}" if action
msg = "a maximum of #{THRESHOLD} is allowed but #{count} SQL queries were executed"
log = @sql_executed.each_with_index.map { |sql, i| "#{i}: #{sql}" }.join("\n").presence
ellipsis = '...' if @count > LOG_THRESHOLD
"#{header}: a maximum of #{THRESHOLD} is allowed but #{count} SQL queries were executed"
["#{header}: #{msg}", log, ellipsis].compact.join("\n")
end
end
end
......
......@@ -3,7 +3,7 @@
require 'spec_helper'
RSpec.describe Gitlab::QueryLimiting::ActiveSupportSubscriber do
let(:transaction) { instance_double(Gitlab::QueryLimiting::Transaction, increment: true) }
let(:transaction) { instance_double(Gitlab::QueryLimiting::Transaction, executed_sql: true, increment: true) }
before do
allow(Gitlab::QueryLimiting::Transaction)
......@@ -18,6 +18,11 @@ RSpec.describe Gitlab::QueryLimiting::ActiveSupportSubscriber do
expect(transaction)
.to have_received(:increment)
.once
expect(transaction)
.to have_received(:executed_sql)
.once
.with(String)
end
context 'when the query is actually a rails cache hit' do
......@@ -30,6 +35,11 @@ RSpec.describe Gitlab::QueryLimiting::ActiveSupportSubscriber do
expect(transaction)
.to have_received(:increment)
.once
expect(transaction)
.to have_received(:executed_sql)
.once
.with(String)
end
end
end
......
......@@ -118,6 +118,30 @@ RSpec.describe Gitlab::QueryLimiting::Transaction do
)
end
it 'includes a list of executed queries' do
transaction = described_class.new
transaction.count = max = described_class::THRESHOLD
%w[foo bar baz].each { |sql| transaction.executed_sql(sql) }
message = transaction.error_message
expect(message).to start_with(
"Too many SQL queries were executed: a maximum of #{max} " \
"is allowed but #{max} SQL queries were executed"
)
expect(message).to include("0: foo", "1: bar", "2: baz")
end
it 'indicates if the log is truncated' do
transaction = described_class.new
transaction.count = described_class::THRESHOLD * 2
message = transaction.error_message
expect(message).to end_with('...')
end
it 'includes the action name in the error message when present' do
transaction = described_class.new
transaction.count = max = described_class::THRESHOLD
......
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