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

3 files changed, 61 insertions, 1 deletions

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..7e86b35a215 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_ms: 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