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