Add Rugged calls and duration to API and Rails logssh-add-rugged-logs

This adds `rugged_duration` 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

7 files changed, 106 insertions, 2 deletions

diff --git a/changelogs/unreleased/sh-add-rugged-logs.yml b/changelogs/unreleased/sh-add-rugged-logs.yml
new file mode 100644
index 00000000000..1f464dd92ff
--- /dev/null
+++ b/changelogs/unreleased/sh-add-rugged-logs.yml
@@ -0,0 +1,5 @@
+---
+title: Add Rugged calls and duration to API and Rails logs
+merge_request: 30871
+author:
+type: other
diff --git a/config/initializers/lograge.rb b/config/initializers/lograge.rb
index fbec28186eb..8d448b7d4ce 100644
--- a/config/initializers/lograge.rb
+++ b/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] = 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
 
diff --git a/lib/gitlab/git/rugged_impl/use_rugged.rb b/lib/gitlab/git/rugged_impl/use_rugged.rb
index 902fa3c7822..badf943e39c 100644
--- a/lib/gitlab/git/rugged_impl/use_rugged.rb
+++ b/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
diff --git a/lib/gitlab/grape_logging/loggers/perf_logger.rb b/lib/gitlab/grape_logging/loggers/perf_logger.rb
index 18ea3a8d2f3..1fcc70cf491 100644
--- a/lib/gitlab/grape_logging/loggers/perf_logger.rb
+++ b/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: Gitlab::RuggedInstrumentation.query_time_ms
+          }
+        end
       end
     end
   end
diff --git a/lib/gitlab/rugged_instrumentation.rb b/lib/gitlab/rugged_instrumentation.rb
new file mode 100644
index 00000000000..70c06e8b308
--- /dev/null
+++ b/lib/gitlab/rugged_instrumentation.rb
@@ -0,0 +1,30 @@
+# 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
diff --git a/scripts/lint-rugged b/scripts/lint-rugged
index 9466c62a415..f7fd08946fb 100755
--- a/scripts/lint-rugged
+++ b/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_client.rb'
 ].freeze
 
 rugged_lines = IO.popen(%w[git grep -i -n rugged -- app config lib], &:read).lines
diff --git a/spec/lib/gitlab/rugged_instrumentation_spec.rb b/spec/lib/gitlab/rugged_instrumentation_spec.rb
new file mode 100644
index 00000000000..4dcc8ae514a
--- /dev/null
+++ b/spec/lib/gitlab/rugged_instrumentation_spec.rb
@@ -0,0 +1,27 @@
+# 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