Merge branch 'sh-log-redis-calls' into 'master'

Log Redis call count and duration to log files

Closes #208821

See merge request gitlab-org/gitlab!27735

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