Log Redis call count and duration to log files

It has been difficult to see trends in the number of Redis calls without
having the number and duration of the calls in structured logs. This
commit adds `redis_calls` and `redis_duration_ms` fields to all relevant
logs (e.g. api_json.log, production_json.log, Sidekiq, etc.).

Closes https://gitlab.com/gitlab-org/gitlab/issues/208821

changelogs/unreleased/sh-log-redis-calls.yml

+---
+title: Log Redis call count and duration to log files
+merge_request: 27735
+author:
+type: other

lib/gitlab/grape_logging/loggers/perf_logger.rb

@@ -5,30 +5,11 @@ module Gitlab
   module GrapeLogging
     module Loggers
       class PerfLogger < ::GrapeLogging::Loggers::Base
-        def parameters(_, _)
-          gitaly_data.merge(rugged_data)
-        end
-
-        def gitaly_data
-          gitaly_calls = Gitlab::GitalyClient.get_request_count
+        include ::Gitlab::InstrumentationHelper
 
-          return {} if gitaly_calls.zero?
-
-          {
-            gitaly_calls: Gitlab::GitalyClient.get_request_count,
-            gitaly_duration: Gitlab::GitalyClient.query_time_ms
-          }
-        end
-
-        def rugged_data
-          rugged_calls = Gitlab::RuggedInstrumentation.query_count
-
-          return {} if rugged_calls.zero?
-
-          {
-            rugged_calls: rugged_calls,
-            rugged_duration_ms: Gitlab::RuggedInstrumentation.query_time_ms
-          }
+        def parameters(_, _)
+          payload = {}
+          payload.tap { add_instrumentation_data(payload) }
         end
       end
     end

lib/gitlab/instrumentation/redis.rb

+# frozen_string_literal: true
+
+require 'redis'
+
+module Gitlab
+  module Instrumentation
+    module RedisInterceptor
+      def call(*args, &block)
+        start = Time.now
+        super(*args, &block)
+      ensure
+        duration = (Time.now - start)
+
+        if ::RequestStore.active?
+          ::Gitlab::Instrumentation::Redis.increment_request_count
+          ::Gitlab::Instrumentation::Redis.add_duration(duration)
+          ::Gitlab::Instrumentation::Redis.add_call_details(duration, args)
+        end
+      end
+    end
+
+    class Redis
+      REDIS_REQUEST_COUNT = :redis_request_count
+      REDIS_CALL_DURATION = :redis_call_duration
+      REDIS_CALL_DETAILS = :redis_call_details
+
+      def self.get_request_count
+        ::RequestStore[REDIS_REQUEST_COUNT] || 0
+      end
+
+      def self.increment_request_count
+        ::RequestStore[REDIS_REQUEST_COUNT] ||= 0
+        ::RequestStore[REDIS_REQUEST_COUNT] += 1
+      end
+
+      def self.detail_store
+        ::RequestStore[REDIS_CALL_DETAILS] ||= []
+      end
+
+      def self.query_time_ms
+        (self.query_time * 1000).round(2)
+      end
+
+      def self.query_time
+        ::RequestStore[REDIS_CALL_DURATION] || 0
+      end
+
+      def self.add_duration(duration)
+        total_time = query_time + duration
+        ::RequestStore[REDIS_CALL_DURATION] = total_time
+      end
+
+      def self.add_call_details(duration, args)
+        return unless Gitlab::PerformanceBar.enabled_for_request?
+        # redis-rb passes an array (e.g. [:get, key])
+        return unless args.length == 1
+
+        detail_store << {
+          cmd: args.first,
+          duration: duration,
+          backtrace: ::Gitlab::BacktraceCleaner.clean_backtrace(caller)
+        }
+      end
+    end
+  end
+end
+
+class ::Redis::Client
+  prepend ::Gitlab::Instrumentation::RedisInterceptor
+end

lib/gitlab/instrumentation_helper.rb

@@ -4,7 +4,7 @@ module Gitlab
   module InstrumentationHelper
     extend self
 
-    KEYS = %i(gitaly_calls gitaly_duration rugged_calls rugged_duration_ms).freeze
+    KEYS = %i(gitaly_calls gitaly_duration rugged_calls rugged_duration_ms redis_calls redis_duration_ms).freeze
 
     def add_instrumentation_data(payload)
       gitaly_calls = Gitlab::GitalyClient.get_request_count
@@ -20,6 +20,13 @@ module Gitlab
         payload[:rugged_calls] = rugged_calls
         payload[:rugged_duration_ms] = Gitlab::RuggedInstrumentation.query_time_ms
       end
+
+      redis_calls = Gitlab::Instrumentation::Redis.get_request_count
+
+      if redis_calls > 0
+        payload[:redis_calls] = redis_calls
+        payload[:redis_duration_ms] = Gitlab::Instrumentation::Redis.query_time_ms
+      end
     end
 
     # Returns the queuing duration for a Sidekiq job in seconds, as a float, if the

lib/peek/views/detailed_view.rb

@@ -17,7 +17,7 @@ module Peek
       end
 
       def detail_store
-        ::Gitlab::SafeRequestStore["#{key}_call_details"] ||= []
+        ::Gitlab::SafeRequestStore["#{key}_call_details".to_sym] ||= []
       end
 
       private

lib/peek/views/redis_detailed.rb

 # frozen_string_literal: true
 
-require 'redis'
-
-module Gitlab
-  module Peek
-    module RedisInstrumented
-      def call(*args, &block)
-        start = Time.now
-        super(*args, &block)
-      ensure
-        duration = (Time.now - start)
-        add_call_details(duration, args)
-      end
-
-      private
-
-      def add_call_details(duration, args)
-        return unless Gitlab::PerformanceBar.enabled_for_request?
-        # redis-rb passes an array (e.g. [:get, key])
-        return unless args.length == 1
-
-        detail_store << {
-          cmd: args.first,
-          duration: duration,
-          backtrace: ::Gitlab::BacktraceCleaner.clean_backtrace(caller)
-        }
-      end
-
-      def detail_store
-        ::Gitlab::SafeRequestStore['redis_call_details'] ||= []
-      end
-    end
-  end
-end
-
 module Peek
   module Views
     class RedisDetailed < DetailedView
@@ -63,7 +29,3 @@ module Peek
     end
   end
 end
-
-class Redis::Client
-  prepend Gitlab::Peek::RedisInstrumented
-end

spec/lib/gitlab/grape_logging/loggers/perf_logger_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+describe Gitlab::GrapeLogging::Loggers::PerfLogger do
+  subject { described_class.new }
+
+  describe ".parameters" do
+    let(:mock_request) { OpenStruct.new(env: {}) }
+
+    describe 'when no performance datais are present' do
+      it 'returns an empty Hash' do
+        expect(subject.parameters(mock_request, nil)).to eq({})
+      end
+    end
+
+    describe 'when Redis calls are present', :request_store do
+      it 'returns a Hash with Redis information' do
+        Gitlab::Redis::SharedState.with { |redis| redis.get('perf-logger-test') }
+
+        payload = subject.parameters(mock_request, nil)
+
+        expect(payload[:redis_calls]).to eq(1)
+        expect(payload[:redis_duration_ms]).to be >= 0
+      end
+    end
+  end
+end

spec/lib/gitlab/instrumentation_helper_spec.rb

 # frozen_string_literal: true
 
-require 'fast_spec_helper'
+require 'spec_helper'
 require 'rspec-parameterized'
 
 describe Gitlab::InstrumentationHelper do
   using RSpec::Parameterized::TableSyntax
 
+  describe '.add_instrumentation_data', :request_store do
+    let(:payload) { {} }
+
+    subject { described_class.add_instrumentation_data(payload) }
+
+    it 'adds nothing' do
+      subject
+
+      expect(payload).to eq({})
+    end
+
+    context 'when Gitaly calls are made' do
+      it 'adds Gitaly data and omits Redis data' do
+        project = create(:project)
+        RequestStore.clear!
+        project.repository.exists?
+
+        subject
+
+        expect(payload[:gitaly_calls]).to eq(1)
+        expect(payload[:gitaly_duration]).to be >= 0
+        expect(payload[:redis_calls]).to be_nil
+        expect(payload[:redis_duration_ms]).to be_nil
+      end
+    end
+
+    context 'when Redis calls are made' do
+      it 'adds Redis data and omits Gitaly data' do
+        Gitlab::Redis::Cache.with { |redis| redis.get('test-instrumentation') }
+
+        subject
+
+        expect(payload[:redis_calls]).to eq(1)
+        expect(payload[:redis_duration_ms]).to be >= 0
+        expect(payload[:gitaly_calls]).to be_nil
+        expect(payload[:gitaly_duration]).to be_nil
+      end
+    end
+  end
+
   describe '.queue_duration_for_job' do
     where(:enqueued_at, :created_at, :time_now, :expected_duration) do
       "2019-06-01T00:00:00.000+0000" | nil                            | "2019-06-01T02:00:00.000+0000" | 2.hours.to_f

spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb

@@ -175,26 +175,30 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
       end
     end
 
-    context 'with Gitaly and Rugged calls' do
+    context 'with Gitaly, Rugged, and Redis calls' do
       let(:timing_data) do
         {
           gitaly_calls: 10,
           gitaly_duration: 10000,
           rugged_calls: 1,
-          rugged_duration_ms: 5000
+          rugged_duration_ms: 5000,
+          redis_calls: 3,
+          redis_duration_ms: 1234
         }
       end
 
-      before do
-        job.merge!(timing_data)
+      let(:expected_end_payload) do
+        end_payload.except('args').merge(timing_data)
       end
 
       it 'logs with Gitaly and Rugged timing data' do
         Timecop.freeze(timestamp) do
           expect(logger).to receive(:info).with(start_payload.except('args')).ordered
-          expect(logger).to receive(:info).with(end_payload.except('args')).ordered
+          expect(logger).to receive(:info).with(expected_end_payload).ordered
 
-          subject.call(job, 'test_queue') { }
+          subject.call(job, 'test_queue') do
+            job.merge!(timing_data)
+          end
         end
       end
     end