From ef973f6f28f5b98ba126985b01d1c463e1cd8761 Mon Sep 17 00:00:00 2001
From: Sean McGivern <sean@gitlab.com>
Date: Thu, 19 Jul 2018 13:38:57 +0100
Subject: [PATCH] Add a Gitlab::Profiler.print_by_total_time convenience method

This method uses Gitlab::Profiler::TotalTimeFlatPrinter internally, which is the
same as RubyProf::FlatPrinter, but the min_percent option (and new max_percent
option) applies to the _total_ time, not the _self_ time. This helps us figure
out if we're calling a library inefficiently, for instance.
---
 ...-total-time-flat-printer-for-profiling.yml |  6 +++
 doc/development/profiling.md                  | 30 ++++++++++++++
 lib/gitlab/profiler.rb                        |  6 +++
 .../profiler/total_time_flat_printer.rb       | 39 +++++++++++++++++++
 4 files changed, 81 insertions(+)
 create mode 100644 changelogs/unreleased/add-total-time-flat-printer-for-profiling.yml
 create mode 100644 lib/gitlab/profiler/total_time_flat_printer.rb

diff --git a/changelogs/unreleased/add-total-time-flat-printer-for-profiling.yml b/changelogs/unreleased/add-total-time-flat-printer-for-profiling.yml
new file mode 100644
index 00000000000..37a4e31896e
--- /dev/null
+++ b/changelogs/unreleased/add-total-time-flat-printer-for-profiling.yml
@@ -0,0 +1,6 @@
+---
+title: Add a Gitlab::Profiler.print_by_total_time convenience method for profiling
+  from a Rails console
+merge_request:
+author:
+type: other
diff --git a/doc/development/profiling.md b/doc/development/profiling.md
index 11878b4009b..0ca8bb67a77 100644
--- a/doc/development/profiling.md
+++ b/doc/development/profiling.md
@@ -42,6 +42,36 @@ Passing a `logger:` keyword argument to `Gitlab::Profiler.profile` will send
 ActiveRecord and ActionController log output to that logger. Further options are
 documented with the method source.
 
+There is also a RubyProf printer available:
+`Gitlab::Profiler::TotalTimeFlatPrinter`. This acts like
+`RubyProf::FlatPrinter`, but its `min_percent` option works on the method's
+total time, not its self time. (This is because we often spend most of our time
+in library code, but this comes from calls in our application.) It also offers a
+`max_percent` option to help filter out outer calls that aren't useful (like
+`ActionDispatch::Integration::Session#process`).
+
+There is a convenience method for using this,
+`Gitlab::Profiler.print_by_total_time`:
+
+```ruby
+result = Gitlab::Profiler.profile('/my-user')
+Gitlab::Profiler.print_by_total_time(result, max_percent: 60, min_percent: 2)
+# Measure Mode: wall_time
+# Thread ID: 70005223698240
+# Fiber ID: 70004894952580
+# Total: 1.768912
+# Sort by: total_time
+#
+#  %self      total      self      wait     child     calls  name
+#   0.00      1.017     0.000     0.000     1.017       14  *ActionView::Helpers::RenderingHelper#render
+#   0.00      1.017     0.000     0.000     1.017       14  *ActionView::Renderer#render_partial
+#   0.00      1.017     0.000     0.000     1.017       14  *ActionView::PartialRenderer#render
+#   0.00      1.007     0.000     0.000     1.007       14  *ActionView::PartialRenderer#render_partial
+#   0.00      0.930     0.000     0.000     0.930       14   Hamlit::TemplateHandler#call
+#   0.00      0.928     0.000     0.000     0.928       14   Temple::Engine#call
+#   0.02      0.865     0.000     0.000     0.864      638  *Enumerable#inject
+```
+
 [GitLab-Profiler](https://gitlab.com/gitlab-com/gitlab-profiler) is a project
 that builds on this to add some additional niceties, such as allowing
 configuration with a single Yaml file for multiple URLs, and uploading of the
diff --git a/lib/gitlab/profiler.rb b/lib/gitlab/profiler.rb
index ecff6ab5d5e..c5bb4648572 100644
--- a/lib/gitlab/profiler.rb
+++ b/lib/gitlab/profiler.rb
@@ -146,5 +146,11 @@ module Gitlab
         logger.info("#{model} total (#{query_count}): #{time.round(2)}ms")
       end
     end
+
+    def self.print_by_total_time(result, options = {})
+      default_options = { sort_method: :total_time }
+
+      Gitlab::Profiler::TotalTimeFlatPrinter.new(result).print(STDOUT, default_options.merge(options))
+    end
   end
 end
diff --git a/lib/gitlab/profiler/total_time_flat_printer.rb b/lib/gitlab/profiler/total_time_flat_printer.rb
new file mode 100644
index 00000000000..2fd0ec10ba8
--- /dev/null
+++ b/lib/gitlab/profiler/total_time_flat_printer.rb
@@ -0,0 +1,39 @@
+module Gitlab
+  module Profiler
+    class TotalTimeFlatPrinter < RubyProf::FlatPrinter
+      def max_percent
+        @options[:max_percent] || 100
+      end
+
+      # Copied from:
+      #   <https://github.com/ruby-prof/ruby-prof/blob/master/lib/ruby-prof/printers/flat_printer.rb>
+      #
+      # The changes are just to filter by total time, not self time, and add a
+      # max_percent option as well.
+      def print_methods(thread)
+        total_time = thread.total_time
+        methods = thread.methods.sort_by(&sort_method).reverse
+
+        sum = 0
+        methods.each do |method|
+          total_percent = (method.total_time / total_time) * 100
+          next if total_percent < min_percent
+          next if total_percent > max_percent
+
+          sum += method.self_time
+
+          @output << "%6.2f  %9.3f %9.3f %9.3f %9.3f %8d  %s%s\n" % [
+            method.self_time / total_time * 100, # %self
+            method.total_time,                   # total
+            method.self_time,                    # self
+            method.wait_time,                    # wait
+            method.children_time,                # children
+            method.called,                       # calls
+            method.recursive? ? "*" : " ",       # cycle
+            method_name(method)                  # name
+          ]
+        end
+      end
+    end
+  end
+end