Merge branch 'jv-redis-bytes-read-written' into 'master'

Log bytes read from / written to Redis

See merge request gitlab-org/gitlab!31352

doc/administration/logs.md

@@ -46,6 +46,8 @@ Line breaks have been added to this example for legibility:
   "gitaly_duration_s":0.16,
   "redis_calls":115,
   "redis_duration_s":0.13,
+  "redis_read_bytes":1507378,
+  "redis_write_bytes":2920,
   "correlation_id":"O1SdybnnIq7",
   "cpu_s":17.50,
   "db_duration_s":0.08,
@@ -56,7 +58,7 @@ Line breaks have been added to this example for legibility:
 
 This example was a GET request for a specific
 issue. Each line also contains performance data, with times in
-milliseconds:
+seconds:
 
 1. `duration_s`: total time taken to retrieve the request
 1. `queue_duration_s`: total time that the request was queued inside GitLab Workhorse
@@ -67,6 +69,8 @@ milliseconds:
 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_read_bytes`: total bytes read from Redis
+1. `redis_write_bytes`: total bytes written to Redis
 
 User clone and fetch activity using HTTP transport appears in this log as `action: git_upload_pack`.
 

lib/gitlab/instrumentation/redis.rb

@@ -23,6 +23,8 @@ module Gitlab
       REDIS_REQUEST_COUNT = :redis_request_count
       REDIS_CALL_DURATION = :redis_call_duration
       REDIS_CALL_DETAILS = :redis_call_details
+      REDIS_READ_BYTES = :redis_read_bytes
+      REDIS_WRITE_BYTES = :redis_write_bytes
 
       # Milliseconds represented in seconds (from 1 to 500 milliseconds).
       QUERY_TIME_BUCKETS = [0.001, 0.0025, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5].freeze
@@ -36,6 +38,24 @@ module Gitlab
         ::RequestStore[REDIS_REQUEST_COUNT] += 1
       end
 
+      def self.increment_read_bytes(num_bytes)
+        ::RequestStore[REDIS_READ_BYTES] ||= 0
+        ::RequestStore[REDIS_READ_BYTES] += num_bytes
+      end
+
+      def self.increment_write_bytes(num_bytes)
+        ::RequestStore[REDIS_WRITE_BYTES] ||= 0
+        ::RequestStore[REDIS_WRITE_BYTES] += num_bytes
+      end
+
+      def self.read_bytes
+        ::RequestStore[REDIS_READ_BYTES] || 0
+      end
+
+      def self.write_bytes
+        ::RequestStore[REDIS_WRITE_BYTES] || 0
+      end
+
       def self.detail_store
         ::RequestStore[REDIS_CALL_DETAILS] ||= []
       end

lib/gitlab/instrumentation/redis_driver.rb

+# frozen_string_literal: true
+
+require 'redis'
+
+module Gitlab
+  module Instrumentation
+    class RedisDriver < ::Redis::Connection::Ruby
+      def write(command)
+        measure_write_size(command) if ::RequestStore.active?
+        super
+      end
+
+      def read
+        result = super
+        measure_read_size(result) if ::RequestStore.active?
+        result
+      end
+
+      private
+
+      def measure_write_size(command)
+        size = 0
+
+        # Mimic what happens in
+        # https://github.com/redis/redis-rb/blob/f597f21a6b954b685cf939febbc638f6c803e3a7/lib/redis/connection/command_helper.rb#L8.
+        # This count is an approximation that omits the Redis protocol overhead
+        # of type prefixes, length prefixes and line endings.
+        command.each do |x|
+          size += begin
+            if x.is_a? Array
+              x.inject(0) { |sum, y| sum + y.to_s.bytesize }
+            else
+              x.to_s.bytesize
+            end
+          end
+        end
+
+        ::Gitlab::Instrumentation::Redis.increment_write_bytes(size)
+      end
+
+      def measure_read_size(result)
+        # The superclass can return one of four types of results from read:
+        # https://github.com/redis/redis-rb/blob/f597f21a6b954b685cf939febbc638f6c803e3a7/lib/redis/connection/ruby.rb#L406
+        #
+        # 1. Error (exception, will not reach this line)
+        # 2. Status (string)
+        # 3. Integer (will be converted to string by to_s.bytesize and thrown away)
+        # 4. "Binary" string (i.e. may contain zero byte)
+        # 5. Array of binary string (recurses back into read)
+
+        # Avoid double-counting array responses: the array elements themselves
+        # are retrieved with 'read'.
+        unless result.is_a? Array
+          # This count is an approximation that omits the Redis protocol overhead
+          # of type prefixes, length prefixes and line endings.
+          ::Gitlab::Instrumentation::Redis.increment_read_bytes(result.to_s.bytesize)
+        end
+      end
+    end
+  end
+end

lib/gitlab/instrumentation_helper.rb

@@ -4,7 +4,7 @@ module Gitlab
   module InstrumentationHelper
     extend self
 
-    KEYS = %i(gitaly_calls gitaly_duration_s rugged_calls rugged_duration_s redis_calls redis_duration_s).freeze
+    KEYS = %i(gitaly_calls gitaly_duration_s rugged_calls rugged_duration_s redis_calls redis_duration_s redis_read_bytes redis_write_bytes).freeze
     DURATION_PRECISION = 6 # microseconds
 
     def add_instrumentation_data(payload)
@@ -28,6 +28,13 @@ module Gitlab
         payload[:redis_calls] = redis_calls
         payload[:redis_duration_s] = Gitlab::Instrumentation::Redis.query_time
       end
+
+      redis_read_bytes = Gitlab::Instrumentation::Redis.read_bytes
+      redis_write_bytes = Gitlab::Instrumentation::Redis.write_bytes
+      if redis_read_bytes > 0 || redis_write_bytes > 0
+        payload[:redis_read_bytes] = redis_read_bytes
+        payload[:redis_write_bytes] = redis_write_bytes
+      end
     end
 
     # Returns the queuing duration for a Sidekiq job in seconds, as a float, if the

lib/gitlab/redis/wrapper.rb

@@ -100,6 +100,8 @@ module Gitlab
         redis_url = config.delete(:url)
         redis_uri = URI.parse(redis_url)
 
+        config[:driver] ||= ::Gitlab::Instrumentation::RedisDriver
+
         if redis_uri.scheme == 'unix'
           # Redis::Store does not handle Unix sockets well, so let's do it for them
           config[:path] = redis_uri.path

spec/lib/gitlab/instrumentation/redis_driver_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+require 'rspec-parameterized'
+
+describe Gitlab::Instrumentation::RedisDriver, :clean_gitlab_redis_shared_state, :request_store do
+  using RSpec::Parameterized::TableSyntax
+
+  describe 'read and write' do
+    where(:setup, :command, :expect_write, :expect_read) do
+      # The response is 'OK', the request size is the combined size of array
+      # elements. Exercise counting of a status reply.
+      [] | [:set, 'foo', 'bar'] | 3 + 3 + 3 | 2
+
+      # The response is 1001, so 4 bytes. Exercise counting an integer reply.
+      [[:set, 'foobar', 1000]] | [:incr, 'foobar'] | 4 + 6 | 4
+
+      # Exercise counting empty multi bulk reply
+      [] | [:hgetall, 'foobar'] | 7 + 6 | 0
+
+      # Hgetall response length is combined length of keys and values in the
+      # hash. Exercises counting of a multi bulk reply
+      [[:hset, 'myhash', 'field', 'hello world']] | [:hgetall, 'myhash'] | 7 + 6 | 5 + 11
+
+      # Exercise counting of a bulk reply
+      [[:set, 'foo', 'bar' * 100]] | [:get, 'foo'] | 3 + 3 | 3 * 100
+    end
+
+    with_them do
+      it 'counts bytes read and written' do
+        Gitlab::Redis::SharedState.with do |redis|
+          setup.each { |cmd| redis.call(cmd) }
+          RequestStore.clear!
+          redis.call(command)
+        end
+
+        expect(Gitlab::Instrumentation::Redis.read_bytes).to eq(expect_read)
+        expect(Gitlab::Instrumentation::Redis.write_bytes).to eq(expect_write)
+      end
+    end
+  end
+end

spec/lib/gitlab/instrumentation_helper_spec.rb

@@ -34,12 +34,14 @@ 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.get('test-instrumentation') }
+        Gitlab::Redis::Cache.with { |redis| redis.set('test-instrumentation', 123) }
 
         subject
 
         expect(payload[:redis_calls]).to eq(1)
         expect(payload[:redis_duration_s]).to be >= 0
+        expect(payload[:redis_read_bytes]).to be >= 0
+        expect(payload[:redis_write_bytes]).to be >= 0
         expect(payload[:gitaly_calls]).to be_nil
         expect(payload[:gitaly_duration]).to be_nil
       end