Add Rugged calls to performance bar

This will help diagnose the source of excessive I/O from Rugged
calls. To implement this, we need to obtain the full list of arguments
sent to each request method.

app/assets/javascripts/performance_bar/components/performance_bar_app.vue

@@ -41,6 +41,12 @@ export default {
       details: 'details',
       keys: ['feature', 'request'],
     },
+    {
+      metric: 'rugged',
+      header: 'Rugged calls',
+      details: 'details',
+      keys: ['feature', 'args'],
+    },
     {
       metric: 'redis',
       header: 'Redis calls',

changelogs/unreleased/sh-add-rugged-to-peek.yml

+---
+title: Add Rugged calls to performance bar
+merge_request: 30983
+author:
+type: other

config/initializers/peek.rb

@@ -26,6 +26,7 @@ Peek.into PEEK_DB_VIEW
 Peek.into Peek::Views::Gitaly
 Peek.into Peek::Views::Rblineprof
 Peek.into Peek::Views::RedisDetailed
+Peek.into Peek::Views::Rugged
 Peek.into Peek::Views::GC
 Peek.into Peek::Views::Tracing if Labkit::Tracing.tracing_url_enabled?
 

lib/gitlab/git/repository.rb

@@ -55,6 +55,10 @@ module Gitlab
         @name = @relative_path.split("/").last
       end
 
+      def to_s
+        "<#{self.class.name}: #{self.gl_project_path}>"
+      end
+
       def ==(other)
         other.is_a?(self.class) && [storage, relative_path] == [other.storage, other.relative_path]
       end

lib/gitlab/git/rugged_impl/blob.rb

@@ -16,7 +16,7 @@ module Gitlab
           override :tree_entry
           def tree_entry(repository, sha, path, limit)
             if use_rugged?(repository, :rugged_tree_entry)
-              wrap_rugged_call { rugged_tree_entry(repository, sha, path, limit) }
+              execute_rugged_call(:rugged_tree_entry, repository, sha, path, limit)
             else
               super
             end

lib/gitlab/git/rugged_impl/commit.rb

@@ -36,7 +36,7 @@ module Gitlab
           override :find_commit
           def find_commit(repo, commit_id)
             if use_rugged?(repo, :rugged_find_commit)
-              wrap_rugged_call { rugged_find(repo, commit_id) }
+              execute_rugged_call(:rugged_find, repo, commit_id)
             else
               super
             end
@@ -45,7 +45,7 @@ module Gitlab
           override :batch_by_oid
           def batch_by_oid(repo, oids)
             if use_rugged?(repo, :rugged_list_commits_by_oid)
-              wrap_rugged_call { rugged_batch_by_oid(repo, oids) }
+              execute_rugged_call(:rugged_batch_by_oid, repo, oids)
             else
               super
             end
@@ -68,7 +68,7 @@ module Gitlab
         override :commit_tree_entry
         def commit_tree_entry(path)
           if use_rugged?(@repository, :rugged_commit_tree_entry)
-            wrap_rugged_call { rugged_tree_entry(path) }
+            execute_rugged_call(:rugged_tree_entry, path)
           else
             super
           end

lib/gitlab/git/rugged_impl/repository.rb

@@ -48,7 +48,7 @@ module Gitlab
         override :ancestor?
         def ancestor?(from, to)
           if use_rugged?(self, :rugged_commit_is_ancestor)
-            wrap_rugged_call { rugged_is_ancestor?(from, to) }
+            execute_rugged_call(:rugged_is_ancestor?, from, to)
           else
             super
           end

lib/gitlab/git/rugged_impl/tree.rb

@@ -16,7 +16,7 @@ module Gitlab
           override :tree_entries
           def tree_entries(repository, sha, path, recursive)
             if use_rugged?(repository, :rugged_tree_entries)
-              wrap_rugged_call { tree_entries_with_flat_path_from_rugged(repository, sha, path, recursive) }
+              execute_rugged_call(:tree_entries_with_flat_path_from_rugged, repository, sha, path, recursive)
             else
               super
             end

lib/gitlab/git/rugged_impl/use_rugged.rb

@@ -11,17 +11,23 @@ module Gitlab
           Gitlab::GitalyClient.can_use_disk?(repo.storage)
         end
 
-        def wrap_rugged_call(&block)
+        def execute_rugged_call(method_name, *args)
           Gitlab::GitalyClient::StorageSettings.allow_disk_access do
             start = Gitlab::Metrics::System.monotonic_time
 
-            result = yield
+            result = send(method_name, *args) # rubocop:disable GitlabSecurity/PublicSend
 
             duration = Gitlab::Metrics::System.monotonic_time - start
 
             if Gitlab::RuggedInstrumentation.active?
               Gitlab::RuggedInstrumentation.increment_query_count
               Gitlab::RuggedInstrumentation.query_time += duration
+
+              Gitlab::RuggedInstrumentation.add_call_details(
+                feature: method_name,
+                args: args,
+                duration: duration,
+                backtrace: Gitlab::Profiler.clean_backtrace(caller))
             end
 
             result

lib/gitlab/rugged_instrumentation.rb

@@ -24,7 +24,24 @@ module Gitlab
     end
 
     def self.active?
-      Gitlab::SafeRequestStore.active?
+      SafeRequestStore.active?
+    end
+
+    def self.peek_enabled?
+      SafeRequestStore[:peek_enabled]
+    end
+
+    def self.add_call_details(details)
+      return unless peek_enabled?
+
+      Gitlab::SafeRequestStore[:rugged_call_details] ||= []
+      Gitlab::SafeRequestStore[:rugged_call_details] << details
+    end
+
+    def self.list_call_details
+      return [] unless peek_enabled?
+
+      Gitlab::SafeRequestStore[:rugged_call_details] || []
     end
   end
 end

lib/peek/views/rugged.rb

+# frozen_string_literal: true
+
+module Peek
+  module Views
+    class Rugged < View
+      def duration
+        ::Gitlab::RuggedInstrumentation.query_time
+      end
+
+      def calls
+        ::Gitlab::RuggedInstrumentation.query_count
+      end
+
+      def results
+        {
+          duration: formatted_duration,
+          calls: calls,
+          details: details
+        }
+      end
+
+      private
+
+      def details
+        ::Gitlab::RuggedInstrumentation.list_call_details
+          .sort { |a, b| b[:duration] <=> a[:duration] }
+          .map(&method(:format_call_details))
+      end
+
+      def format_call_details(call)
+        call.merge(duration: (call[:duration] * 1000).round(3),
+                   args: format_args(call[:args]))
+      end
+
+      def format_args(args)
+        args.map do |arg|
+          # Needed to avoid infinite as_json calls
+          if arg.is_a?(Gitlab::Git::Repository)
+            arg.to_s
+          else
+            arg
+          end
+        end
+      end
+
+      def formatted_duration
+        ms = duration * 1000
+        if ms >= 1000
+          "%.2fms" % ms
+        else
+          "%.0fms" % ms
+        end
+      end
+    end
+  end
+end

scripts/lint-rugged

@@ -13,9 +13,11 @@ ALLOWED = [
   'lib/gitlab/gitaly_client/storage_settings.rb',
 
   # Needed for logging
+  'config/initializers/peek.rb',
   'config/initializers/lograge.rb',
   'lib/gitlab/grape_logging/loggers/perf_logger.rb',
-  'lib/gitlab/rugged_instrumentation.rb'
+  'lib/gitlab/rugged_instrumentation.rb',
+  'lib/peek/views/rugged.rb'
 ].freeze
 
 rugged_lines = IO.popen(%w[git grep -i -n rugged -- app config lib], &:read).lines

spec/lib/gitlab/git/repository_spec.rb

@@ -186,6 +186,12 @@ describe Gitlab::Git::Repository, :seed_helper do
     it { is_expected.to be < 2 }
   end
 
+  describe '#to_s' do
+    subject { repository.to_s }
+
+    it { is_expected.to eq("<Gitlab::Git::Repository: group/project>") }
+  end
+
   describe '#object_directory_size' do
     before do
       allow(repository.gitaly_repository_client)

spec/lib/gitlab/git/rugged_impl/use_rugged_spec.rb

@@ -16,7 +16,13 @@ describe Gitlab::Git::RuggedImpl::UseRugged, :seed_helper do
   end
 
   subject(:wrapper) do
-    klazz = Class.new { include Gitlab::Git::RuggedImpl::UseRugged }
+    klazz = Class.new do
+      include Gitlab::Git::RuggedImpl::UseRugged
+
+      def rugged_test(ref, test_number)
+      end
+    end
+
     klazz.new
   end
 
@@ -25,6 +31,23 @@ describe Gitlab::Git::RuggedImpl::UseRugged, :seed_helper do
     Gitlab::GitalyClient.instance_variable_set(:@can_use_disk, {})
   end
 
+  context '#execute_rugged_call', :request_store do
+    let(:args) { ['refs/heads/master', 1] }
+
+    before do
+      allow(Gitlab::RuggedInstrumentation).to receive(:peek_enabled?).and_return(true)
+    end
+
+    it 'instruments Rugged call' do
+      expect(subject).to receive(:rugged_test).with(args)
+
+      subject.execute_rugged_call(:rugged_test, args)
+
+      expect(Gitlab::RuggedInstrumentation.query_count).to eq(1)
+      expect(Gitlab::RuggedInstrumentation.list_call_details.count).to eq(1)
+    end
+  end
+
   context 'when feature flag is not persisted' do
     before do
       allow(Feature).to receive(:persisted?).with(feature_flag).and_return(false)

spec/lib/peek/views/rugged_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+describe Peek::Views::Rugged, :request_store do
+  subject { described_class.new }
+
+  let(:project) { create(:project) }
+
+  before do
+    allow(Gitlab::RuggedInstrumentation).to receive(:peek_enabled?).and_return(true)
+  end
+
+  it 'returns aggregated results' do
+    ::Gitlab::RuggedInstrumentation.query_time += 1.234
+    ::Gitlab::RuggedInstrumentation.increment_query_count
+    ::Gitlab::RuggedInstrumentation.increment_query_count
+
+    ::Gitlab::RuggedInstrumentation.add_call_details(feature: :rugged_test,
+                                                     args: [project.repository.raw, 'HEAD'],
+                                                     duration: 0.123)
+    ::Gitlab::RuggedInstrumentation.add_call_details(feature: :rugged_test2,
+                                                     args: [project.repository.raw, 'refs/heads/master'],
+                                                     duration: 0.456)
+
+    expect(subject.duration).to be_within(0.00001).of(1.234)
+    expect(subject.calls).to eq(2)
+
+    results = subject.results
+    expect(results[:calls]).to eq(2)
+    expect(results[:duration]).to eq('1234.00ms')
+    expect(results[:details].count).to eq(2)
+
+    expect(results[:details][0][:args]).to eq([project.repository.raw.to_s, "refs/heads/master"])
+    expect(results[:details][1][:args]).to eq([project.repository.raw.to_s, "HEAD"])
+  end
+end