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

Add Rugged calls to performance bar

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

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

@@ -0,0 +1,5 @@
+---
+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?
 

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

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

@@ -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

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

@@ -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