Closed
Description
While profiling the initialisation phase of our app I stumbled upon a sizeable chunk due to Grape.
It seems most of the time is spent within Grape::Endpoint#generate_api_method, because Array.sort! uses <=> on its elements, thus internally calling Symbol#to_s since symbols really are just integers.
This seems to negate what could be an attempt at optimisation in #generate_api_method: if instance_methods.include?(method_name.to_sym) || instance_methods.include?(method_name.to_s), though what triggers the sort! dance I don't know, as I tried to isolate it with the following script run from the affected Rails application:
# bundle exec ruby foo.rb
require File.expand_path('../config/environment.rb', __FILE__)
require 'ruby-prof'
result = RubyProf.profile do
1000.times do
Grape::Endpoint.instance_methods.include?(:foo)
end
end
printer = RubyProf::FlatPrinter.new(result)
File.open('prof.out', 'wb') { |f| printer.print(f, {}) }and its output:
Measure Mode: wall_time
Thread ID: 70191707060580
Fiber ID: 70191783619080
Total: 0.161279
Sort by: self_time
%self total self wait child calls name
84.55 0.136 0.136 0.000 0.000 1000 Module#instance_methods
5.13 0.008 0.008 0.000 0.000 1000 Array#include?
2.42 0.004 0.004 0.000 0.000 1000 Module#extend_object
2.12 0.150 0.003 0.000 0.147 1000 Class#instance_methods
1.69 0.161 0.003 0.000 0.159 1 Integer#times
1.29 0.002 0.002 0.000 0.000 1000 Kernel#instance_variable_set
0.88 0.006 0.001 0.000 0.004 1000 Kernel#extend
0.86 0.001 0.001 0.000 0.000 1000 UnboundMethod#bind
0.77 0.138 0.001 0.000 0.136 1000 Method#call
0.26 0.000 0.000 0.000 0.000 1000 Module#extended
0.02 0.161 0.000 0.000 0.161 1 Global#[No method]
* indicates recursively called methods