While investigating performance problems in a Rails app, a profiler is quite helpful. stackprof is such a tool which can be added to an existing Rails app quite easily.
Installation
As usual, add
gem 'stackprof'
to your Gemfile
and run
$ bundle install
To enable profiling, add this line to your configuration:
# development.rb
config.middleware.use(StackProf::Middleware,
out: 'tmp/stackprof.dump',
enabled: true,
mode: :wall,
interval: 1000,
save_every: 5)
Important here is the save_every: 5
parameter. It means that profile data is written after 5 HTTP request to your application.
Usage
Restart your server
$ rails s
And make 5 requests to your app (usually you would investigate performance issues for a single action, i.e. you would run the same request 5 times in a row).
Now, raw profile data should be created in files tmp/stackprof-wall-*
.
Finally, you would generate profiling information by
$ stackprof tmp/stackprof-wall-*dump
This gives you something like
$ stackprof tmp/stackprof-wall-*dump
==================================
Mode: wall(1000)
Samples: 20152 (4.57% miss rate)
GC: 590 (2.93%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
15666 (77.7%) 15666 (77.7%) Puma::Single#run
590 (2.9%) 590 (2.9%) (garbage collection)
502 (2.5%) 436 (2.2%) Logger::LogDevice#write
265 (1.3%) 265 (1.3%) ActiveRecord::LogSubscriber#ignored_callstack
227 (1.1%) 227 (1.1%) Logger::Formatter#format_datetime
224 (1.1%) 224 (1.1%) ActiveRecord::Base.logger
157 (0.8%) 157 (0.8%) Mysql2::Client#query
119 (0.6%) 119 (0.6%) Concurrent::Collection::NonConcurrentMapBackend#[]
118 (0.6%) 118 (0.6%) Sprockets::Mime#compute_extname_map
97 (0.5%) 97 (0.5%) ActiveRecord::LogSubscriber#sql_color
358 (1.8%) 92 (0.5%) Logger::Formatter#call
1047 (5.2%) 83 (0.4%) Logger#add
63 (0.3%) 63 (0.3%) ActiveSupport::TaggedLogging::Formatter#current_tags
53 (0.3%) 53 (0.3%) ActiveRecord::Result#hash_rows
1156 (5.7%) 49 (0.2%) ActiveSupport::Logger#add
48 (0.2%) 48 (0.2%) ActiveRecord::QueryMethods#get_value
wall vs cpu
Depending on your use case, you might want to
- analyze time spent in your app together with other systems like a database or an external http service (
wall
mode = total runtime)
– or –
- analyze time spent in your app itself (
cpu
mode = cpu time)
You might have noticed that in the listing above, most time is spent for Puma.single
. This is because we’ve used mode: :wall
in our configuration. Puma.single basically means i/o wait.
How it works
Note that stackprof is a sampling profiler:
Stackprof is a sampling call-stack profile for Ruby 2.1+. Instead of tracking all method calls, it will simply collect the current stack trace of a running program at fixed intervals. Methods that appear on top of the stack trace most often, are the methods your program spends most of its time in. (https://makandracards.com/makandra/38975-stackprof-sampling-call-stack-profiler-for-ruby)
Resources
- https://scoutapm.com/blog/profiling-rails-with-stackprof
- https://samsaffron.com/archive/2018/01/18/my-production-ruby-on-rails-cpu-is-at-100-now-what
- https://scoutapm.com/blog/which-rails-profiler-is-right-for-you
- https://github.com/MiniProfiler/rack-mini-profiler
- http://maratgaliev.com/profiling-ruby-rails/
- https://engineering.appfolio.com/appfolio-engineering/2019/6/4/where-does-rails-spend-its-time