Commit 8f01bbe8 authored by Sean McGivern's avatar Sean McGivern

Remove Rails background transaction metrics

We don't need these as we have Sidekiq-specific metrics. Having these
metrics with Sidekiq labels also increases cardinality.

We keep the DB counters in logs for Sidekiq, but remove them from
metrics too.
parent 1d6b538f
...@@ -2,7 +2,6 @@ ...@@ -2,7 +2,6 @@
unless Gitlab::Runtime.sidekiq? unless Gitlab::Runtime.sidekiq?
Rails.application.reloader.to_prepare do Rails.application.reloader.to_prepare do
filename = File.join(Rails.root, 'log', "#{Rails.env}_json.log") filename = File.join(Rails.root, 'log', "#{Rails.env}_json.log")
db_counter = Gitlab::Metrics::Subscribers::ActiveRecord
Rails.application.configure do Rails.application.configure do
config.lograge.enabled = true config.lograge.enabled = true
...@@ -17,7 +16,6 @@ unless Gitlab::Runtime.sidekiq? ...@@ -17,7 +16,6 @@ unless Gitlab::Runtime.sidekiq?
data[:db_duration_s] = Gitlab::Utils.ms_to_round_sec(data.delete(:db)) if data[:db] data[:db_duration_s] = Gitlab::Utils.ms_to_round_sec(data.delete(:db)) if data[:db]
data[:view_duration_s] = Gitlab::Utils.ms_to_round_sec(data.delete(:view)) if data[:view] data[:view_duration_s] = Gitlab::Utils.ms_to_round_sec(data.delete(:view)) if data[:view]
data[:duration_s] = Gitlab::Utils.ms_to_round_sec(data.delete(:duration)) if data[:duration] data[:duration_s] = Gitlab::Utils.ms_to_round_sec(data.delete(:duration)) if data[:duration]
data.merge!(db_counter.db_counter_payload)
# Remove empty hashes to prevent type mismatches # Remove empty hashes to prevent type mismatches
# These are set to empty hashes in Lograge's ActionCable subscriber # These are set to empty hashes in Lograge's ActionCable subscriber
......
...@@ -150,12 +150,6 @@ if Gitlab::Metrics.enabled? && !Rails.env.test? && !(Rails.env.development? && d ...@@ -150,12 +150,6 @@ if Gitlab::Metrics.enabled? && !Rails.env.test? && !(Rails.env.development? && d
config.middleware.use(Gitlab::Metrics::ElasticsearchRackMiddleware) config.middleware.use(Gitlab::Metrics::ElasticsearchRackMiddleware)
end end
Sidekiq.configure_server do |config|
config.server_middleware do |chain|
chain.add Gitlab::Metrics::SidekiqMiddleware
end
end
# This instruments all methods residing in app/models that (appear to) use any # This instruments all methods residing in app/models that (appear to) use any
# of the ActiveRecord methods. This has to take place _after_ initializing as # of the ActiveRecord methods. This has to take place _after_ initializing as
# for some unknown reason calling eager_load! earlier breaks Devise. # for some unknown reason calling eager_load! earlier breaks Devise.
......
...@@ -13,7 +13,8 @@ module Gitlab ...@@ -13,7 +13,8 @@ module Gitlab
:rugged_duration_s, :rugged_duration_s,
:elasticsearch_calls, :elasticsearch_calls,
:elasticsearch_duration_s, :elasticsearch_duration_s,
*::Gitlab::Instrumentation::Redis.known_payload_keys] *::Gitlab::Instrumentation::Redis.known_payload_keys,
*::Gitlab::Metrics::Subscribers::ActiveRecord::DB_COUNTERS]
end end
def add_instrumentation_data(payload) def add_instrumentation_data(payload)
...@@ -22,6 +23,7 @@ module Gitlab ...@@ -22,6 +23,7 @@ module Gitlab
instrument_redis(payload) instrument_redis(payload)
instrument_elasticsearch(payload) instrument_elasticsearch(payload)
instrument_throttle(payload) instrument_throttle(payload)
instrument_active_record(payload)
end end
def instrument_gitaly(payload) def instrument_gitaly(payload)
...@@ -62,6 +64,12 @@ module Gitlab ...@@ -62,6 +64,12 @@ module Gitlab
payload[:throttle_safelist] = safelist if safelist.present? payload[:throttle_safelist] = safelist if safelist.present?
end end
def instrument_active_record(payload)
db_counters = ::Gitlab::Metrics::Subscribers::ActiveRecord.db_counter_payload
payload.merge!(db_counters)
end
# Returns the queuing duration for a Sidekiq job in seconds, as a float, if the # Returns the queuing duration for a Sidekiq job in seconds, as a float, if the
# `enqueued_at` field or `created_at` field is available. # `enqueued_at` field or `created_at` field is available.
# #
......
# frozen_string_literal: true
module Gitlab
module Metrics
class BackgroundTransaction < Transaction
def initialize(worker_class)
super()
@worker_class = worker_class
end
def labels
{ controller: @worker_class.name, action: 'perform', feature_category: @worker_class.try(:get_feature_category).to_s }
end
end
end
end
# frozen_string_literal: true
module Gitlab
module Metrics
# Sidekiq middleware for tracking jobs.
#
# This middleware is intended to be used as a server-side middleware.
class SidekiqMiddleware
def call(worker, payload, queue)
trans = BackgroundTransaction.new(worker.class)
begin
# Old gitlad-shell messages don't provide enqueued_at/created_at attributes
enqueued_at = payload['enqueued_at'] || payload['created_at'] || 0
trans.set(:gitlab_transaction_sidekiq_queue_duration_total, Time.current.to_f - enqueued_at) do
multiprocess_mode :livesum
end
trans.run { yield }
rescue Exception => error # rubocop: disable Lint/RescueException
trans.add_event(:sidekiq_exception)
raise error
ensure
add_info_to_payload(payload, trans)
end
end
private
def add_info_to_payload(payload, trans)
payload.merge!(::Gitlab::Metrics::Subscribers::ActiveRecord.db_counter_payload)
end
end
end
end
...@@ -16,16 +16,14 @@ module Gitlab ...@@ -16,16 +16,14 @@ module Gitlab
# using a connection. # using a connection.
Thread.current[:uses_db_connection] = true Thread.current[:uses_db_connection] = true
return unless current_transaction
payload = event.payload payload = event.payload
return if payload[:name] == 'SCHEMA' || IGNORABLE_SQL.include?(payload[:sql]) return if payload[:name] == 'SCHEMA' || IGNORABLE_SQL.include?(payload[:sql])
current_transaction.observe(:gitlab_sql_duration_seconds, event.duration / 1000.0) do increment_db_counters(payload)
current_transaction&.observe(:gitlab_sql_duration_seconds, event.duration / 1000.0) do
buckets [0.05, 0.1, 0.25] buckets [0.05, 0.1, 0.25]
end end
increment_db_counters(payload)
end end
def self.db_counter_payload def self.db_counter_payload
...@@ -53,7 +51,7 @@ module Gitlab ...@@ -53,7 +51,7 @@ module Gitlab
end end
def increment(counter) def increment(counter)
current_transaction.increment("gitlab_transaction_#{counter}_total".to_sym, 1) current_transaction&.increment("gitlab_transaction_#{counter}_total".to_sym, 1)
if Gitlab::SafeRequestStore.active? if Gitlab::SafeRequestStore.active?
Gitlab::SafeRequestStore[counter] = Gitlab::SafeRequestStore[counter].to_i + 1 Gitlab::SafeRequestStore[counter] = Gitlab::SafeRequestStore[counter].to_i + 1
......
...@@ -153,32 +153,22 @@ RSpec.describe 'lograge', type: :request do ...@@ -153,32 +153,22 @@ RSpec.describe 'lograge', type: :request do
end end
end end
context 'with transaction' do context 'with db payload' do
let(:transaction) { Gitlab::Metrics::WebTransaction.new({}) }
before do
allow(Gitlab::Metrics::Transaction).to receive(:current).and_return(transaction)
end
context 'when RequestStore is enabled', :request_store do context 'when RequestStore is enabled', :request_store do
context 'with db payload' do it 'includes db counters' do
it 'includes db counters', :request_store do ActiveRecord::Base.connection.execute('SELECT pg_sleep(0.1);')
ActiveRecord::Base.connection.execute('SELECT pg_sleep(0.1);') subscriber.process_action(event)
subscriber.process_action(event)
expect(log_data).to include("db_count" => 1, "db_write_count" => 0, "db_cached_count" => 0) expect(log_data).to include("db_count" => a_value >= 1, "db_write_count" => 0, "db_cached_count" => 0)
end
end end
end end
context 'when RequestStore is disabled' do context 'when RequestStore is disabled' do
context 'with db payload' do it 'does not include db counters' do
it 'does not include db counters' do ActiveRecord::Base.connection.execute('SELECT pg_sleep(0.1);')
ActiveRecord::Base.connection.execute('SELECT pg_sleep(0.1);') subscriber.process_action(event)
subscriber.process_action(event)
expect(log_data).not_to include("db_count" => 1, "db_write_count" => 0, "db_cached_count" => 0) expect(log_data).not_to include("db_count", "db_write_count", "db_cached_count")
end
end end
end end
end end
......
...@@ -34,7 +34,10 @@ RSpec.describe Gitlab::InstrumentationHelper do ...@@ -34,7 +34,10 @@ RSpec.describe Gitlab::InstrumentationHelper do
:redis_shared_state_calls, :redis_shared_state_calls,
:redis_shared_state_duration_s, :redis_shared_state_duration_s,
:redis_shared_state_read_bytes, :redis_shared_state_read_bytes,
:redis_shared_state_write_bytes :redis_shared_state_write_bytes,
:db_count,
:db_write_count,
:db_cached_count
] ]
expect(described_class.keys).to eq(expected_keys) expect(described_class.keys).to eq(expected_keys)
...@@ -46,10 +49,10 @@ RSpec.describe Gitlab::InstrumentationHelper do ...@@ -46,10 +49,10 @@ RSpec.describe Gitlab::InstrumentationHelper do
subject { described_class.add_instrumentation_data(payload) } subject { described_class.add_instrumentation_data(payload) }
it 'adds nothing' do it 'adds only DB counts by default' do
subject subject
expect(payload).to eq({}) expect(payload).to eq(db_count: 0, db_cached_count: 0, db_write_count: 0)
end end
context 'when Gitaly calls are made' do context 'when Gitaly calls are made' do
......
# frozen_string_literal: true
require 'spec_helper'
RSpec.describe Gitlab::Metrics::BackgroundTransaction do
let(:test_worker_class) { double(:class, name: 'TestWorker') }
let(:prometheus_metric) { instance_double(Prometheus::Client::Metric, base_labels: {}) }
before do
allow(described_class).to receive(:prometheus_metric).and_return(prometheus_metric)
end
subject { described_class.new(test_worker_class) }
RSpec.shared_examples 'metric with worker labels' do |metric_method|
it 'measures with correct labels and value' do
value = 1
expect(prometheus_metric).to receive(metric_method).with({ controller: 'TestWorker', action: 'perform', feature_category: '' }, value)
subject.send(metric_method, :bau, value)
end
end
describe '#label' do
it 'returns labels based on class name' do
expect(subject.labels).to eq(controller: 'TestWorker', action: 'perform', feature_category: '')
end
it 'contains only the labels defined for metrics' do
expect(subject.labels.keys).to contain_exactly(*described_class.superclass::BASE_LABEL_KEYS)
end
it 'includes the feature category if there is one' do
expect(test_worker_class).to receive(:get_feature_category).and_return('source_code_management')
expect(subject.labels).to include(feature_category: 'source_code_management')
end
end
describe '#increment' do
let(:prometheus_metric) { instance_double(Prometheus::Client::Counter, :increment, base_labels: {}) }
it_behaves_like 'metric with worker labels', :increment
end
describe '#set' do
let(:prometheus_metric) { instance_double(Prometheus::Client::Gauge, :set, base_labels: {}) }
it_behaves_like 'metric with worker labels', :set
end
describe '#observe' do
let(:prometheus_metric) { instance_double(Prometheus::Client::Histogram, :observe, base_labels: {}) }
it_behaves_like 'metric with worker labels', :observe
end
end
# frozen_string_literal: true
require 'spec_helper'
RSpec.describe Gitlab::Metrics::SidekiqMiddleware do
let(:middleware) { described_class.new }
let(:message) { { 'args' => ['test'], 'enqueued_at' => Time.new(2016, 6, 23, 6, 59).to_f } }
describe '#call' do
it 'tracks the transaction' do
worker = double(:worker, class: double(:class, name: 'TestWorker'))
expect_next_instance_of(Gitlab::Metrics::BackgroundTransaction) do |transaction|
expect(transaction).to receive(:set).with(:gitlab_transaction_sidekiq_queue_duration_total, instance_of(Float))
expect(transaction).to receive(:increment).with(:gitlab_transaction_db_count_total, 1)
end
middleware.call(worker, message, :test) do
ActiveRecord::Base.connection.execute('SELECT pg_sleep(0.1);')
end
end
it 'prevents database counters from leaking to the next transaction' do
worker = double(:worker, class: double(:class, name: 'TestWorker'))
2.times do
Gitlab::WithRequestStore.with_request_store do
middleware.call(worker, message, :test) do
ActiveRecord::Base.connection.execute('SELECT pg_sleep(0.1);')
end
end
end
expect(message).to include(db_count: 1, db_write_count: 0, db_cached_count: 0)
end
it 'tracks the transaction (for messages without `enqueued_at`)', :aggregate_failures do
worker = double(:worker, class: double(:class, name: 'TestWorker'))
expect(Gitlab::Metrics::BackgroundTransaction).to receive(:new)
.with(worker.class)
.and_call_original
expect_any_instance_of(Gitlab::Metrics::Transaction).to receive(:set)
.with(:gitlab_transaction_sidekiq_queue_duration_total, instance_of(Float))
middleware.call(worker, {}, :test) { nil }
end
it 'tracks any raised exceptions', :aggregate_failures, :request_store do
worker = double(:worker, class: double(:class, name: 'TestWorker'))
expect_any_instance_of(Gitlab::Metrics::Transaction)
.to receive(:add_event).with(:sidekiq_exception)
expect do
middleware.call(worker, message, :test) do
ActiveRecord::Base.connection.execute('SELECT pg_sleep(0.1);')
raise RuntimeError
end
end.to raise_error(RuntimeError)
expect(message).to include(db_count: 1, db_write_count: 0, db_cached_count: 0)
end
end
end
...@@ -18,59 +18,73 @@ RSpec.describe Gitlab::Metrics::Subscribers::ActiveRecord do ...@@ -18,59 +18,73 @@ RSpec.describe Gitlab::Metrics::Subscribers::ActiveRecord do
end end
describe '#sql' do describe '#sql' do
describe 'without a current transaction' do shared_examples 'track query in metrics' do
it 'simply returns' do before do
expect_any_instance_of(Gitlab::Metrics::Transaction) allow(subscriber).to receive(:current_transaction)
.not_to receive(:increment) .at_least(:once)
.and_return(transaction)
end
it 'increments only db count value' do
described_class::DB_COUNTERS.each do |counter|
prometheus_counter = "gitlab_transaction_#{counter}_total".to_sym
if expected_counters[counter] > 0
expect(transaction).to receive(:increment).with(prometheus_counter, 1)
else
expect(transaction).not_to receive(:increment).with(prometheus_counter, 1)
end
end
subscriber.sql(event) subscriber.sql(event)
end end
end end
describe 'with a current transaction' do shared_examples 'track query in RequestStore' do
shared_examples 'track executed query' do context 'when RequestStore is enabled' do
before do it 'caches db count value', :request_store, :aggregate_failures do
allow(subscriber).to receive(:current_transaction) subscriber.sql(event)
.at_least(:once)
.and_return(transaction)
end
it 'increments only db count value' do
described_class::DB_COUNTERS.each do |counter| described_class::DB_COUNTERS.each do |counter|
prometheus_counter = "gitlab_transaction_#{counter}_total".to_sym expect(Gitlab::SafeRequestStore[counter].to_i).to eq expected_counters[counter]
if expected_counters[counter] > 0
expect(transaction).to receive(:increment).with(prometheus_counter, 1)
else
expect(transaction).not_to receive(:increment).with(prometheus_counter, 1)
end
end end
subscriber.sql(event)
end end
context 'when RequestStore is enabled' do it 'prevents db counters from leaking to the next transaction' do
it 'caches db count value', :request_store, :aggregate_failures do 2.times do
subscriber.sql(event) Gitlab::WithRequestStore.with_request_store do
subscriber.sql(event)
described_class::DB_COUNTERS.each do |counter| described_class::DB_COUNTERS.each do |counter|
expect(Gitlab::SafeRequestStore[counter].to_i).to eq expected_counters[counter] expect(Gitlab::SafeRequestStore[counter].to_i).to eq expected_counters[counter]
end
end end
end end
end
end
end
describe 'without a current transaction' do
it 'does not track any metrics' do
expect_any_instance_of(Gitlab::Metrics::Transaction)
.not_to receive(:increment)
it 'prevents db counters from leaking to the next transaction' do subscriber.sql(event)
2.times do end
Gitlab::WithRequestStore.with_request_store do
subscriber.sql(event)
described_class::DB_COUNTERS.each do |counter| context 'with read query' do
expect(Gitlab::SafeRequestStore[counter].to_i).to eq expected_counters[counter] let(:expected_counters) do
end {
end db_count: 1,
end db_write_count: 0,
end db_cached_count: 0
}
end end
it_behaves_like 'track query in RequestStore'
end end
end
describe 'with a current transaction' do
it 'observes sql_duration metric' do it 'observes sql_duration metric' do
expect(subscriber).to receive(:current_transaction) expect(subscriber).to receive(:current_transaction)
.at_least(:once) .at_least(:once)
...@@ -96,12 +110,14 @@ RSpec.describe Gitlab::Metrics::Subscribers::ActiveRecord do ...@@ -96,12 +110,14 @@ RSpec.describe Gitlab::Metrics::Subscribers::ActiveRecord do
} }
end end
it_behaves_like 'track executed query' it_behaves_like 'track query in metrics'
it_behaves_like 'track query in RequestStore'
context 'with only select' do context 'with only select' do
let(:payload) { { sql: 'WITH active_milestones AS (SELECT COUNT(*), state FROM milestones GROUP BY state) SELECT * FROM active_milestones' } } let(:payload) { { sql: 'WITH active_milestones AS (SELECT COUNT(*), state FROM milestones GROUP BY state) SELECT * FROM active_milestones' } }
it_behaves_like 'track executed query' it_behaves_like 'track query in metrics'
it_behaves_like 'track query in RequestStore'
end end
end end
...@@ -117,33 +133,38 @@ RSpec.describe Gitlab::Metrics::Subscribers::ActiveRecord do ...@@ -117,33 +133,38 @@ RSpec.describe Gitlab::Metrics::Subscribers::ActiveRecord do
context 'with select for update sql event' do context 'with select for update sql event' do
let(:payload) { { sql: 'SELECT * FROM users WHERE id = 10 FOR UPDATE' } } let(:payload) { { sql: 'SELECT * FROM users WHERE id = 10 FOR UPDATE' } }
it_behaves_like 'track executed query' it_behaves_like 'track query in metrics'
it_behaves_like 'track query in RequestStore'
end end
context 'with common table expression' do context 'with common table expression' do
context 'with insert' do context 'with insert' do
let(:payload) { { sql: 'WITH archived_rows AS (SELECT * FROM users WHERE archived = true) INSERT INTO products_log SELECT * FROM archived_rows' } } let(:payload) { { sql: 'WITH archived_rows AS (SELECT * FROM users WHERE archived = true) INSERT INTO products_log SELECT * FROM archived_rows' } }
it_behaves_like 'track executed query' it_behaves_like 'track query in metrics'
it_behaves_like 'track query in RequestStore'
end end
end end
context 'with delete sql event' do context 'with delete sql event' do
let(:payload) { { sql: 'DELETE FROM users where id = 10' } } let(:payload) { { sql: 'DELETE FROM users where id = 10' } }
it_behaves_like 'track executed query' it_behaves_like 'track query in metrics'
it_behaves_like 'track query in RequestStore'
end end
context 'with insert sql event' do context 'with insert sql event' do
let(:payload) { { sql: 'INSERT INTO project_ci_cd_settings (project_id) SELECT id FROM projects' } } let(:payload) { { sql: 'INSERT INTO project_ci_cd_settings (project_id) SELECT id FROM projects' } }
it_behaves_like 'track executed query' it_behaves_like 'track query in metrics'
it_behaves_like 'track query in RequestStore'
end end
context 'with update sql event' do context 'with update sql event' do
let(:payload) { { sql: 'UPDATE users SET admin = true WHERE id = 10' } } let(:payload) { { sql: 'UPDATE users SET admin = true WHERE id = 10' } }
it_behaves_like 'track executed query' it_behaves_like 'track query in metrics'
it_behaves_like 'track query in RequestStore'
end end
end end
...@@ -164,18 +185,20 @@ RSpec.describe Gitlab::Metrics::Subscribers::ActiveRecord do ...@@ -164,18 +185,20 @@ RSpec.describe Gitlab::Metrics::Subscribers::ActiveRecord do
} }
end end
it_behaves_like 'track executed query' it_behaves_like 'track query in metrics'
it_behaves_like 'track query in RequestStore'
end end
context 'with cached payload name' do context 'with cached payload name' do
let(:payload) do let(:payload) do
{ {
sql: 'SELECT * FROM users WHERE id = 10', sql: 'SELECT * FROM users WHERE id = 10',
name: 'CACHE' name: 'CACHE'
} }
end end
it_behaves_like 'track executed query' it_behaves_like 'track query in metrics'
it_behaves_like 'track query in RequestStore'
end end
end end
...@@ -227,8 +250,8 @@ RSpec.describe Gitlab::Metrics::Subscribers::ActiveRecord do ...@@ -227,8 +250,8 @@ RSpec.describe Gitlab::Metrics::Subscribers::ActiveRecord do
it 'skips schema/begin/commit sql commands' do it 'skips schema/begin/commit sql commands' do
allow(subscriber).to receive(:current_transaction) allow(subscriber).to receive(:current_transaction)
.at_least(:once) .at_least(:once)
.and_return(transaction) .and_return(transaction)
expect(transaction).not_to receive(:increment) expect(transaction).not_to receive(:increment)
......
...@@ -328,6 +328,13 @@ RSpec.configure do |config| ...@@ -328,6 +328,13 @@ RSpec.configure do |config|
Gitlab::WithRequestStore.with_request_store { example.run } Gitlab::WithRequestStore.with_request_store { example.run }
end end
config.before(:example, :request_store) do
# Clear request store before actually starting the spec (the
# `around` above will have the request store enabled for all
# `before` blocks)
RequestStore.clear!
end
config.around do |example| config.around do |example|
# Wrap each example in it's own context to make sure the contexts don't # Wrap each example in it's own context to make sure the contexts don't
# leak # leak
......
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