Jens Dahl Møllerhøj

January 9, 2022

Profiling your Ruby on Rails Application like a boss

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.