Merge branch '323163-restore-gitlab_database_transaction_seconds_sum-for-sidekiq' into 'master'

Port essential database metrics to Sidekiq

See merge request gitlab-org/gitlab!56005

changelogs/unreleased/323163-restore-gitlab_database_transaction_seconds_sum-for-sidekiq.yml

+---
+title: Port essential database metrics to Sidekiq
+merge_request: 56005
+author:
+type: changed

ee/lib/ee/gitlab/metrics/subscribers/active_record.rb

@@ -43,7 +43,7 @@ module EE
 
             db_role = ::Gitlab::Database::LoadBalancing.db_role_for_connection(payload[:connection])
             increment_db_role_counters(db_role, payload)
-            observe_db_role_duration(db_role, event.duration)
+            observe_db_role_duration(db_role, event)
           end
 
           private
@@ -53,13 +53,10 @@ module EE
             increment("db_#{db_role}_cached_count".to_sym) if cached_query?(payload)
           end
 
-          def observe_db_role_duration(db_role, duration)
-            duration /= 1000.0
-
-            current_transaction&.observe("gitlab_sql_#{db_role}_duration_seconds".to_sym, duration) do
-              buckets [0.05, 0.1, 0.25]
-            end
+          def observe_db_role_duration(db_role, event)
+            observe("gitlab_sql_#{db_role}_duration_seconds".to_sym, event)
 
+            duration = event.duration / 1000.0
             duration_key = "db_#{db_role}_duration_s".to_sym
             ::Gitlab::SafeRequestStore[duration_key] = (::Gitlab::SafeRequestStore[duration_key].presence || 0) + duration
           end

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

@@ -6,7 +6,6 @@ RSpec.describe ::Gitlab::Metrics::Subscribers::ActiveRecord do
   using RSpec::Parameterized::TableSyntax
 
   let(:env) { {} }
-  let(:transaction) { Gitlab::Metrics::WebTransaction.new(env) }
   let(:subscriber) { described_class.new }
   let(:connection) { double(:connection) }
   let(:payload) { { sql: 'SELECT * FROM users WHERE id = 10', connection: connection } }
@@ -49,8 +48,6 @@ RSpec.describe ::Gitlab::Metrics::Subscribers::ActiveRecord do
 
       before do
         allow(Gitlab::Database::LoadBalancing).to receive(:enable?).and_return(true)
-        allow(subscriber).to receive(:current_transaction)
-          .and_return(transaction)
       end
 
       context 'query using a connection to a replica' do

lib/gitlab/database.rb

@@ -313,28 +313,18 @@ module Gitlab
       ActiveRecord::Base.prepend(ActiveRecordBaseTransactionMetrics)
     end
 
-    # observe_transaction_duration is called from ActiveRecordBaseTransactionMetrics.transaction and used to
-    # record transaction durations.
-    def self.observe_transaction_duration(duration_seconds)
-      if current_transaction = ::Gitlab::Metrics::Transaction.current
-        current_transaction.observe(:gitlab_database_transaction_seconds, duration_seconds) do
-          docstring "Time spent in database transactions, in seconds"
-        end
-      end
-    rescue Prometheus::Client::LabelSetValidator::LabelSetError => err
-      # Ensure that errors in recording these metrics don't affect the operation of the application
-      Gitlab::AppLogger.error("Unable to observe database transaction duration: #{err}")
-    end
-
     # MonkeyPatch for ActiveRecord::Base for adding observability
     module ActiveRecordBaseTransactionMetrics
-      # A monkeypatch over ActiveRecord::Base.transaction.
-      # It provides observability into transactional methods.
-      def transaction(options = {}, &block)
-        start_time = Gitlab::Metrics::System.monotonic_time
-        super(options, &block)
-      ensure
-        Gitlab::Database.observe_transaction_duration(Gitlab::Metrics::System.monotonic_time - start_time)
+      extend ActiveSupport::Concern
+
+      class_methods do
+        # A monkeypatch over ActiveRecord::Base.transaction.
+        # It provides observability into transactional methods.
+        def transaction(**options, &block)
+          ActiveSupport::Notifications.instrument('transaction.active_record', { connection: connection }) do
+            super(**options, &block)
+          end
+        end
       end
     end
   end

lib/gitlab/metrics/background_transaction.rb

+# frozen_string_literal: true
+
+module Gitlab
+  module Metrics
+    class BackgroundTransaction < Transaction
+      # Separate web transaction instance and background transaction instance
+      BACKGROUND_THREAD_KEY = :_gitlab_metrics_background_transaction
+      BACKGROUND_BASE_LABEL_KEYS = %i(endpoint_id feature_category).freeze
+
+      class << self
+        def current
+          Thread.current[BACKGROUND_THREAD_KEY]
+        end
+
+        def prometheus_metric(name, type, &block)
+          fetch_metric(type, name) do
+            # set default metric options
+            docstring "#{name.to_s.humanize} #{type}"
+
+            evaluate(&block)
+            # always filter sensitive labels and merge with base ones
+            label_keys BACKGROUND_BASE_LABEL_KEYS | (label_keys - ::Gitlab::Metrics::Transaction::FILTERED_LABEL_KEYS)
+          end
+        end
+      end
+
+      def run
+        Thread.current[BACKGROUND_THREAD_KEY] = self
+
+        yield
+      ensure
+        Thread.current[BACKGROUND_THREAD_KEY] = nil
+      end
+
+      def labels
+        @labels ||= {
+          endpoint_id: current_context&.get_attribute(:caller_id),
+          feature_category: current_context&.get_attribute(:feature_category)
+        }
+      end
+
+      private
+
+      def current_context
+        Labkit::Context.current
+      end
+    end
+  end
+end

lib/gitlab/metrics/subscribers/active_record.rb

@@ -11,6 +11,15 @@ module Gitlab
         DB_COUNTERS = %i{db_count db_write_count db_cached_count}.freeze
         SQL_COMMANDS_WITH_COMMENTS_REGEX = /\A(\/\*.*\*\/\s)?((?!(.*[^\w'"](DELETE|UPDATE|INSERT INTO)[^\w'"])))(WITH.*)?(SELECT)((?!(FOR UPDATE|FOR SHARE)).)*$/i.freeze
 
+        DURATION_BUCKET = [0.05, 0.1, 0.25].freeze
+
+        # This event is published from ActiveRecordBaseTransactionMetrics and
+        # used to record a database transaction duration when calling
+        # ActiveRecord::Base.transaction {} block.
+        def transaction(event)
+          observe(:gitlab_database_transaction_seconds, event)
+        end
+
         def sql(event)
           # Mark this thread as requiring a database connection. This is used
           # by the Gitlab::Metrics::Samplers::ThreadsSampler to count threads
@@ -20,10 +29,11 @@ module Gitlab
           payload = event.payload
           return if ignored_query?(payload)
 
-          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_count)
+          increment(:db_cached_count) if cached_query?(payload)
+          increment(:db_write_count) unless select_sql_command?(payload)
+
+          observe(:gitlab_sql_duration_seconds, event)
         end
 
         def self.db_counter_payload
@@ -50,20 +60,20 @@ module Gitlab
           payload[:sql].match(SQL_COMMANDS_WITH_COMMENTS_REGEX)
         end
 
-        def increment_db_counters(payload)
-          increment(:db_count)
-          increment(:db_cached_count) if cached_query?(payload)
-          increment(:db_write_count) unless select_sql_command?(payload)
-        end
-
         def increment(counter)
           current_transaction&.increment("gitlab_transaction_#{counter}_total".to_sym, 1)
 
           Gitlab::SafeRequestStore[counter] = Gitlab::SafeRequestStore[counter].to_i + 1
         end
 
+        def observe(histogram, event)
+          current_transaction&.observe(histogram, event.duration / 1000.0) do
+            buckets DURATION_BUCKET
+          end
+        end
+
         def current_transaction
-          ::Gitlab::Metrics::Transaction.current
+          ::Gitlab::Metrics::WebTransaction.current || ::Gitlab::Metrics::BackgroundTransaction.current
         end
       end
     end

lib/gitlab/sidekiq_middleware/server_metrics.rb

@@ -34,7 +34,8 @@ module Gitlab
         monotonic_time_start = Gitlab::Metrics::System.monotonic_time
         job_thread_cputime_start = get_thread_cputime
         begin
-          yield
+          transaction = Gitlab::Metrics::BackgroundTransaction.new
+          transaction.run { yield }
           job_succeeded = true
         ensure
           monotonic_time_end = Gitlab::Metrics::System.monotonic_time

spec/lib/gitlab/database_spec.rb

@@ -441,4 +441,112 @@ RSpec.describe Gitlab::Database do
       end
     end
   end
+
+  describe 'ActiveRecordBaseTransactionMetrics' do
+    def subscribe_events
+      events = []
+
+      begin
+        subscriber = ActiveSupport::Notifications.subscribe('transaction.active_record') do |e|
+          events << e
+        end
+
+        yield
+      ensure
+        ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber
+      end
+
+      events
+    end
+
+    context 'without a transaction block' do
+      it 'does not publish a transaction event' do
+        events = subscribe_events do
+          User.first
+        end
+
+        expect(events).to be_empty
+      end
+    end
+
+    context 'within a transaction block' do
+      it 'publishes a transaction event' do
+        events = subscribe_events do
+          ActiveRecord::Base.transaction do
+            User.first
+          end
+        end
+
+        expect(events.length).to be(1)
+
+        event = events.first
+        expect(event).not_to be_nil
+        expect(event.duration).to be > 0.0
+        expect(event.payload).to a_hash_including(
+          connection: be_a(ActiveRecord::ConnectionAdapters::AbstractAdapter)
+        )
+      end
+    end
+
+    context 'within an empty transaction block' do
+      it 'publishes a transaction event' do
+        events = subscribe_events do
+          ActiveRecord::Base.transaction {}
+        end
+
+        expect(events.length).to be(1)
+
+        event = events.first
+        expect(event).not_to be_nil
+        expect(event.duration).to be > 0.0
+        expect(event.payload).to a_hash_including(
+          connection: be_a(ActiveRecord::ConnectionAdapters::AbstractAdapter)
+        )
+      end
+    end
+
+    context 'within a nested transaction block' do
+      it 'publishes multiple transaction events' do
+        events = subscribe_events do
+          ActiveRecord::Base.transaction do
+            ActiveRecord::Base.transaction do
+              ActiveRecord::Base.transaction do
+                User.first
+              end
+            end
+          end
+        end
+
+        expect(events.length).to be(3)
+
+        events.each do |event|
+          expect(event).not_to be_nil
+          expect(event.duration).to be > 0.0
+          expect(event.payload).to a_hash_including(
+            connection: be_a(ActiveRecord::ConnectionAdapters::AbstractAdapter)
+          )
+        end
+      end
+    end
+
+    context 'within a cancelled transaction block' do
+      it 'publishes multiple transaction events' do
+        events = subscribe_events do
+          ActiveRecord::Base.transaction do
+            User.first
+            raise ActiveRecord::Rollback
+          end
+        end
+
+        expect(events.length).to be(1)
+
+        event = events.first
+        expect(event).not_to be_nil
+        expect(event.duration).to be > 0.0
+        expect(event.payload).to a_hash_including(
+          connection: be_a(ActiveRecord::ConnectionAdapters::AbstractAdapter)
+        )
+      end
+    end
+  end
 end

spec/lib/gitlab/metrics/background_transaction_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+RSpec.describe Gitlab::Metrics::BackgroundTransaction do
+  let(:transaction) { described_class.new }
+  let(:prometheus_metric) { instance_double(Prometheus::Client::Metric, base_labels: {}) }
+
+  before do
+    allow(described_class).to receive(:prometheus_metric).and_return(prometheus_metric)
+  end
+
+  describe '#run' do
+    it 'yields the supplied block' do
+      expect { |b| transaction.run(&b) }.to yield_control
+    end
+
+    it 'stores the transaction in the current thread' do
+      transaction.run do
+        expect(Thread.current[described_class::BACKGROUND_THREAD_KEY]).to eq(transaction)
+      end
+    end
+
+    it 'removes the transaction from the current thread upon completion' do
+      transaction.run { }
+
+      expect(Thread.current[described_class::BACKGROUND_THREAD_KEY]).to be_nil
+    end
+  end
+
+  describe '#labels' do
+    it 'provides labels with endpoint_id and feature_category' do
+      Labkit::Context.with_context(feature_category: 'projects', caller_id: 'TestWorker') do
+        expect(transaction.labels).to eq({ endpoint_id: 'TestWorker', feature_category: 'projects' })
+      end
+    end
+  end
+
+  RSpec.shared_examples 'metric with labels' do |metric_method|
+    it 'measures with correct labels and value' do
+      value = 1
+      expect(prometheus_metric).to receive(metric_method).with({ endpoint_id: 'TestWorker', feature_category: 'projects' }, value)
+
+      Labkit::Context.with_context(feature_category: 'projects', caller_id: 'TestWorker') do
+        transaction.send(metric_method, :test_metric, value)
+      end
+    end
+  end
+
+  describe '#increment' do
+    let(:prometheus_metric) { instance_double(Prometheus::Client::Counter, :increment, base_labels: {}) }
+
+    it_behaves_like 'metric with labels', :increment
+  end
+
+  describe '#set' do
+    let(:prometheus_metric) { instance_double(Prometheus::Client::Gauge, :set, base_labels: {}) }
+
+    it_behaves_like 'metric with labels', :set
+  end
+
+  describe '#observe' do
+    let(:prometheus_metric) { instance_double(Prometheus::Client::Histogram, :observe, base_labels: {}) }
+
+    it_behaves_like 'metric with labels', :observe
+  end
+end

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

@@ -6,8 +6,7 @@ RSpec.describe Gitlab::Metrics::Subscribers::ActiveRecord do
   using RSpec::Parameterized::TableSyntax
 
   let(:env) { {} }
-  let(:transaction) { Gitlab::Metrics::WebTransaction.new(env) }
-  let(:subscriber)  { described_class.new }
+  let(:subscriber) { described_class.new }
   let(:connection) { double(:connection) }
   let(:payload) { { sql: 'SELECT * FROM users WHERE id = 10', connection: connection } }
 
@@ -47,33 +46,15 @@ RSpec.describe Gitlab::Metrics::Subscribers::ActiveRecord do
     with_them do
       let(:payload) { { name: name, sql: sql(sql_query, comments: comments), connection: connection } }
 
-      describe 'with a current transaction' do
-        before do
-          allow(subscriber).to receive(:current_transaction)
-            .at_least(:once)
-            .and_return(transaction)
-        end
+      it 'marks the current thread as using the database' do
+        # since it would already have been toggled by other specs
+        Thread.current[:uses_db_connection] = nil
 
-        it 'marks the current thread as using the database' do
-          # since it would already have been toggled by other specs
-          Thread.current[:uses_db_connection] = nil
-
-          expect { subscriber.sql(event) }.to change { Thread.current[:uses_db_connection] }.from(nil).to(true)
-        end
-
-        it_behaves_like 'record ActiveRecord metrics'
-        it_behaves_like 'store ActiveRecord info in RequestStore'
+        expect { subscriber.sql(event) }.to change { Thread.current[:uses_db_connection] }.from(nil).to(true)
       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)
-          subscriber.sql(event)
-        end
-
-        it_behaves_like 'store ActiveRecord info in RequestStore'
-      end
+      it_behaves_like 'record ActiveRecord metrics'
+      it_behaves_like 'store ActiveRecord info in RequestStore'
     end
   end
 

spec/lib/gitlab/sidekiq_middleware/server_metrics_spec.rb

@@ -113,6 +113,14 @@ RSpec.describe Gitlab::SidekiqMiddleware::ServerMetrics do
             expect { |b| subject.call(worker, job, :test, &b) }.to yield_control.once
           end
 
+          it 'calls BackgroundTransaction' do
+            expect_next_instance_of(Gitlab::Metrics::BackgroundTransaction) do |instance|
+              expect(instance).to receive(:run)
+            end
+
+            subject.call(worker, job, :test) {}
+          end
+
           it 'sets queue specific metrics' do
             expect(running_jobs_metric).to receive(:increment).with(labels, -1)
             expect(running_jobs_metric).to receive(:increment).with(labels, 1)

spec/support/shared_examples/metrics/active_record_subscriber_shared_examples.rb

@@ -42,7 +42,7 @@ RSpec.shared_examples 'store ActiveRecord info in RequestStore' do |db_role|
   end
 end
 
-RSpec.shared_examples 'record ActiveRecord metrics' do |db_role|
+RSpec.shared_examples 'record ActiveRecord metrics in a metrics transaction' do |db_role|
   it 'increments only db counters' do
     if record_query
       expect(transaction).to receive(:increment).with(:gitlab_transaction_db_count_total, 1)
@@ -80,3 +80,58 @@ RSpec.shared_examples 'record ActiveRecord metrics' do |db_role|
     subscriber.sql(event)
   end
 end
+
+RSpec.shared_examples 'record ActiveRecord metrics' do |db_role|
+  context 'when both web and background transaction are available' do
+    let(:transaction) { double('Gitlab::Metrics::WebTransaction') }
+    let(:background_transaction) { double('Gitlab::Metrics::WebTransaction') }
+
+    before do
+      allow(::Gitlab::Metrics::WebTransaction).to receive(:current)
+        .and_return(transaction)
+      allow(::Gitlab::Metrics::BackgroundTransaction).to receive(:current)
+        .and_return(background_transaction)
+      allow(transaction).to receive(:increment)
+      allow(transaction).to receive(:observe)
+    end
+
+    it_behaves_like 'record ActiveRecord metrics in a metrics transaction', db_role
+
+    it 'captures the metrics for web only' do
+      expect(background_transaction).not_to receive(:observe)
+      expect(background_transaction).not_to receive(:increment)
+
+      subscriber.sql(event)
+    end
+  end
+
+  context 'when web transaction is available' do
+    let(:transaction) { double('Gitlab::Metrics::WebTransaction') }
+
+    before do
+      allow(::Gitlab::Metrics::WebTransaction).to receive(:current)
+        .and_return(transaction)
+      allow(::Gitlab::Metrics::BackgroundTransaction).to receive(:current)
+        .and_return(nil)
+      allow(transaction).to receive(:increment)
+      allow(transaction).to receive(:observe)
+    end
+
+    it_behaves_like 'record ActiveRecord metrics in a metrics transaction', db_role
+  end
+
+  context 'when background transaction is available' do
+    let(:transaction) { double('Gitlab::Metrics::BackgroundTransaction') }
+
+    before do
+      allow(::Gitlab::Metrics::WebTransaction).to receive(:current)
+        .and_return(nil)
+      allow(::Gitlab::Metrics::BackgroundTransaction).to receive(:current)
+        .and_return(transaction)
+      allow(transaction).to receive(:increment)
+      allow(transaction).to receive(:observe)
+    end
+
+    it_behaves_like 'record ActiveRecord metrics in a metrics transaction', db_role
+  end
+end