Track and report DB query counts

Author: philippthun

lib/cloud_controller/metrics/prometheus_updater.rb

@@ -19,6 +19,7 @@ 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 },
@@ -29,6 +30,7 @@ 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 },
@@ -124,6 +126,10 @@ 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

@@ -13,11 +13,14 @@ def start_request
         @prometheus_updater.increment_gauge_metric(:cc_requests_outstanding_total)
       end
 
-      def complete_request(status, query_count)
+      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,6 +110,10 @@ 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/sequel/extensions/request_query_counter.rb

@@ -1,7 +1,7 @@
 module Sequel
   module RequestQueryCounter
     def log_connection_yield(sql, conn, args=nil)
-      VCAP::Request.db_query_count = (VCAP::Request.db_query_count || 0) + 1
+      VCAP::Request.increment_db_query_count
       super
     end
   end

lib/vcap/request.rb

@@ -63,6 +63,15 @@ def db_query_count=(count)
       def db_query_count
         Thread.current[:db_query_count]
       end
+
+      def increment_db_query_count
+        Thread.current[:db_query_count] ||= 0
+        Thread.current[:db_query_count] += 1
+      end
+
+      def reset_db_query_count
+        Thread.current[:db_query_count] = 0
+      end
     end
   end
 end

middleware/request_logs.rb

@@ -8,6 +8,7 @@ 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)
         start_time = Time.now
 

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

@@ -60,6 +60,16 @@ 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

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

@@ -32,15 +32,29 @@ module VCAP::CloudController::Metrics
       let(:status) { 204 }
 
       it 'increments completed, decrements outstanding, increments status for statsd' do
-        request_metrics.complete_request(status, 5)
+        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
-        request_metrics.complete_request(status, 5)
+        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,4 +457,15 @@ 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/lib/sequel/extensions/request_query_counter_spec.rb

@@ -8,7 +8,7 @@
   end
 
   it 'increments the thread local query count on each query' do
-    VCAP::Request.db_query_count = 0
+    VCAP::Request.reset_db_query_count
     db.fetch('SELECT 1').all
     expect(VCAP::Request.db_query_count).to eq(1)
   end