Merge branch '222684-fix-db-call-logging' into 'master'

Fix db call logging numbers

Closes #222684

See merge request !34939

config/initializers/lograge.rb

@@ -15,6 +15,7 @@
       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!(::Gitlab::Metrics::Subscribers::ActiveRecord.db_counter_payload)
 
       data
     end

lib/gitlab/lograge/custom_options.rb

@@ -20,8 +20,6 @@ def self.call(event)
           username: event.payload[:username],
           ua: event.payload[:ua]
         }
-        add_db_counters!(payload)
-
         payload.merge!(event.payload[:metadata]) if event.payload[:metadata]
 
         ::Gitlab::InstrumentationHelper.add_instrumentation_data(payload)
@@ -46,16 +44,6 @@ def self.call(event)
 
         payload
       end
-
-      def self.add_db_counters!(payload)
-        current_transaction = Gitlab::Metrics::Transaction.current
-        if current_transaction
-          payload[:db_count] = current_transaction.get(:db_count, :counter).to_i
-          payload[:db_write_count] = current_transaction.get(:db_write_count, :counter).to_i
-          payload[:db_cached_count] = current_transaction.get(:db_cached_count, :counter).to_i
-        end
-      end
-      private_class_method :add_db_counters!
     end
   end
 end

lib/gitlab/metrics/sidekiq_middleware.rb

@@ -26,9 +26,7 @@ def call(worker, payload, queue)
       private
 
       def add_info_to_payload(payload, trans)
-        payload[:db_count] = trans.get(:db_count, :counter).to_i
-        payload[:db_write_count] = trans.get(:db_write_count, :counter).to_i
-        payload[:db_cached_count] = trans.get(:db_cached_count, :counter).to_i
+        payload.merge!(::Gitlab::Metrics::Subscribers::ActiveRecord.db_counter_payload)
       end
     end
   end

lib/gitlab/metrics/subscribers/active_record.rb

@@ -23,6 +23,14 @@ def sql(event)
           increment_db_counters(payload)
         end
 
+        def self.db_counter_payload
+          return {} unless Gitlab::SafeRequestStore.active?
+
+          DB_COUNTERS.map do |counter|
+            [counter, Gitlab::SafeRequestStore[counter].to_i]
+          end.to_h
+        end
+
         private
 
         define_histogram :gitlab_sql_duration_seconds do
@@ -36,13 +44,21 @@ def select_sql_command?(payload)
         end
 
         def increment_db_counters(payload)
-          current_transaction.increment(:db_count, 1)
+          increment(:db_count)
 
           if payload.fetch(:cached, payload[:name] == 'CACHE')
-            current_transaction.increment(:db_cached_count, 1)
+            increment(:db_cached_count)
           end
 
-          current_transaction.increment(:db_write_count, 1) unless select_sql_command?(payload)
+          increment(:db_write_count) unless select_sql_command?(payload)
+        end
+
+        def increment(counter)
+          current_transaction.increment(counter, 1)
+
+          if Gitlab::SafeRequestStore.active?
+            Gitlab::SafeRequestStore[counter] = Gitlab::SafeRequestStore[counter].to_i + 1
+          end
         end
 
         def current_transaction

lib/gitlab/metrics/transaction.rb

@@ -92,12 +92,6 @@ def set(name, value, use_prometheus = true)
         self.class.transaction_metric(name, :gauge).set(labels, value) if use_prometheus
       end
 
-      def get(name, type, tags = {})
-        metric = self.class.transaction_metric(name, type)
-
-        metric.get(filter_tags(tags).merge(labels))
-      end
-
       def labels
         BASE_LABELS
       end

spec/initializers/lograge_spec.rb

@@ -152,5 +152,35 @@
         expect(log_data['etag_route']).to eq(etag_route)
       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 '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)
+
+            expect(log_data).to include("db_count" => 1, "db_write_count" => 0, "db_cached_count" => 0)
+          end
+        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)
+
+            expect(log_data).not_to include("db_count" => 1, "db_write_count" => 0, "db_cached_count" => 0)
+          end
+        end
+      end
+    end
   end
 end

spec/lib/gitlab/lograge/custom_options_spec.rb

@@ -44,18 +44,6 @@
       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
-
-      it 'adds db counters' do
-        expect(subject).to include(:db_count, :db_write_count, :db_cached_count)
-      end
-    end
-
     it 'adds the user id' do
       expect(subject[:user_id]).to eq('test')
     end

spec/lib/gitlab/metrics/sidekiq_middleware_spec.rb

@@ -18,8 +18,20 @@
       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'))
 
-      expect(message).to include(:db_count, :db_write_count, :db_cached_count)
+      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
@@ -35,19 +47,20 @@
       middleware.call(worker, {}, :test) { nil }
     end
 
-    it 'tracks any raised exceptions', :aggregate_failures do
+    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(:run).and_raise(RuntimeError)
-
       expect_any_instance_of(Gitlab::Metrics::Transaction)
         .to receive(:add_event).with(:sidekiq_exception)
 
-      expect { middleware.call(worker, message, :test) }
-        .to raise_error(RuntimeError)
+      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, :db_write_count, :db_cached_count)
+      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

@@ -28,60 +28,45 @@
     end
 
     describe 'with a current transaction' do
-      shared_examples 'read only query' do
-        it 'increments only db count value' do
+      shared_examples 'track executed query' do
+        before do
           allow(subscriber).to receive(:current_transaction)
-                                  .at_least(:once)
-                                  .and_return(transaction)
-
-          expect(transaction).to receive(:increment)
-                                   .with(:db_count, 1)
-
-          expect(transaction).not_to receive(:increment)
-                                       .with(:db_cached_count, 1)
-
-          expect(transaction).not_to receive(:increment)
-                                       .with(:db_write_count, 1)
-
-          subscriber.sql(event)
+                                 .at_least(:once)
+                                 .and_return(transaction)
         end
-      end
-
-      shared_examples 'write query' do
-        it 'increments db_write_count and db_count value' do
-          expect(subscriber).to receive(:current_transaction)
-                                  .at_least(:once)
-                                  .and_return(transaction)
 
-          expect(transaction).to receive(:increment)
-                                   .with(:db_count, 1)
-
-          expect(transaction).not_to receive(:increment)
-                                       .with(:db_cached_count, 1)
-
-          expect(transaction).to receive(:increment)
-                                       .with(:db_write_count, 1)
+        it 'increments only db count value' do
+          described_class::DB_COUNTERS.each do |counter|
+            if expected_counters[counter] > 0
+              expect(transaction).to receive(:increment).with(counter, 1)
+            else
+              expect(transaction).not_to receive(:increment).with(counter, 1)
+            end
+          end
 
           subscriber.sql(event)
         end
-      end
 
-      shared_examples 'cached query' do
-        it 'increments db_cached_count and db_count value' do
-          expect(subscriber).to receive(:current_transaction)
-                                  .at_least(:once)
-                                  .and_return(transaction)
-
-          expect(transaction).to receive(:increment)
-                                   .with(:db_count, 1)
-
-          expect(transaction).to receive(:increment)
-                                       .with(:db_cached_count, 1)
-
-          expect(transaction).not_to receive(:increment)
-                                   .with(:db_write_count, 1)
-
-          subscriber.sql(event)
+        context 'when RequestStore is enabled' do
+          it 'caches db count value', :request_store, :aggregate_failures do
+            subscriber.sql(event)
+
+            described_class::DB_COUNTERS.each do |counter|
+              expect(Gitlab::SafeRequestStore[counter].to_i).to eq expected_counters[counter]
+            end
+          end
+
+          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]
+                end
+              end
+            end
+          end
         end
       end
 
@@ -93,66 +78,96 @@
         subscriber.sql(event)
       end
 
-      it_behaves_like 'read only query'
+      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 executed query'
 
-      context 'with select for update sql event' do
-        let(:payload) { { sql: 'SELECT * FROM users WHERE id = 10 FOR UPDATE' } }
+        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 'write query'
+          it_behaves_like 'track executed query'
+        end
       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' } }
+      context 'write query' do
+        let(:expected_counters) do
+          {
+            db_count: 1,
+            db_write_count: 1,
+            db_cached_count: 0
+          }
+        end
+
+        context 'with select for update sql event' do
+          let(:payload) { { sql: 'SELECT * FROM users WHERE id = 10 FOR UPDATE' } }
 
-          it_behaves_like 'write query'
+          it_behaves_like 'track executed query'
         end
 
-        context 'with only select' do
-          let(:payload) { { sql: 'WITH active_milestones AS (SELECT COUNT(*), state FROM milestones GROUP BY state) SELECT * FROM active_milestones' } }
+        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 'read only query'
+            it_behaves_like 'track executed query'
+          end
         end
-      end
 
-      context 'with delete sql event' do
-        let(:payload) { { sql: 'DELETE FROM users where id = 10' } }
+        context 'with delete sql event' do
+          let(:payload) { { sql: 'DELETE FROM users where id = 10' } }
 
-        it_behaves_like 'write query'
-      end
+          it_behaves_like 'track executed query'
+        end
 
-      context 'with insert sql event' do
-        let(:payload) { { sql: 'INSERT INTO project_ci_cd_settings (project_id) SELECT id FROM projects' } }
+        context 'with insert sql event' do
+          let(:payload) { { sql: 'INSERT INTO project_ci_cd_settings (project_id) SELECT id FROM projects' } }
 
-        it_behaves_like 'write query'
-      end
+          it_behaves_like 'track executed query'
+        end
 
-      context 'with update sql event' do
-        let(:payload) { { sql: 'UPDATE users SET admin = true WHERE id = 10' } }
+        context 'with update sql event' do
+          let(:payload) { { sql: 'UPDATE users SET admin = true WHERE id = 10' } }
 
-        it_behaves_like 'write query'
+          it_behaves_like 'track executed query'
+        end
       end
 
-      context 'with cached payload ' do
-        let(:payload) do
+      context 'with cached query' do
+        let(:expected_counters) do
           {
-            sql: 'SELECT * FROM users WHERE id = 10',
-            cached: true
+            db_count: 1,
+            db_write_count: 0,
+            db_cached_count: 1
           }
         end
 
-        it_behaves_like 'cached query'
-      end
+        context 'with cached payload ' do
+          let(:payload) do
+            {
+              sql: 'SELECT * FROM users WHERE id = 10',
+              cached: true
+            }
+          end
 
-      context 'with cached payload name' do
-        let(:payload) do
-          {
-           sql: 'SELECT * FROM users WHERE id = 10',
-           name: 'CACHE'
-          }
+          it_behaves_like 'track executed query'
         end
 
-        it_behaves_like 'cached query'
+        context 'with cached payload name' do
+          let(:payload) do
+            {
+             sql: 'SELECT * FROM users WHERE id = 10',
+             name: 'CACHE'
+            }
+          end
+
+          it_behaves_like 'track executed query'
+        end
       end
 
       context 'events are internal to Rails or irrelevant' do
@@ -215,4 +230,54 @@
       end
     end
   end
+
+  describe 'self.db_counter_payload' do
+    before do
+      allow(subscriber).to receive(:current_transaction)
+                             .at_least(:once)
+                             .and_return(transaction)
+    end
+
+    context 'when RequestStore is enabled', :request_store do
+      context 'when query is executed' do
+        let(:expected_payload) do
+          {
+            db_count: 1,
+            db_cached_count: 0,
+            db_write_count: 0
+          }
+        end
+
+        it 'returns correct payload' do
+          subscriber.sql(event)
+
+          expect(described_class.db_counter_payload).to eq(expected_payload)
+        end
+      end
+
+      context 'when query is not executed' do
+        let(:expected_payload) do
+          {
+            db_count: 0,
+            db_cached_count: 0,
+            db_write_count: 0
+          }
+        end
+
+        it 'returns correct payload' do
+          expect(described_class.db_counter_payload).to eq(expected_payload)
+        end
+      end
+    end
+
+    context 'when RequestStore is disabled' do
+      let(:expected_payload) { {} }
+
+      it 'returns empty payload' do
+        subscriber.sql(event)
+
+        expect(described_class.db_counter_payload).to eq(expected_payload)
+      end
+    end
+  end
 end

spec/lib/gitlab/metrics/transaction_spec.rb

@@ -114,15 +114,4 @@
       transaction.set(:meow, 1)
     end
   end
-
-  describe '#get' do
-    let(:prometheus_metric) { instance_double(Prometheus::Client::Counter, get: nil) }
-
-    it 'gets a metric' do
-      expect(described_class).to receive(:fetch_metric).with(:counter, :gitlab_transaction_meow_total).and_return(prometheus_metric)
-      expect(prometheus_metric).to receive(:get)
-
-      transaction.get(:meow, :counter)
-    end
-  end
 end