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