Merge branch 'remove-rails-background-transaction-metrics' into 'master'

Remove Rails background transaction metrics

See merge request gitlab-org/gitlab!48024

config/initializers/lograge.rb

@@ -2,7 +2,6 @@
 unless Gitlab::Runtime.sidekiq?
   Rails.application.reloader.to_prepare do
     filename = File.join(Rails.root, 'log', "#{Rails.env}_json.log")
-    db_counter = Gitlab::Metrics::Subscribers::ActiveRecord
 
     Rails.application.configure do
       config.lograge.enabled = true
@@ -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[: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.merge!(db_counter.db_counter_payload)
 
         # Remove empty hashes to prevent type mismatches
         # These are set to empty hashes in Lograge's ActionCable subscriber

config/initializers/zz_metrics.rb

@@ -150,12 +150,6 @@ if Gitlab::Metrics.enabled? && !Rails.env.test? && !(Rails.env.development? && d
     config.middleware.use(Gitlab::Metrics::ElasticsearchRackMiddleware)
   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
   # of the ActiveRecord methods. This has to take place _after_ initializing as
   # for some unknown reason calling eager_load! earlier breaks Devise.

lib/gitlab/instrumentation_helper.rb

@@ -13,7 +13,8 @@ module Gitlab
                  :rugged_duration_s,
                  :elasticsearch_calls,
                  :elasticsearch_duration_s,
-                 *::Gitlab::Instrumentation::Redis.known_payload_keys]
+                 *::Gitlab::Instrumentation::Redis.known_payload_keys,
+                 *::Gitlab::Metrics::Subscribers::ActiveRecord::DB_COUNTERS]
     end
 
     def add_instrumentation_data(payload)
@@ -22,6 +23,7 @@ module Gitlab
       instrument_redis(payload)
       instrument_elasticsearch(payload)
       instrument_throttle(payload)
+      instrument_active_record(payload)
     end
 
     def instrument_gitaly(payload)
@@ -62,6 +64,12 @@ module Gitlab
       payload[:throttle_safelist] = safelist if safelist.present?
     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
     # `enqueued_at` field or `created_at` field is available.
     #

lib/gitlab/metrics/background_transaction.rb

-# 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

lib/gitlab/metrics/sidekiq_middleware.rb

-# 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

lib/gitlab/metrics/subscribers/active_record.rb

@@ -16,16 +16,14 @@ module Gitlab
           # using a connection.
           Thread.current[:uses_db_connection] = true
 
-          return unless current_transaction
-
           payload = event.payload
           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]
           end
-
-          increment_db_counters(payload)
         end
 
         def self.db_counter_payload
@@ -53,7 +51,7 @@ module Gitlab
         end
 
         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?
             Gitlab::SafeRequestStore[counter] = Gitlab::SafeRequestStore[counter].to_i + 1

spec/initializers/lograge_spec.rb

@@ -153,32 +153,22 @@ RSpec.describe 'lograge', type: :request do
       end
     end
 
-    context 'with transaction' do
-      let(:transaction) { Gitlab::Metrics::WebTransaction.new({}) }
-
-      before do
-        allow(Gitlab::Metrics::Transaction).to receive(:current).and_return(transaction)
-      end
-
+    context 'with db payload' do
       context 'when RequestStore is enabled', :request_store do
-        context 'with db payload' do
-          it 'includes db counters', :request_store do
-            ActiveRecord::Base.connection.execute('SELECT pg_sleep(0.1);')
-            subscriber.process_action(event)
+        it 'includes db counters' do
+          ActiveRecord::Base.connection.execute('SELECT pg_sleep(0.1);')
+          subscriber.process_action(event)
 
-            expect(log_data).to include("db_count" => 1, "db_write_count" => 0, "db_cached_count" => 0)
-          end
+          expect(log_data).to include("db_count" => a_value >= 1, "db_write_count" => 0, "db_cached_count" => 0)
         end
       end
 
       context 'when RequestStore is disabled' do
-        context 'with db payload' do
-          it 'does not include db counters' do
-            ActiveRecord::Base.connection.execute('SELECT pg_sleep(0.1);')
-            subscriber.process_action(event)
+        it 'does not include db counters' do
+          ActiveRecord::Base.connection.execute('SELECT pg_sleep(0.1);')
+          subscriber.process_action(event)
 
-            expect(log_data).not_to include("db_count" => 1, "db_write_count" => 0, "db_cached_count" => 0)
-          end
+          expect(log_data).not_to include("db_count", "db_write_count", "db_cached_count")
         end
       end
     end

spec/lib/gitlab/instrumentation_helper_spec.rb

@@ -34,7 +34,10 @@ RSpec.describe Gitlab::InstrumentationHelper do
         :redis_shared_state_calls,
         :redis_shared_state_duration_s,
         :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)
@@ -46,10 +49,10 @@ RSpec.describe Gitlab::InstrumentationHelper do
 
     subject { described_class.add_instrumentation_data(payload) }
 
-    it 'adds nothing' do
+    it 'adds only DB counts by default' do
       subject
 
-      expect(payload).to eq({})
+      expect(payload).to eq(db_count: 0, db_cached_count: 0, db_write_count: 0)
     end
 
     context 'when Gitaly calls are made' do

spec/lib/gitlab/metrics/background_transaction_spec.rb

-# 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

spec/lib/gitlab/metrics/sidekiq_middleware_spec.rb

-# 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

spec/lib/gitlab/metrics/subscribers/active_record_spec.rb

@@ -18,59 +18,73 @@ RSpec.describe Gitlab::Metrics::Subscribers::ActiveRecord do
   end
 
   describe '#sql' do
-    describe 'without a current transaction' do
-      it 'simply returns' do
-        expect_any_instance_of(Gitlab::Metrics::Transaction)
-          .not_to receive(:increment)
+    shared_examples 'track query in metrics' do
+      before do
+        allow(subscriber).to receive(:current_transaction)
+                               .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)
       end
     end
 
-    describe 'with a current transaction' do
-      shared_examples 'track executed query' do
-        before do
-          allow(subscriber).to receive(:current_transaction)
-                                 .at_least(:once)
-                                 .and_return(transaction)
-        end
+    shared_examples 'track query in RequestStore' do
+      context 'when RequestStore is enabled' do
+        it 'caches db count value', :request_store, :aggregate_failures do
+          subscriber.sql(event)
 
-        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
+            expect(Gitlab::SafeRequestStore[counter].to_i).to eq expected_counters[counter]
           end
-
-          subscriber.sql(event)
         end
 
-        context 'when RequestStore is enabled' do
-          it 'caches db count value', :request_store, :aggregate_failures do
-            subscriber.sql(event)
+        it 'prevents db counters from leaking to the next transaction' do
+          2.times do
+            Gitlab::WithRequestStore.with_request_store do
+              subscriber.sql(event)
 
-            described_class::DB_COUNTERS.each do |counter|
-              expect(Gitlab::SafeRequestStore[counter].to_i).to eq expected_counters[counter]
+              described_class::DB_COUNTERS.each do |counter|
+                expect(Gitlab::SafeRequestStore[counter].to_i).to eq expected_counters[counter]
+              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
-            2.times do
-              Gitlab::WithRequestStore.with_request_store do
-                subscriber.sql(event)
+        subscriber.sql(event)
+      end
 
-                described_class::DB_COUNTERS.each do |counter|
-                  expect(Gitlab::SafeRequestStore[counter].to_i).to eq expected_counters[counter]
-                end
-              end
-            end
-          end
+      context 'with read query' do
+        let(:expected_counters) do
+          {
+            db_count: 1,
+            db_write_count: 0,
+            db_cached_count: 0
+          }
         end
+
+        it_behaves_like 'track query in RequestStore'
       end
+    end
 
+    describe 'with a current transaction' do
       it 'observes sql_duration metric' do
         expect(subscriber).to receive(:current_transaction)
                                 .at_least(:once)
@@ -96,12 +110,14 @@ RSpec.describe Gitlab::Metrics::Subscribers::ActiveRecord do
           }
         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
           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
 
@@ -117,33 +133,38 @@ RSpec.describe Gitlab::Metrics::Subscribers::ActiveRecord do
         context 'with select for update sql event' do
           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
 
         context 'with common table expression' 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' } }
 
-            it_behaves_like 'track executed query'
+            it_behaves_like 'track query in metrics'
+            it_behaves_like 'track query in RequestStore'
           end
         end
 
         context 'with delete sql event' do
           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
 
         context 'with insert sql event' do
           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
 
         context 'with update sql event' do
           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
 
@@ -164,18 +185,20 @@ RSpec.describe Gitlab::Metrics::Subscribers::ActiveRecord do
             }
           end
 
-          it_behaves_like 'track executed query'
+          it_behaves_like 'track query in metrics'
+          it_behaves_like 'track query in RequestStore'
         end
 
         context 'with cached payload name' do
           let(:payload) do
             {
-             sql: 'SELECT * FROM users WHERE id = 10',
-             name: 'CACHE'
+              sql: 'SELECT * FROM users WHERE id = 10',
+              name: 'CACHE'
             }
           end
 
-          it_behaves_like 'track executed query'
+          it_behaves_like 'track query in metrics'
+          it_behaves_like 'track query in RequestStore'
         end
       end
 
@@ -227,8 +250,8 @@ RSpec.describe Gitlab::Metrics::Subscribers::ActiveRecord do
 
         it 'skips schema/begin/commit sql commands' do
           allow(subscriber).to receive(:current_transaction)
-                                  .at_least(:once)
-                                  .and_return(transaction)
+                                 .at_least(:once)
+                                 .and_return(transaction)
 
           expect(transaction).not_to receive(:increment)
 

spec/spec_helper.rb

@@ -332,6 +332,13 @@ RSpec.configure do |config|
     Gitlab::WithRequestStore.with_request_store { example.run }
   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|
     # Wrap each example in it's own context to make sure the contexts don't
     # leak