Add Redis logs for each Redis instance

It introduces detailed logs for each Redis instance.

Before this change, we used to have just the following
Redis logs for API, Sidekiq and Web requests:

- redis_calls
- redis_duration_s
- redis_read_bytes
- redis_write_bytes

Here we introduce the following (when > 0):

- redis_action_cable_calls
- redis_action_cable_duration_s
- redis_action_cable_read_bytes
- redis_action_cable_write_bytes
- redis_cache_calls
- redis_cache_duration_s
- redis_cache_read_bytes
- redis_cache_write_bytes
- redis_queues_calls
- redis_queues_duration_s
- redis_queues_read_bytes
- redis_queues_write_bytes
- redis_shared_state_calls
- redis_shared_state_duration_s
- redis_shared_state_read_bytes
- redis_shared_state_write_bytes

That's valuable information about how GitLab
use Redis instances.

changelogs/unreleased/osw-separate-redis-logs.yml

+---
+title: Add detailed logs of each Redis instance usage during job execution and web
+  requests
+merge_request: 34110
+author:
+type: added

doc/administration/logs.md

@@ -64,13 +64,17 @@ seconds:
 1. `queue_duration_s`: total time that the request was queued inside GitLab Workhorse
 1. `view_duration_s`: total time taken inside the Rails views
 1. `db_duration_s`: total time to retrieve data from PostgreSQL
-1. `redis_duration_s`: total time to retrieve data from Redis
 1. `cpu_s`: total time spent on CPU
 1. `gitaly_duration_s`: total time taken by Gitaly calls
 1. `gitaly_calls`: total number of calls made to Gitaly
 1. `redis_calls`: total number of calls made to Redis
+1. `redis_duration_s`: total time to retrieve data from Redis
 1. `redis_read_bytes`: total bytes read from Redis
 1. `redis_write_bytes`: total bytes written to Redis
+1. `redis_<instance>_calls`: total number of calls made to a Redis instance
+1. `redis_<instance>_duration_s`: total time to retrieve data from a Redis instance
+1. `redis_<instance>_read_bytes`: total bytes read from a Redis instance
+1. `redis_<instance>_write_bytes`: total bytes written to a Redis instance
 
 User clone and fetch activity using HTTP transport appears in this log as `action: git_upload_pack`.
 

lib/gitlab/instrumentation/redis.rb

@@ -15,6 +15,20 @@ module Gitlab
       QUERY_TIME_BUCKETS = [0.001, 0.0025, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2].freeze
 
       class << self
+        include ::Gitlab::Instrumentation::RedisPayload
+
+        def storage_key
+          nil
+        end
+
+        def known_payload_keys
+          super + STORAGES.flat_map(&:known_payload_keys)
+        end
+
+        def payload
+          super.merge(*STORAGES.flat_map(&:payload))
+        end
+
         def detail_store
           STORAGES.flat_map(&:detail_store)
         end

lib/gitlab/instrumentation/redis_base.rb

@@ -7,11 +7,12 @@ module Gitlab
     class RedisBase
       class << self
         include ::Gitlab::Utils::StrongMemoize
+        include ::Gitlab::Instrumentation::RedisPayload
 
         # TODO: To be used by https://gitlab.com/gitlab-com/gl-infra/scalability/-/issues/395
         # as a 'label' alias.
         def storage_key
-          self.name.underscore
+          self.name.demodulize.underscore
         end
 
         def add_duration(duration)

lib/gitlab/instrumentation/redis_payload.rb

+# frozen_string_literal: true
+
+module Gitlab
+  module Instrumentation
+    module RedisPayload
+      include ::Gitlab::Utils::StrongMemoize
+
+      # Fetches payload keys from the lazy payload (this avoids
+      # unnecessary processing of the values).
+      def known_payload_keys
+        to_lazy_payload.keys
+      end
+
+      def payload
+        to_lazy_payload.transform_values do |value|
+          result = value.call
+          result if result > 0
+        end.compact
+      end
+
+      private
+
+      def to_lazy_payload
+        strong_memoize(:to_lazy_payload) do
+          key_prefix = storage_key ? "redis_#{storage_key}" : 'redis'
+
+          {
+            "#{key_prefix}_calls": -> { get_request_count },
+            "#{key_prefix}_duration_s": -> { query_time },
+            "#{key_prefix}_read_bytes": -> { read_bytes },
+            "#{key_prefix}_write_bytes": -> { write_bytes }
+          }.symbolize_keys
+        end
+      end
+    end
+  end
+end

lib/gitlab/instrumentation_helper.rb

@@ -4,26 +4,22 @@ module Gitlab
   module InstrumentationHelper
     extend self
 
-    KEYS = %i(
-      gitaly_calls
-      gitaly_duration_s
-      rugged_calls
-      rugged_duration_s
-      redis_calls
-      redis_duration_s
-      redis_read_bytes
-      redis_write_bytes
-      elasticsearch_calls
-      elasticsearch_duration_s
-    ).freeze
-
     DURATION_PRECISION = 6 # microseconds
 
+    def keys
+      @keys ||= [:gitaly_calls,
+                 :gitaly_duration_s,
+                 :rugged_calls,
+                 :rugged_duration_s,
+                 :elasticsearch_calls,
+                 :elasticsearch_duration_s,
+                 *::Gitlab::Instrumentation::Redis.known_payload_keys]
+    end
+
     def add_instrumentation_data(payload)
       instrument_gitaly(payload)
       instrument_rugged(payload)
       instrument_redis(payload)
-      instrument_redis_bytes(payload)
       instrument_elasticsearch(payload)
     end
 
@@ -46,22 +42,7 @@ module Gitlab
     end
 
     def instrument_redis(payload)
-      redis_calls = Gitlab::Instrumentation::Redis.get_request_count
-
-      return if redis_calls == 0
-
-      payload[:redis_calls] = redis_calls
-      payload[:redis_duration_s] = Gitlab::Instrumentation::Redis.query_time
-    end
-
-    def instrument_redis_bytes(payload)
-      redis_read_bytes = Gitlab::Instrumentation::Redis.read_bytes
-      redis_write_bytes = Gitlab::Instrumentation::Redis.write_bytes
-
-      return if redis_read_bytes == 0 && redis_write_bytes == 0
-
-      payload[:redis_read_bytes] = redis_read_bytes
-      payload[:redis_write_bytes] = redis_write_bytes
+      payload.merge! ::Gitlab::Instrumentation::Redis.payload
     end
 
     def instrument_elasticsearch(payload)

lib/gitlab/sidekiq_logging/structured_logger.rb

@@ -27,7 +27,7 @@ module Gitlab
       private
 
       def add_instrumentation_keys!(job, output_payload)
-        output_payload.merge!(job.slice(*::Gitlab::InstrumentationHelper::KEYS))
+        output_payload.merge!(job.slice(*::Gitlab::InstrumentationHelper.keys))
       end
 
       def add_logging_extras!(job, output_payload)

spec/lib/gitlab/instrumentation/redis_base_spec.rb

@@ -4,17 +4,52 @@ require 'spec_helper'
 
 describe Gitlab::Instrumentation::RedisBase, :request_store do
   let(:instrumentation_class_a) do
-    stub_const('RedisInstanceA', Class.new(described_class))
+    stub_const('InstanceA', Class.new(described_class))
   end
 
   let(:instrumentation_class_b) do
-    stub_const('RedisInstanceB', Class.new(described_class))
+    stub_const('InstanceB', Class.new(described_class))
   end
 
   describe '.storage_key' do
     it 'returns the class name with underscore' do
-      expect(instrumentation_class_a.storage_key).to eq('redis_instance_a')
-      expect(instrumentation_class_b.storage_key).to eq('redis_instance_b')
+      expect(instrumentation_class_a.storage_key).to eq('instance_a')
+      expect(instrumentation_class_b.storage_key).to eq('instance_b')
+    end
+  end
+
+  describe '.known_payload_keys' do
+    it 'returns generated payload keys' do
+      expect(instrumentation_class_a.known_payload_keys).to eq([:redis_instance_a_calls,
+                                                                :redis_instance_a_duration_s,
+                                                                :redis_instance_a_read_bytes,
+                                                                :redis_instance_a_write_bytes])
+    end
+
+    it 'does not call calculation methods' do
+      expect(instrumentation_class_a).not_to receive(:get_request_count)
+      expect(instrumentation_class_a).not_to receive(:query_time)
+      expect(instrumentation_class_a).not_to receive(:read_bytes)
+      expect(instrumentation_class_a).not_to receive(:write_bytes)
+
+      instrumentation_class_a.known_payload_keys
+    end
+  end
+
+  describe '.payload' do
+    it 'returns values that are higher than 0' do
+      allow(instrumentation_class_a).to receive(:get_request_count) { 1 }
+      allow(instrumentation_class_a).to receive(:query_time) { 0.1 }
+      allow(instrumentation_class_a).to receive(:read_bytes) { 0.0 }
+      allow(instrumentation_class_a).to receive(:write_bytes) { 123 }
+
+      expected_payload = {
+        redis_instance_a_calls: 1,
+        redis_instance_a_write_bytes: 123,
+        redis_instance_a_duration_s: 0.1
+      }
+
+      expect(instrumentation_class_a.payload).to eq(expected_payload)
     end
   end
 

spec/lib/gitlab/instrumentation/redis_spec.rb

@@ -25,4 +25,76 @@ describe Gitlab::Instrumentation::Redis do
   it_behaves_like 'aggregation of redis storage data', :query_time
   it_behaves_like 'aggregation of redis storage data', :read_bytes
   it_behaves_like 'aggregation of redis storage data', :write_bytes
+
+  describe '.known_payload_keys' do
+    it 'returns all known payload keys' do
+      expected_keys = [
+        :redis_calls,
+        :redis_duration_s,
+        :redis_read_bytes,
+        :redis_write_bytes,
+        :redis_action_cable_calls,
+        :redis_action_cable_duration_s,
+        :redis_action_cable_read_bytes,
+        :redis_action_cable_write_bytes,
+        :redis_cache_calls,
+        :redis_cache_duration_s,
+        :redis_cache_read_bytes,
+        :redis_cache_write_bytes,
+        :redis_queues_calls,
+        :redis_queues_duration_s,
+        :redis_queues_read_bytes,
+        :redis_queues_write_bytes,
+        :redis_shared_state_calls,
+        :redis_shared_state_duration_s,
+        :redis_shared_state_read_bytes,
+        :redis_shared_state_write_bytes
+      ]
+
+      expect(described_class.known_payload_keys).to eq(expected_keys)
+    end
+
+    it 'does not call storage calculation methods' do
+      described_class::STORAGES.each do |storage|
+        expect(storage).not_to receive(:get_request_count)
+        expect(storage).not_to receive(:query_time)
+        expect(storage).not_to receive(:read_bytes)
+        expect(storage).not_to receive(:write_bytes)
+      end
+
+      described_class.known_payload_keys
+    end
+  end
+
+  describe '.payload', :request_store do
+    before do
+      Gitlab::Redis::Cache.with { |redis| redis.set('cache-test', 321) }
+      Gitlab::Redis::SharedState.with { |redis| redis.set('shared-state-test', 123) }
+    end
+
+    it 'returns payload filtering out zeroed values' do
+      expected_payload = {
+        # Aggregated results
+        redis_calls: 2,
+        redis_duration_s: be >= 0,
+        redis_read_bytes: be >= 0,
+        redis_write_bytes: be >= 0,
+
+        # Cache results
+        redis_cache_calls: 1,
+        redis_cache_duration_s: be >= 0,
+        redis_cache_read_bytes: be >= 0,
+        redis_cache_write_bytes: be >= 0,
+
+        # Shared state results
+        redis_shared_state_calls: 1,
+        redis_shared_state_duration_s: be >= 0,
+        redis_shared_state_read_bytes: be >= 0,
+        redis_shared_state_write_bytes: be >= 0
+      }
+
+      expect(described_class.payload).to include(expected_payload)
+      expect(described_class.payload.keys).to match_array(expected_payload.keys)
+    end
+  end
 end

spec/lib/gitlab/instrumentation_helper_spec.rb

@@ -6,6 +6,41 @@ require 'rspec-parameterized'
 describe Gitlab::InstrumentationHelper do
   using RSpec::Parameterized::TableSyntax
 
+  describe '.keys' do
+    it 'returns all available payload keys' do
+      expected_keys = [
+        :gitaly_calls,
+        :gitaly_duration_s,
+        :rugged_calls,
+        :rugged_duration_s,
+        :elasticsearch_calls,
+        :elasticsearch_duration_s,
+        :redis_calls,
+        :redis_duration_s,
+        :redis_read_bytes,
+        :redis_write_bytes,
+        :redis_action_cable_calls,
+        :redis_action_cable_duration_s,
+        :redis_action_cable_read_bytes,
+        :redis_action_cable_write_bytes,
+        :redis_cache_calls,
+        :redis_cache_duration_s,
+        :redis_cache_read_bytes,
+        :redis_cache_write_bytes,
+        :redis_queues_calls,
+        :redis_queues_duration_s,
+        :redis_queues_read_bytes,
+        :redis_queues_write_bytes,
+        :redis_shared_state_calls,
+        :redis_shared_state_duration_s,
+        :redis_shared_state_read_bytes,
+        :redis_shared_state_write_bytes
+      ]
+
+      expect(described_class.keys).to eq(expected_keys)
+    end
+  end
+
   describe '.add_instrumentation_data', :request_store do
     let(:payload) { {} }
 
@@ -34,14 +69,30 @@ describe Gitlab::InstrumentationHelper do
 
     context 'when Redis calls are made' do
       it 'adds Redis data and omits Gitaly data' do
-        Gitlab::Redis::Cache.with { |redis| redis.set('test-instrumentation', 123) }
+        Gitlab::Redis::Cache.with { |redis| redis.set('test-cache', 123) }
+        Gitlab::Redis::Queues.with { |redis| redis.set('test-queues', 321) }
 
         subject
 
-        expect(payload[:redis_calls]).to eq(1)
+        # Aggregated payload
+        expect(payload[:redis_calls]).to eq(2)
         expect(payload[:redis_duration_s]).to be >= 0
         expect(payload[:redis_read_bytes]).to be >= 0
         expect(payload[:redis_write_bytes]).to be >= 0
+
+        # Shared state payload
+        expect(payload[:redis_queues_calls]).to eq(1)
+        expect(payload[:redis_queues_duration_s]).to be >= 0
+        expect(payload[:redis_queues_read_bytes]).to be >= 0
+        expect(payload[:redis_queues_write_bytes]).to be >= 0
+
+        # Cache payload
+        expect(payload[:redis_cache_calls]).to eq(1)
+        expect(payload[:redis_cache_duration_s]).to be >= 0
+        expect(payload[:redis_cache_read_bytes]).to be >= 0
+        expect(payload[:redis_cache_write_bytes]).to be >= 0
+
+        # Gitaly
         expect(payload[:gitaly_calls]).to be_nil
         expect(payload[:gitaly_duration]).to be_nil
       end