Merge branch 'add-total-time-flat-printer-for-profiling' into 'master'

Add a Gitlab::Profiler.print_by_total_time convenience method

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

changelogs/unreleased/add-total-time-flat-printer-for-profiling.yml

+---
+title: Add a Gitlab::Profiler.print_by_total_time convenience method for profiling
+  from a Rails console
+merge_request:
+author:
+type: other

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

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

lib/gitlab/profiler/total_time_flat_printer.rb

+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