Log DB query counts per request

Author: philippthun

lib/cloud_controller/metrics/prometheus_updater.rb

@@ -19,7 +19,6 @@ def self.allow_pid_label
     DURATION_BUCKETS = [5, 10, 30, 60, 300, 600, 890].freeze
     CONNECTION_DURATION_BUCKETS = [0.001, 0.005, 0.01, 0.05, 0.1, 0.5, 1, 5, 10].freeze
     DELAYED_JOB_METRIC_BUCKETS = [0.01, 0.05, 0.1, 0.5, 1, 2, 5, 10, 30, 60, 120, 300, 600].freeze
-    DB_QUERY_BUCKETS = [1, 2, 5, 10, 20, 50, 100].freeze
 
     METRICS = [
       { type: :gauge, name: :cc_job_queues_length_total, docstring: 'Job queues length of worker processes', labels: [:queue], aggregation: :most_recent },
@@ -30,7 +29,6 @@ def self.allow_pid_label
       { type: :histogram, name: :cc_staging_failed_duration_seconds, docstring: 'Durations of failed staging events', buckets: DURATION_BUCKETS },
       { type: :gauge, name: :cc_requests_outstanding_total, docstring: 'Requests outstanding', aggregation: :sum },
       { type: :counter, name: :cc_requests_completed_total, docstring: 'Requests completed' },
-      { type: :histogram, name: :cc_request_db_queries_total, docstring: 'Database queries per request', buckets: DB_QUERY_BUCKETS },
       { type: :gauge, name: :cc_vitals_started_at, docstring: 'CloudController Vitals: started_at', aggregation: :most_recent },
       { type: :gauge, name: :cc_vitals_mem_bytes, docstring: 'CloudController Vitals: mem_bytes', aggregation: :most_recent },
       { type: :gauge, name: :cc_vitals_cpu_load_avg, docstring: 'CloudController Vitals: cpu_load_avg', aggregation: :most_recent },
@@ -126,10 +124,6 @@ def update_user_count(user_count)
       update_gauge_metric(:cc_users_total, user_count)
     end
 
-    def update_db_query_count(query_count)
-      update_histogram_metric(:cc_request_db_queries_total, query_count)
-    end
-
     def update_job_queue_length(pending_job_count_by_queue)
       pending_job_count_by_queue.each do |key, value|
         update_gauge_metric(:cc_job_queues_length_total, value, labels: { queue: key.to_s.underscore })

lib/cloud_controller/metrics/request_metrics.rb

@@ -14,13 +14,10 @@ def start_request
       end
 
       def complete_request(status)
-        query_count = VCAP::Request.db_query_count
         @statsd_updater.complete_request(status)
-        @statsd_updater.record_db_query_count(query_count) if query_count
 
         @prometheus_updater.increment_counter_metric(:cc_requests_completed_total)
         @prometheus_updater.decrement_gauge_metric(:cc_requests_outstanding_total)
-        @prometheus_updater.update_db_query_count(query_count) if query_count
       end
     end
   end

lib/cloud_controller/metrics/statsd_updater.rb

@@ -110,10 +110,6 @@ def complete_request(status)
       end
     end
 
-    def record_db_query_count(query_count)
-      @statsd.gauge('cc.request.db_query_count', query_count)
-    end
-
     private
 
     def nanoseconds_to_milliseconds(time_ns)

lib/vcap/request.rb

@@ -56,10 +56,6 @@ def b3_span_id
         Thread.current[:b3_span_id]
       end
 
-      def db_query_count=(count)
-        Thread.current[:db_query_count] = count
-      end
-
       def db_query_count
         Thread.current[:db_query_count]
       end

middleware/request_logs.rb

@@ -8,8 +8,8 @@ def initialize(app, request_logs)
 
       def call(env)
         request_id = env['cf.request_id']
-        VCAP::Request.reset_db_query_count
         @request_logs.start_request(request_id, env)
+        VCAP::Request.reset_db_query_count
         start_time = Time.now
 
         status, headers, body = @app.call(env)

middleware/request_metrics.rb

@@ -7,7 +7,6 @@ def initialize(app, request_metrics)
       end
 
       def call(env)
-        VCAP::Request.db_query_count = 0
         @request_metrics.start_request
 
         status, headers, body = @app.call(env)
@@ -18,9 +17,7 @@ def call(env)
         status = 500
         raise e
       ensure
-        query_count = VCAP::Request.db_query_count
-        VCAP::Request.db_query_count = nil
-        @request_metrics.complete_request(status, query_count)
+        @request_metrics.complete_request(status)
       end
     end
   end

spec/unit/lib/cloud_controller/metrics/prometheus_updater_spec.rb

@@ -60,16 +60,6 @@ module VCAP::CloudController::Metrics
       end
     end
 
-    describe '#update_db_query_count' do
-      it 'records queries per request' do
-        updater.update_db_query_count(7)
-
-        metric = prom_client.metrics.find { |m| m.name == :cc_request_db_queries_total }
-        expect(metric).to be_present
-        expect(metric.get['sum']).to eq 7.0
-      end
-    end
-
     describe '#update_job_queue_length' do
       it 'records the length of the delayed job queues and total' do
         expected_local_length   = 5
@@ -288,6 +278,5 @@ module VCAP::CloudController::Metrics
         expect(metric.get).to eq({ '5' => 0.0, '10' => 0.0, '30' => 0.0, '60' => 0.0, '300' => 0.0, '600' => 0.0, '890' => 0.0, 'sum' => 900.0, '+Inf' => 1.0 })
       end
     end
-
   end
 end

spec/unit/lib/cloud_controller/metrics/request_metrics_spec.rb

@@ -32,29 +32,15 @@ module VCAP::CloudController::Metrics
       let(:status) { 204 }
 
       it 'increments completed, decrements outstanding, increments status for statsd' do
-        allow(statsd_updater).to receive(:record_db_query_count)
-        allow(prometheus_client).to receive(:update_db_query_count)
-
-        VCAP::Request.reset_db_query_count
-        VCAP::Request.increment_db_query_count
-
         request_metrics.complete_request(status)
         expect(statsd_updater).to have_received(:complete_request).with(status)
-        expect(statsd_updater).to have_received(:record_db_query_count).with(1)
       end
 
       it 'increments completed and decrements outstanding for prometheus' do
-        allow(statsd_updater).to receive(:record_db_query_count)
-        allow(prometheus_client).to receive(:update_db_query_count)
-
-        VCAP::Request.reset_db_query_count
-        VCAP::Request.increment_db_query_count
-
         request_metrics.complete_request(status)
 
         expect(prometheus_client).to have_received(:decrement_gauge_metric).with(:cc_requests_outstanding_total)
         expect(prometheus_client).to have_received(:increment_counter_metric).with(:cc_requests_completed_total)
-        expect(prometheus_client).to have_received(:update_db_query_count).with(1)
       end
     end
   end

spec/unit/lib/cloud_controller/metrics/statsd_updater_spec.rb

@@ -300,7 +300,7 @@ module VCAP::CloudController::Metrics
       end
     end
 
-  describe '#complete_request' do
+    describe '#complete_request' do
       let(:batch) { double(:batch) }
       let(:status) { 204 }
 
@@ -457,15 +457,4 @@ module VCAP::CloudController::Metrics
       end
     end
   end
-
-  describe '#record_db_query_count' do
-    before do
-      allow(statsd_client).to receive(:gauge)
-    end
-
-    it 'records database query counts' do
-      updater.record_db_query_count(3)
-      expect(statsd_client).to have_received(:gauge).with('cc.request.db_query_count', 3)
-    end
-  end
 end

spec/unit/middleware/request_metrics_spec.rb

@@ -20,7 +20,7 @@ module Middleware
 
         it 'calls complete request on request metrics after the request' do
           middleware.call({})
-          expect(request_metrics).to have_received(:complete_request).with(200, an_instance_of(Integer))
+          expect(request_metrics).to have_received(:complete_request).with(200)
         end
 
         context 'when an unexpected error occurs' do
@@ -33,7 +33,7 @@ module Middleware
 
           it 'catches the exception and calls complete request on request metrics' do
             expect { middleware.call({}) }.to raise_error('Unexpected') do
-              expect(request_metrics).to have_received(:complete_request).with(500, an_instance_of(Integer))
+              expect(request_metrics).to have_received(:complete_request).with(500)
             end
           end
         end