Merge branch 'sh-add-rugged-to-peek' into 'master'

Add Rugged calls to performance bar

See merge request gitlab-org/gitlab-ce!30983

21 files changed, 185 insertions, 14 deletions

diff --git a/app/assets/javascripts/performance_bar/components/performance_bar_app.vue b/app/assets/javascripts/performance_bar/components/performance_bar_app.vue
index 015c1527500..f05db8376a4 100644
--- a/app/assets/javascripts/performance_bar/components/performance_bar_app.vue
+++ b/app/assets/javascripts/performance_bar/components/performance_bar_app.vue
@@ -42,6 +42,12 @@ export default {
       keys: ['feature', 'request'],
     },
     {
+      metric: 'rugged',
+      header: 'Rugged calls',
+      details: 'details',
+      keys: ['feature', 'args'],
+    },
+    {
       metric: 'redis',
       header: 'Redis calls',
       details: 'details',
diff --git a/changelogs/unreleased/sh-add-rugged-to-peek.yml b/changelogs/unreleased/sh-add-rugged-to-peek.yml
new file mode 100644
index 00000000000..8a030f3daf2
--- /dev/null
+++ b/changelogs/unreleased/sh-add-rugged-to-peek.yml
@@ -0,0 +1,5 @@
+---
+title: Add Rugged calls to performance bar
+merge_request: 30983
+author:
+type: other
diff --git a/config/initializers/peek.rb b/config/initializers/peek.rb
index 1ffd133239d..8416ae430c7 100644
--- a/config/initializers/peek.rb
+++ b/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?
 
diff --git a/doc/administration/monitoring/performance/img/performance_bar.png b/doc/administration/monitoring/performance/img/performance_bar.png
index 2bf686f9017..8a6f8b3b273 100644
--- a/doc/administration/monitoring/performance/img/performance_bar.png
+++ b/doc/administration/monitoring/performance/img/performance_bar.png
diff --git a/doc/administration/monitoring/performance/img/performance_bar_gitaly_calls.png b/doc/administration/monitoring/performance/img/performance_bar_gitaly_calls.png
index 7af6d401d1d..265178729c4 100644
--- a/doc/administration/monitoring/performance/img/performance_bar_gitaly_calls.png
+++ b/doc/administration/monitoring/performance/img/performance_bar_gitaly_calls.png
diff --git a/doc/administration/monitoring/performance/img/performance_bar_redis_calls.png b/doc/administration/monitoring/performance/img/performance_bar_redis_calls.png
new file mode 100644
index 00000000000..78dd7594adf
--- /dev/null
+++ b/doc/administration/monitoring/performance/img/performance_bar_redis_calls.png
diff --git a/doc/administration/monitoring/performance/img/performance_bar_rugged_calls.png b/doc/administration/monitoring/performance/img/performance_bar_rugged_calls.png
new file mode 100644
index 00000000000..f4068268137
--- /dev/null
+++ b/doc/administration/monitoring/performance/img/performance_bar_rugged_calls.png
diff --git a/doc/administration/monitoring/performance/img/performance_bar_sql_queries.png b/doc/administration/monitoring/performance/img/performance_bar_sql_queries.png
index b3219b4fa94..dab323eb066 100644
--- a/doc/administration/monitoring/performance/img/performance_bar_sql_queries.png
+++ b/doc/administration/monitoring/performance/img/performance_bar_sql_queries.png
diff --git a/doc/administration/monitoring/performance/performance_bar.md b/doc/administration/monitoring/performance/performance_bar.md
index 4ee156fdc11..15eab7dcab0 100644
--- a/doc/administration/monitoring/performance/performance_bar.md
+++ b/doc/administration/monitoring/performance/performance_bar.md
@@ -8,15 +8,16 @@ activated, it looks as follows:
 It allows you to see (from left to right):
 
 - the current host serving the page
-- the timing of the page (backend, frontend)
 - time taken and number of DB queries, click through for details of these queries
   ![SQL profiling using the Performance Bar](img/performance_bar_sql_queries.png)
 - time taken and number of [Gitaly] calls, click through for details of these calls
   ![Gitaly profiling using the Performance Bar](img/performance_bar_gitaly_calls.png)
+- time taken and number of [Rugged] calls, click through for details of these calls
+  ![Rugged profiling using the Performance Bar](img/performance_bar_rugged_calls.png)
 - profile of the code used to generate the page, line by line. In the profile view, the numbers in the left panel represent wall time, cpu time, and number of calls (based on [rblineprof](https://github.com/tmm1/rblineprof)).
   ![Line profiling using the Performance Bar](img/performance_bar_line_profiling.png)
-- time taken and number of calls to Redis
-- time taken and number of background jobs created by Sidekiq
+- time taken and number of Redis calls, click through for details of these calls
+  ![Redis profiling using the Performance Bar](img/performance_bar_redis_calls.png)
 - time taken and number of Ruby GC calls
 
 On the far right is a request selector that allows you to view the same metrics
@@ -43,3 +44,4 @@ You can toggle the Bar using the same shortcut.
 ![GitLab Performance Bar Admin Settings](img/performance_bar_configuration_settings.png)
 
 [Gitaly]: ../../gitaly/index.md
+[Rugged]: ../../high_availability/nfs.md#improving-nfs-performance-with-gitlab
diff --git a/lib/gitlab/git/repository.rb b/lib/gitlab/git/repository.rb
index 6e8aa5d578e..27032602828 100644
--- a/lib/gitlab/git/repository.rb
+++ b/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
diff --git a/lib/gitlab/git/rugged_impl/blob.rb b/lib/gitlab/git/rugged_impl/blob.rb
index 9aea736527b..5c73c0c66a9 100644
--- a/lib/gitlab/git/rugged_impl/blob.rb
+++ b/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
diff --git a/lib/gitlab/git/rugged_impl/commit.rb b/lib/gitlab/git/rugged_impl/commit.rb
index 29ae9bdd851..0eff35ab1c4 100644
--- a/lib/gitlab/git/rugged_impl/commit.rb
+++ b/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
diff --git a/lib/gitlab/git/rugged_impl/repository.rb b/lib/gitlab/git/rugged_impl/repository.rb
index 7bed553393c..8fde93e71e2 100644
--- a/lib/gitlab/git/rugged_impl/repository.rb
+++ b/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
diff --git a/lib/gitlab/git/rugged_impl/tree.rb b/lib/gitlab/git/rugged_impl/tree.rb
index 479c5f9d8b7..389c9d32ccb 100644
--- a/lib/gitlab/git/rugged_impl/tree.rb
+++ b/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
diff --git a/lib/gitlab/git/rugged_impl/use_rugged.rb b/lib/gitlab/git/rugged_impl/use_rugged.rb
index badf943e39c..80b75689334 100644
--- a/lib/gitlab/git/rugged_impl/use_rugged.rb
+++ b/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
diff --git a/lib/gitlab/rugged_instrumentation.rb b/lib/gitlab/rugged_instrumentation.rb
index 70c06e8b308..8bb8c547ae1 100644
--- a/lib/gitlab/rugged_instrumentation.rb
+++ b/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
diff --git a/lib/peek/views/rugged.rb b/lib/peek/views/rugged.rb
new file mode 100644
index 00000000000..7b0ab162b15
--- /dev/null
+++ b/lib/peek/views/rugged.rb
@@ -0,0 +1,58 @@
+# 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
+        return {} unless calls > 0
+
+        {
+          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
diff --git a/scripts/lint-rugged b/scripts/lint-rugged
index e1605b4501b..f40f0489c1a 100755
--- a/scripts/lint-rugged
+++ b/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
diff --git a/spec/lib/gitlab/git/repository_spec.rb b/spec/lib/gitlab/git/repository_spec.rb
index 41b898df112..dccd50bc472 100644
--- a/spec/lib/gitlab/git/repository_spec.rb
+++ b/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)
diff --git a/spec/lib/gitlab/git/rugged_impl/use_rugged_spec.rb b/spec/lib/gitlab/git/rugged_impl/use_rugged_spec.rb
index e437647c258..1a4168f7317 100644
--- a/spec/lib/gitlab/git/rugged_impl/use_rugged_spec.rb
+++ b/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)
diff --git a/spec/lib/peek/views/rugged_spec.rb b/spec/lib/peek/views/rugged_spec.rb
new file mode 100644
index 00000000000..715b360953c
--- /dev/null
+++ b/spec/lib/peek/views/rugged_spec.rb
@@ -0,0 +1,41 @@
+# 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 no results' do
+    expect(subject.results).to eq({})
+  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