From e236180618c785ccf210fcf4847242ca814731d3 Mon Sep 17 00:00:00 2001
From: Sean McGivern <sean@gitlab.com>
Date: Wed, 21 Mar 2018 16:22:56 +0000
Subject: [PATCH] Add query counts by model to profiler output

---
 .../add-query-counts-to-profiler-output.yml   |  5 ++++
 lib/gitlab/profiler.rb                        | 12 ++++++----
 spec/lib/gitlab/profiler_spec.rb              | 24 +++++++++++++++++--
 3 files changed, 35 insertions(+), 6 deletions(-)
 create mode 100644 changelogs/unreleased/add-query-counts-to-profiler-output.yml

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