Read more

Stackprof - sampling call-stack profiler for ruby

Tobias Kraze
March 11, 2016Software engineer at makandra GmbH

Stackprof is a sampling call-stack profile for Ruby 2.1+.

Illustration online protection

Rails Long Term Support

Rails LTS provides security patches for old versions of Ruby on Rails (2.3, 3.2, 4.2 and 5.2)

  • Prevents you from data breaches and liability risks
  • Upgrade at your own pace
  • Works with modern Rubies
Read more Show archive.org snapshot

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.

The big advantage of this is that it is very fast. You can even enable it in production and collect real performance data. See the README on how to add it as a middleware. It will dump its data to the tmp directory.

Sampling is by default based on CPU time, so it does not matter if an application is idle for a while.

The gem also includes a command line utility to extract useful information from the raw dumps. You can run

stackprof tmp/stackprof-cpu-* --limit 5

to see the 5 worst offenders. The output will look like this:

==================================
  Mode: cpu(100)
  Samples: 107530 (1.04% miss rate)
  GC: 12232 (11.38%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
      7472   (6.9%)        7472   (6.9%)     ActiveRecord::Type::Integer#type_cast_from_database
      3269   (3.0%)        3245   (3.0%)     block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_cache
      2484   (2.3%)        2297   (2.1%)     block in Module#delegate
      2437   (2.3%)        2290   (2.1%)     block (2 levels) in V8::Function#methodcall
      2037   (1.9%)        2032   (1.9%)     ActiveRecord::Core#update_attributes_from_transaction_state

The TOTAL column counts the number of times a certain method appeared anywhere in the sampled stack traces, and the SAMPLES column how often it was on top of the stack trace. Both values correspond roughly to "time spent", either including or excluding children.

You can get more detailed information on a method by running

stackprof tmp/stackprof-cpu-* --method 'ActiveRecord::Type::Integer#type_cast_from_database'

The output will look like this:

ActiveRecord::Type::Integer#type_cast_from_database (activerecord-4.2.5.2/lib/active_record/type/integer.rb:15)
  samples:  7472 self (6.9%)  /   7472 total (6.9%)
  callers:
    7253  (   97.1%)  block (2 levels) in ActiveRecord::Result#cast_values
     218  (    2.9%)  ActiveRecord::Attribute::FromDatabase#type_cast
  code:
                                  |    15  |       def type_cast_from_database(value)
 5811    (5.4%) /  5811   (5.4%)  |    16  |         return if value.nil?
 1661    (1.5%) /  1661   (1.5%)  |    17  |         value.to_i
                                  |    18  |       end
Posted by Tobias Kraze to makandra dev (2016-03-11 17:03)