Merge branch 'add-query-counts-to-profiler-output' into 'master'

Add query counts by model to profiler output

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

3 files changed, 35 insertions, 6 deletions

diff --git a/changelogs/unreleased/add-query-counts-to-profiler-output.yml b/changelogs/unreleased/add-query-counts-to-profiler-output.yml
new file mode 100644
index 00000000000..8a90b1cbeb0
--- /dev/null
+++ b/changelogs/unreleased/add-query-counts-to-profiler-output.yml
@@ -0,0 +1,5 @@
+---
+title: Add query counts to profiler output
+merge_request:
+author:
+type: other
diff --git a/lib/gitlab/profiler.rb b/lib/gitlab/profiler.rb
index 98a168b43bb..18540e64d4c 100644
--- a/lib/gitlab/profiler.rb
+++ b/lib/gitlab/profiler.rb
@@ -92,8 +92,8 @@ module Gitlab
 
             if type && time
               @load_times_by_model ||= {}
-              @load_times_by_model[type] ||= 0
-              @load_times_by_model[type] += time.to_f
+              @load_times_by_model[type] ||= []
+              @load_times_by_model[type] << time.to_f
             end
 
             super
@@ -135,8 +135,12 @@ module Gitlab
     def self.log_load_times_by_model(logger)
       return unless logger.respond_to?(:load_times_by_model)
 
-      logger.load_times_by_model.to_a.sort_by(&:last).reverse.each do |(model, time)|
-        logger.info("#{model} total: #{time.round(2)}ms")
+      summarised_load_times = logger.load_times_by_model.to_a.map do |(model, times)|
+        [model, times.count, times.sum]
+      end
+
+      summarised_load_times.sort_by(&:last).reverse.each do |(model, query_count, time)|
+        logger.info("#{model} total (#{query_count}): #{time.round(2)}ms")
       end
     end
   end
diff --git a/spec/lib/gitlab/profiler_spec.rb b/spec/lib/gitlab/profiler_spec.rb
index 3d5b56cd5b8..548eb28fe4d 100644
--- a/spec/lib/gitlab/profiler_spec.rb
+++ b/spec/lib/gitlab/profiler_spec.rb
@@ -110,8 +110,8 @@ describe Gitlab::Profiler do
         custom_logger.debug('User Load (1.3ms)')
         custom_logger.debug('Project Load (10.4ms)')
 
-        expect(custom_logger.load_times_by_model).to eq('User' => 2.5,
-                                                        'Project' => 10.4)
+        expect(custom_logger.load_times_by_model).to eq('User' => [1.2, 1.3],
+                                                        'Project' => [10.4])
       end
 
       it 'logs the backtrace, ignoring lines as appropriate' do
@@ -164,4 +164,24 @@ describe Gitlab::Profiler do
       end
     end
   end
+
+  describe '.log_load_times_by_model' do
+    it 'logs the model, query count, and time by slowest first' do
+      expect(null_logger).to receive(:load_times_by_model).and_return(
+        'User' => [1.2, 1.3],
+        'Project' => [10.4]
+      )
+
+      expect(null_logger).to receive(:info).with('Project total (1): 10.4ms')
+      expect(null_logger).to receive(:info).with('User total (2): 2.5ms')
+
+      described_class.log_load_times_by_model(null_logger)
+    end
+
+    it 'does nothing when called with a logger that does not have load times' do
+      expect(null_logger).not_to receive(:info)
+
+      expect(described_class.log_load_times_by_model(null_logger)).to be_nil
+    end
+  end
 end