Add Rugged calls and duration to API and Rails logs

This adds `rugged_duration_ms` and `rugged_calls` fields to
`api_json.log` and `production_json.log`. This will make it easier to
identify performance issues caused by excessive I/O.

Closes https://gitlab.com/gitlab-org/gitlab-ce/issues/64676

changelogs/unreleased/sh-add-rugged-logs.yml

+---
+title: Add Rugged calls and duration to API and Rails logs
+merge_request: 30871
+author:
+type: other

config/initializers/lograge.rb

@@ -34,6 +34,13 @@ unless Sidekiq.server?
         payload[:gitaly_duration] = Gitlab::GitalyClient.query_time_ms
       end
+      rugged_calls = Gitlab::RuggedInstrumentation.query_count
+
+      if rugged_calls > 0
+        payload[:rugged_calls] = rugged_calls
+        payload[:rugged_duration_ms] = Gitlab::RuggedInstrumentation.query_time_ms
+      end
+
       payload[:response] = event.payload[:response] if event.payload[:response]
       payload[Labkit::Correlation::CorrelationId::LOG_KEY] = Labkit::Correlation::CorrelationId.current_id

lib/gitlab/git/rugged_impl/use_rugged.rb

@@ -13,7 +13,18 @@ module Gitlab
         def wrap_rugged_call(&block)
           Gitlab::GitalyClient::StorageSettings.allow_disk_access do
-            yield
+            start = Gitlab::Metrics::System.monotonic_time
+
+            result = yield
+
+            duration = Gitlab::Metrics::System.monotonic_time - start
+
+            if Gitlab::RuggedInstrumentation.active?
+              Gitlab::RuggedInstrumentation.increment_query_count
+              Gitlab::RuggedInstrumentation.query_time += duration
+            end
+
+            result
           end
         end
       end

lib/gitlab/grape_logging/loggers/perf_logger.rb

@@ -6,11 +6,30 @@ module Gitlab
     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
+
+          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
+          }
+        end
       end
     end
   end

lib/gitlab/rugged_instrumentation.rb

+# frozen_string_literal: true
+
+module Gitlab
+  module RuggedInstrumentation
+    def self.query_time
+      SafeRequestStore[:rugged_query_time] ||= 0
+    end
+
+    def self.query_time=(duration)
+      SafeRequestStore[:rugged_query_time] = duration
+    end
+
+    def self.query_time_ms
+      (self.query_time * 1000).round(2)
+    end
+
+    def self.query_count
+      SafeRequestStore[:rugged_call_count] ||= 0
+    end
+
+    def self.increment_query_count
+      SafeRequestStore[:rugged_call_count] ||= 0
+      SafeRequestStore[:rugged_call_count] += 1
+    end
+
+    def self.active?
+      Gitlab::SafeRequestStore.active?
+    end
+  end
+end

scripts/lint-rugged

@@ -10,7 +10,12 @@ ALLOWED = [
   # Reverted Rugged calls due to Gitaly atop NFS performance
   # See https://docs.gitlab.com/ee/development/gitaly.html#legacy-rugged-code.
   'lib/gitlab/git/rugged_impl/',
-  'lib/gitlab/gitaly_client/storage_settings.rb'
+  'lib/gitlab/gitaly_client/storage_settings.rb',
+
+  # Needed for logging
+  'config/initializers/lograge.rb',
+  'lib/gitlab/grape_logging/loggers/perf_logger.rb',
+  'lib/gitlab/rugged_instrumentation.rb'
 ].freeze
 rugged_lines = IO.popen(%w[git grep -i -n rugged -- app config lib], &:read).lines

spec/lib/gitlab/rugged_instrumentation_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+describe Gitlab::RuggedInstrumentation, :request_store do
+  subject { described_class }
+
+  describe '.query_time' do
+    it 'increments query times' do
+      subject.query_time += 0.451
+      subject.query_time += 0.322
+
+      expect(subject.query_time).to be_within(0.001).of(0.773)
+      expect(subject.query_time_ms).to eq(773.0)
+    end
+  end
+
+  context '.increment_query_count' do
+    it 'tracks query counts' do
+      expect(subject.query_count).to eq(0)
+
+      2.times { subject.increment_query_count }
+
+      expect(subject.query_count).to eq(2)
+    end
+  end
+end