class Tuttle::Middleware::RequestProfiler

Constants

TRACE_METHODS

These methods may cause the method cache to be invalidated

Public Class Methods

new(app) click to toggle source
# File lib/tuttle/middleware/request_profiler.rb, line 7
def initialize(app)
  @app = app
end

Public Instance Methods

call(env) click to toggle source
# File lib/tuttle/middleware/request_profiler.rb, line 11
def call(env)
  query_string = env['QUERY_STRING']

  tuttle_profiler_action = /(^|[&?])tuttle-profiler=([\w\-]*)/.match(query_string) { |m| m[2] }

  case tuttle_profiler_action
  when 'memory_profiler', 'memory'
    profile_memory(env, query_string)
  when 'ruby-prof', 'cpu'
    profile_cpu(env, query_string)
  when 'busted'
    profile_busted(env, query_string)
  else
    @app.call(env)
  end
end

Private Instance Methods

profile_busted(env, _query_string) click to toggle source
# File lib/tuttle/middleware/request_profiler.rb, line 104
def profile_busted(env, _query_string)
  # Note: Requires Busted (of course) and DTrace so will need much better error handling and information
  # For DTrace on OS X (post 10.11) you may need to disable SIP as well as be running with root privileges
  # https://derflounder.wordpress.com/2015/10/01/system-integrity-protection-adding-another-layer-to-apples-security-model/

  require 'busted'
  require 'busted/profiler/default' # Required so `autoload :Default` does not get included in trace

  # Notes:
  # Much of this is per https://tenderlovemaking.com/2015/12/23/inline-caching-in-mri.html
  #   and https://github.com/charliesome/charlie.bz/blob/master/posts/things-that-clear-rubys-method-cache.md
  # RubyVM.stat tracks the :global_method_state, :global_constant_state, and :class_serial
  #   :global_method_state - "global serial number that increments every time certain classes get mutated"
  #      ** Changes to this are BAD because they invalidate all caches
  #   :global_constant_state - counter of constants defined *or redefined(?)*
  #   :class_serial - global serial number that increments every time a method is Class is created/modified (?-verify)
  # Since Ruby 2.1(2.2?) the method caches are per-Class rather than global.
  #   So clearing the method cache of a single Class is less of a performance hit than blowing away the entire method cache
  #
  # Busted Dtraces :method-cache-clear internal events which are when Ruby says the method cache was cleared
  # The @cache_buster_tracepoint Dtraces Class/Module definitions (:class)
  # and calls to C method (:c_call) which would likely cause a method cache clear
  #
  # From the observed results...
  #   :method-cache-clear may fire more times than RubyVM.stat[]
  cache_busters = []

  # This is really still incomplete...
  # Internally, Ruby does not fire :c_call or :class for many events that would increment the :class_serial
  # For example `Person = Class.new` does not fire a :class event
  # And it also does create a new constant (:constant_state) but does not fire a :const_set event

  # Trace class definitions (which always(?) invalidate the cache) and c-calls which may invalidate the cache
  @cache_buster_tracepoint ||= TracePoint.new(:class, :c_call) do |trace|
    if trace.event == :class
      cache_busters << {
        :event => trace.event,
        :event_description => "Class definition",
        :location => "#{trace.path}##{trace.lineno}",
        :target_class => trace.self
      }
    elsif TRACE_METHODS.include?(trace.method_id)
      cache_busters << {
        :event => trace.event,
        :event_description => "#{trace.defined_class}##{trace.method_id}",
        :location => "#{trace.path}##{trace.lineno}",
        :target_class => trace.self.class,
        :defined_class => trace.defined_class,
        :method_id => trace.method_id
      }
    end
  end

  # Trace the request and capture the RubyVM.stat before/after
  vmstat_before = RubyVM.stat
  results = @cache_buster_tracepoint.enable do
    Busted.run(trace: true) do
      _, _, body = @app.call(env)
      body.close if body.respond_to?(:close)
    end
  end
  vmstat_after = RubyVM.stat

  # Prepare the output
  output = "\nRubyVM.stat:           Before     After      Change\n".dup
  %i[global_method_state global_constant_state class_serial].each do |stat|
    output << format("%-22s %-10d %-10d %+d\n",
                     stat,
                     vmstat_before[stat],
                     vmstat_after[stat],
                     vmstat_after[stat] - vmstat_before[stat])
  end

  output << "\nCounts:\n"
  output << "method-cache-clear: #{results[:traces][:method].size}\n"
  output << "C calls that may cause cache clear: #{cache_busters.size}\n"
  grouped_traces = cache_busters.group_by do |trace_info|
    if trace_info[:event] == :c_call
      "#{trace_info[:defined_class]}##{trace_info[:method_id]}"
    else
      "Class Defined"
    end
  end
  grouped_traces.each do |grouping, traces|
    output << "  #{grouping}: #{traces.size}\n"
  end

  output << "\nTraces (method-cache-clear): (#{results[:traces][:method].size} times)\n"
  results[:traces][:method].each do |trace|
    output << "#{trace[:class]} - #{trace[:sourcefile]}##{trace[:lineno]}\n"
  end

  output << "\nTraces (method cache clearing calls): (#{cache_busters.size} times)\n"
  cache_busters.each do |trace_info|
    output << if trace_info[:event] == :c_call
      format("%s\#%s: %s %s\n",
                       trace_info[:defined_class],
                       trace_info[:method_id],
                       trace_info[:target_class],
                       trace_info[:location])
    else
      format("Class Definition: %s %s %s\n",
                       trace_info[:target_class],
                       trace_info[:defined_class],
                       trace_info[:location])
              end
  end

  [200,
   { 'Content-Type' => 'text/plain' },
   ["Tuttle - Ruby Method/Constant Caches Request Observer v0.0.1\n",
    "Ruby Version: #{RUBY_VERSION}\n",
    output]]
end
profile_cpu(env, query_string) click to toggle source
# File lib/tuttle/middleware/request_profiler.rb, line 63
def profile_cpu(env, query_string)
  require 'ruby-prof'
  require 'tuttle/ruby_prof/fast_call_stack_printer'

  query_params = Rack::Utils.parse_nested_query(query_string)
  options = {}
  options[:threshold] = Float(query_params['ruby-prof_threshold']) if query_params.key?('ruby-prof_threshold')
  rubyprof_printer = /ruby-prof_printer=([\w]*)/.match(query_string) { |m| m[1] }

  data = ::RubyProf::Profile.profile do
    _, _, body = @app.call(env)
    body.close if body.respond_to? :close
  end

  result = StringIO.new
  content_type = 'text/html'

  profiler = case rubyprof_printer
             when 'flat'
               content_type = 'text/plain'
               ::RubyProf::FlatPrinter
             when 'graph'
               ::RubyProf::GraphHtmlPrinter
             when 'stack', 'call_stack'
               ::RubyProf::CallStackPrinter
             else
               options[:application] = env['REQUEST_URI']
               ::Tuttle::RubyProf::FastCallStackPrinter
             end

  profiler.new(data).print(result, options)

  [200, { 'Content-Type' => content_type }, [result.string]]
end
profile_memory(env, query_string) click to toggle source
# File lib/tuttle/middleware/request_profiler.rb, line 30
def profile_memory(env, query_string)
  require 'memory_profiler'

  query_params = Rack::Utils.parse_nested_query(query_string)
  options = {
    :ignore_files => query_params['memory_profiler_ignore_files'],
    :allow_files => query_params['memory_profiler_allow_files']
  }
  options[:top] = Integer(query_params['memory_profiler_top']) if query_params.key?('memory_profiler_top')

  status = nil
  body = nil

  t0 = Time.current
  report = MemoryProfiler.report(options) do
    status, _headers, body = @app.call(env)
    body.close if body.respond_to?(:close)
  end
  response_time = Time.current - t0

  result = StringIO.new
  report.pretty_print(result)

  response = ["Report from Tuttle::Middeware::RequestProfiler\n"]
  response << "Time of request: #{Time.current}\n"
  response << "Response status: #{status}\n" unless status == 200
  response << "Response time: #{response_time}\n"
  response << "Response body size: #{body.body.length}\n" if body.respond_to?(:body)
  response << "\n"
  response << result.string
  [200, { 'Content-Type' => 'text/plain' }, response]
end