Usually, when trying to figure out why my code is slow I am only interested in code that I can actually change. Luckly, the StackProf gem allows us to do just that:
# Gemfile gem "stackprof"
# spec/spec_helper.rb RSpec.configure do |config| config.around do |example| if example.metadata[:profile] profile = StackProf.run(mode: :cpu, interval: 1000) do example.run end report = StackProf::Report.new(profile) report.print_text(true, nil, [Rails.root.to_s]) else example.run end end end
Now, set the :profile tag on any spec:
it "works but is slow", :profile do ... end
Add you'll get useful info about what parts on your code is slow:
Randomized with seed 36924 ================================== Mode: cpu(1000) Samples: 437 (16.44% miss rate) GC: 47 (10.76%) ================================== TOTAL (pct) SAMPLES (pct) FRAME RSpec::ExampleGroups::FooJob::ExampleGroup#Spec 282 (64.5%) 0 (0.0%) SidekiqJob.perform_later 282 (64.5%) 0 (0.0%) Reports::FooJob#perform 279 (63.8%) 0 (0.0%) Reports::FooJob#call 255 (58.4%) 0 (0.0%) Umr::BarClass#each 204 (46.7%) 0 (0.0%) Reports::FooJob#process_payload 65 (14.9%) 0 (0.0%) Reports::FooJob#payloads 60 (13.7%) 0 (0.0%) Gateway::Baz#reports 60 (13.7%) 0 (0.0%) Gateway::Baz#with_token ....
You can ignore the "SAMPLES" metrics. (They show how many times that particular method was on the top of the stack, which is irrelevant.)
The "TOTAL pct" is what's interesting: It is an estimate (Stackprof is a sampling tracer) of how much time we spend in each method of the total time. (Notice that since methods are nested, this does not sum to 100%).
This should give you a pretty good idea about what is going on.