diff options
| -rw-r--r-- | changelogs/unreleased/add-total-time-flat-printer-for-profiling.yml | 6 | ||||
| -rw-r--r-- | doc/development/profiling.md | 30 | ||||
| -rw-r--r-- | lib/gitlab/profiler.rb | 6 | ||||
| -rw-r--r-- | lib/gitlab/profiler/total_time_flat_printer.rb | 39 |
4 files changed, 81 insertions, 0 deletions
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 |