Commit ef973f6f authored by Sean McGivern's avatar Sean McGivern

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.
parent 928c81e2
---
title: Add a Gitlab::Profiler.print_by_total_time convenience method for profiling
from a Rails console
merge_request:
author:
type: other
......@@ -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
......
......@@ -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
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
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment