Log DB query request metrics (#4442)

* Log DB query request metrics

- number of queries per request
- accumulated query time

* Fix request metrics logging if log_db_queries is false

* if log_db_queries is falses, the two new fields would be logged but always with "0" as value

---------

Co-authored-by: Jochen Ehret <[email protected]>

Author: philippthun

lib/cloud_controller/db.rb

@@ -3,6 +3,7 @@
 require 'cloud_controller/db_connection/options_factory'
 require 'cloud_controller/db_connection/finalizer'
 require 'sequel/extensions/query_length_logging'
+require 'sequel/extensions/request_query_metrics'
 
 module VCAP::CloudController
   class DB
@@ -30,12 +31,13 @@ def self.connect(opts, logger)
         db.logger = logger
         db.sql_log_level = opts[:log_level]
         db.extension :caller_logging
-        db.caller_logging_ignore = /sequel_paginator|query_length_logging|sequel_pg|paginated_collection_renderer/
+        db.caller_logging_ignore = /sequel_paginator|query_length_logging|sequel_pg|paginated_collection_renderer|request_query_metrics/
         db.caller_logging_formatter = lambda do |caller|
           "(#{caller.sub(%r{^.*/cloud_controller_ng/}, '')})"
         end
 
         db.extension(:query_length_logging)
+        db.extension(:request_query_metrics)
         db.opts[:query_size_log_threshold] = opts[:query_size_log_threshold]
       end
       db.default_collate = 'utf8_bin' if db.database_type == :mysql

lib/cloud_controller/logs/request_logs.rb

@@ -26,15 +26,21 @@ def start_request(request_id, env)
         @incomplete_requests.store(request_id, env)
       end
 
-      def complete_request(request_id, status, env, time_taken)
+      def complete_request(request_id, status, env, time_taken_ms, total_db_query_time_us=nil, db_query_count=nil)
         return if @incomplete_requests.delete(request_id).nil?
 
         request = ActionDispatch::Request.new(env)
-        @logger.info("Completed #{status} vcap-request-id: #{request_id}",
-                     { status_code: status,
-                       time_taken_in_ms: time_taken,
-                       request_method: request.request_method,
-                       request_fullpath: request.filtered_path })
+
+        log_fields = {
+          status_code: status,
+          time_taken_in_ms: time_taken_ms,
+          request_method: request.request_method,
+          request_fullpath: request.filtered_path
+        }
+        log_fields[:total_db_query_time_in_ms] = (total_db_query_time_us.to_f / 1_000) unless total_db_query_time_us.nil?
+        log_fields[:db_query_count] = db_query_count unless db_query_count.nil?
+
+        @logger.info("Completed #{status} vcap-request-id: #{request_id}", log_fields)
       end
 
       def log_incomplete_requests

lib/sequel/extensions/request_query_metrics.rb

@@ -0,0 +1,15 @@
+# frozen_string_literal: true
+
+Sequel::Database.register_extension(:request_query_metrics) do |db|
+  mod = Module.new do
+    private
+
+    def log_duration(duration, message)
+      VCAP::Request.record_db_query((duration * 1_000_000).round)
+
+      super
+    end
+  end
+
+  db.singleton_class.prepend(mod)
+end

lib/vcap/request.rb

@@ -55,6 +55,29 @@ def b3_span_id=(span_id)
       def b3_span_id
         Thread.current[:b3_span_id]
       end
+
+      def db_query_metrics
+        init_db_query_metrics
+
+        Thread.current[:db_query_metrics]
+      end
+
+      def record_db_query(duration)
+        init_db_query_metrics
+
+        Thread.current[:db_query_metrics].total_query_time_us += duration
+        Thread.current[:db_query_metrics].query_count += 1
+      end
+
+      def reset_db_query_metrics
+        Thread.current[:db_query_metrics] = Struct.new(:total_query_time_us, :query_count).new(0, 0)
+      end
+
+      private
+
+      def init_db_query_metrics
+        reset_db_query_metrics if Thread.current[:db_query_metrics].nil?
+      end
     end
   end
 end

middleware/request_logs.rb

@@ -9,16 +9,26 @@ def initialize(app, request_logs)
       def call(env)
         request_id = env['cf.request_id']
         @request_logs.start_request(request_id, env)
-        start_time = Time.now
+        start_timer = timer
 
         status, headers, body = @app.call(env)
-        # convert to milliseconds
-        time_taken = (Time.now - start_time) * 1000
-        time_taken = time_taken.to_i
-        @request_logs.complete_request(request_id, status, env, time_taken)
+        time_taken_ms = timer - start_timer
+
+        args = [request_id, status, env, time_taken_ms]
+        if VCAP::CloudController::Config.config.get(:db, :log_db_queries)
+          db_query_metrics = ::VCAP::Request.db_query_metrics
+          args += [db_query_metrics.total_query_time_us, db_query_metrics.query_count]
+        end
+        @request_logs.complete_request(*args)
 
         [status, headers, body]
       end
+
+      private
+
+      def timer
+        Process.clock_gettime(Process::CLOCK_MONOTONIC, :millisecond)
+      end
     end
   end
 end

middleware/request_metrics.rb

@@ -7,6 +7,7 @@ def initialize(app, request_metrics)
       end
 
       def call(env)
+        ::VCAP::Request.reset_db_query_metrics
         @request_metrics.start_request
 
         status, headers, body = @app.call(env)

spec/unit/lib/cloud_controller/logs/request_logs_spec.rb

@@ -9,7 +9,9 @@ module VCAP::CloudController::Logs
     let(:fake_fullpath) { 'fullpath' }
     let(:fake_request) { double('request', request_method: 'request_method', ip: fake_ip, filtered_path: 'filtered_path', fullpath: fake_fullpath) }
     let(:request_id) { 'ID' }
-    let(:time_taken) { 30 }
+    let(:time_taken_ms) { 30 }
+    let(:total_db_query_time_us) { 123_456 }
+    let(:db_query_count) { 5 }
     let(:env) { { 'cf.user_guid' => 'user-guid' } }
     let(:status) { 200 }
 
@@ -46,10 +48,12 @@ module VCAP::CloudController::Logs
           end
 
           it 'logs the completion of the request' do
-            request_logs.complete_request(request_id, status, env, time_taken)
+            request_logs.complete_request(request_id, status, env, time_taken_ms, total_db_query_time_us, db_query_count)
             expect(logger).to have_received(:info).with(
               /\ACompleted 200 vcap-request-id: ID/,
               time_taken_in_ms: 30,
+              total_db_query_time_in_ms: 123.456,
+              db_query_count: 5,
               request_method: 'request_method',
               request_fullpath: 'filtered_path',
               status_code: 200
@@ -59,7 +63,7 @@ module VCAP::CloudController::Logs
 
         context 'without a matching start request' do
           it 'does not log the completion of the request' do
-            request_logs.complete_request(request_id, status, env, time_taken)
+            request_logs.complete_request(request_id, status, env, time_taken_ms, total_db_query_time_us, db_query_count)
             expect(logger).not_to have_received(:info)
           end
         end

spec/unit/lib/sequel/extensions/request_query_metrics_spec.rb

@@ -0,0 +1,26 @@
+require 'spec_helper'
+
+RSpec.describe 'request_query_metrics' do
+  let(:db) { DbConfig.new.connection }
+
+  before do
+    # Add a logger to the database connection to ensure that the duration is captured
+    db.loggers << Logger.new(StringIO.new)
+    db.extension(:request_query_metrics)
+    allow(VCAP::Request).to receive(:record_db_query).and_wrap_original do |original_method|
+      original_method.call(1_234)
+    end
+  end
+
+  it 'increments the thread local total query time on each query' do
+    expect do
+      2.times { db.fetch('SELECT 1').all }
+    end.to change(VCAP::Request.db_query_metrics, :total_query_time_us).by(2_468)
+  end
+
+  it 'increments the thread local query count on each query' do
+    expect do
+      db.fetch('SELECT 1').all
+    end.to change(VCAP::Request.db_query_metrics, :query_count).by(1)
+  end
+end

spec/unit/middleware/request_logs_spec.rb

@@ -10,6 +10,10 @@ module Middleware
       let(:env) { { 'cf.request_id' => 'ID' } }
 
       describe 'handling the request' do
+        before do
+          VCAP::CloudController::Config.config.get(:db)[:log_db_queries] = true
+        end
+
         it 'calls start request on request logs before the request' do
           middleware.call(env)
           expect(request_logs).to have_received(:start_request).with('ID', env)
@@ -20,6 +24,17 @@ module Middleware
         end
 
         it 'calls complete request on request logs after the request' do
+          middleware.call(env)
+          expect(request_logs).to have_received(:complete_request).with('ID', 200, { 'cf.request_id' => 'ID' }, be_a(Numeric), be_a(Numeric), be_a(Numeric))
+        end
+      end
+
+      describe 'when db query logging is disabled' do
+        before do
+          VCAP::CloudController::Config.config.get(:db)[:log_db_queries] = false
+        end
+
+        it 'calls complete request on request logs without db query metrics' do
           middleware.call(env)
           expect(request_logs).to have_received(:complete_request).with('ID', 200, { 'cf.request_id' => 'ID' }, be_a(Numeric))
         end

spec/unit/middleware/request_metrics_spec.rb

@@ -9,7 +9,8 @@ module Middleware
       let(:request_metrics) { instance_double(VCAP::CloudController::Metrics::RequestMetrics, start_request: nil, complete_request: nil) }
 
       describe 'handling the request' do
-        it 'calls start request on request metrics before the request' do
+        it 'resets the db query count and calls start request on request metrics before the request' do
+          expect(VCAP::Request).to receive(:reset_db_query_metrics)
           middleware.call({})
           expect(request_metrics).to have_received(:start_request)
         end