Merge branch 'osw-separate-redis-logs' into 'master'

Add detailed logs of each Redis instance usage during job execution and web requests

See merge request gitlab-org/gitlab!34110

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