AllocationStats

Introduction
- Install
- Tabular output examples
- More on trace_object_allocations()
The API
- AllocationStats API
  - Burn one
- AllocationsProxy API
  - What are faux attributes?
  - What is class_plus?
Gotchas
- Allocations in C
- autoload
Examples
- Example from the specs
- A little slower
- Psych example
References

Introduction

AllocationStats is a rubygem that makes use of Ruby 2.1's new abilities to trace Ruby object allocations (MRI only). Ruby 2.1's new ObjectSpace.trace_object_allocations methods give only raw information, and are not immediately useful for anything beyond micro profiling. The data must be aggregated!

AllocationStats collects all of the allocation information generated by ObjectSpace.trace_object_allocations, then provides mechanisms for filtering, grouping, and sorting the allocation information.

Install

To install AllocationStats, add the following line to a project's Gemfile, perhaps to the development group:

gem 'allocation_stats'

or run the following command:

gem install allocation_stats

Tabular output examples

It is very easy to get some simple statistics out of AllocationStats. Wrap some code with AllocationStats.trace and print out a listing of all of the new object allocation information.

As an example, lets look at examples/my_class.rb:

class MyClass
  def my_method
    @hash = {1 => "foo", 2 => "bar"}
  end
end

And use that class in a bit of ad-hoc Ruby:

$ ruby -r ./lib/allocation_stats -r ./allocation
stats = AllocationStats.trace { MyClass.new.my_method }
puts stats.allocations(alias_paths: true).to_text
^D
    sourcefile       sourceline  class_path  method_id  memsize   class
-------------------  ----------  ----------  ---------  -------  -------
<PWD>/allocation.rb           4  MyClass     my_method        0  String
<PWD>/allocation.rb           3  MyClass     my_method      192  Hash
<PWD>/allocation.rb           3  MyClass     my_method        0  String
<PWD>/allocation.rb           3  MyClass     my_method        0  String
<PWD>/allocation.rb           3  MyClass     my_method        0  String
-                             1  Class       new              0  MyClass

(I've used alias_paths: true above for readability. This way, the sourcefile column is not crazy long, using the full file path on my filesystem.)

(This full example is found in examples/trace_my_class_raw.rb)

We can also group allocations by one or more attributes, and get an aggregate count. Below, we group allocations by source file, source line, and class:

$ ruby -r ./lib/allocation_stats -r ./allocation
stats = AllocationStats.trace { MyClass.new.my_method }
puts stats.allocations(alias_paths: true).group_by(:sourcefile, :sourceline, :class).to_text
^D
    sourcefile       sourceline   class   count
-------------------  ----------  -------  -----
<PWD>/allocation.rb           4  String       1
<PWD>/allocation.rb           3  Hash         1
<PWD>/allocation.rb           3  String       3
-                             1  MyClass      1

(This full example is found in examples/trace_my_class_group_by.rb)

More on `trace_object_allocations()`

To start at the beginning: Ruby 2.1 will be released with a new feature that enables one to trace object allocations. Through ObjectSpace.trace_object_allocations, one can trace the following properties for any new object allocation:

source file
source line
class path
method ID
generation

Let's see this in action:

$ cat examples/trace_object_allocations.rb
require 'objspace'

ObjectSpace.trace_object_allocations do
  a = [2,3,5,7,11,13,17,19,23,29,31]
  puts ObjectSpace.allocation_sourcefile(a)
  puts ObjectSpace.allocation_sourceline(a)
end
$ ruby ./examples/trace_object_allocations.rb
./examples/trace_object_allocations.rb
4

To see some detailed examples, review the Examples section.

The API

`AllocationStats` API

The tracing of allocations can be kicked off in a few different ways, to provide flexibility:

Block-style

Just pass a block to AllocationStats.trace:

stats = AllocationStats.trace do
  # code to trace
end

Or initialize an AllocationStats, then call #trace with a block:

stats = AllocationStats.new
stats.trace do
  # code to trace
end

Inline

Wrap lines of code to trace with calls to #trace (or #start) and #stop:

stats = AllocationStats.new
stats.trace  # also stats.start
# code to trace
stats.stop

Burn One

If you find a lot of allocations in kernel_require.rb or a lot of allocations of RubyVM::InstructuinSequences, you can "burn" one or more iterations. Instantiate your AllocationStats instance with the burn keyword, and trace your code block-style. For example: AllocationStats.new(burn: 3).trace{ ... } will first call the block 3 times, without tracing allocations, before calling the block a 4th time, tracing allocations.

`AllocationsProxy` API

Here are the methods available on the AllocationStats::AllocationsProxy object that is returned by AllocationStats#allocations:

#group_by
#from takes one String argument, which will matched against the allocation filename.
#not_from is the opposite of #from.
#from_pwd will filter the allocations down to those originating from pwd (e.g. allocations originating from "my project")
#where accepts a hash of faux attribute keys. For example,
```
allocations.where(class: String)
```
It does not yet accept lambdas as values, which would enable ActiveRecord-4-like calls, like
```
allocations.where(class: Array, size: ->(size) { size > 10 }
```
#at_least(n) selects allocation groups with at least n allocations per group.
#bytes, which has an inconsistent definition, I think... TODO

What are faux attributes?

Valid values for #group_by and #where include:

instance variables on each Allocation. These include :sourcefile, :sourceline, etc.
methods available on the objects that were allocated. These include things like :class, or even :size if you know you only have objects that respond to :size.
Allocation helper methods that return something special about the allocated object. Right now this just includes :class_plus.

I'm calling these things that you can group by or filter by, "faux attributes."

What is `class_plus`?

Tracing RSpec

You can trace an RSpec test suite by including this at the top of your spec_helper.rb:

require 'allocation_stats'
AllocationStats.trace_rspec

This will put hooks around your RSpec tests, tracing each RSpec test individually. When RSpec exits, the top sourcefile/sourceline/class combinations will be printed out.

Tracing RSpec gives maintainers of existing libraries a great place to start to search for inefficiencies in their project. You can trace an RSpec run of your whole test suite, or a subset, and if any one spec allocates hundreds of objects from the same line, then it might be something worth investigating.

Here's the example from examples/trace_specs/:

 rspec strings_spec.rb
..

Top 2 slowest examples (0.08615 seconds, 100.0% of total time):
  Array of Strings allocates Strings and Arrays
    0.0451 seconds ./strings_spec.rb:8
  Array of Strings allocates more Strings
    0.04105 seconds ./strings_spec.rb:12

Finished in 0.08669 seconds
2 examples, 0 failures

Randomized with seed 56224

Top 7 allocation sites:
  5 allocations of String at <PWD>/strings.rb:2
    during ./strings_spec.rb:8
  2 allocations of Array at <PWD>/strings_spec.rb:9
    during ./strings_spec.rb:8
  2 allocations of Array at <PWD>/strings_spec.rb:13
    during ./strings_spec.rb:12
  1 allocations of Array at <PWD>/strings.rb:2
    during ./strings_spec.rb:8
  1 allocations of String at <PWD>/strings.rb:6
    during ./strings_spec.rb:8
  1 allocations of String at <PWD>/strings.rb:14
    during ./strings_spec.rb:12
  1 allocations of String at <PWD>/strings.rb:10
    during ./strings_spec.rb:12

We are informed that during the spec at strings_spec.rb:8, there were 5x Strings allocated at strings.rb:2.

#trace_rspec always burns each test run once, mostly to prevent #autoload from appearing in the allocations.

Gotchas

Allocations in C

If allocations occur in C code (such as a C extension), their allocation site will be somewhat obfuscated. The allocation will still be logged, but the sourcefile and sourceline will register as the deepest Ruby file that called a C function that maybe called other C functions that at some point allocated an object. This brings us to the next gotcha:

`autoload`

Kernel#autoload is tricky! Autoloading can hide allocations (during the ensuing require) in a simple constant reference. For example, in the mail gem, tracing object allocations during rspec spec/mail/body_spec.rb:339 makes it look like the following line allocates 219 Strings:

#  lib/mail/configuration.rb

28    def lookup_delivery_method(method)
29      case method.is_a?(String) ? method.to_sym : method
30      when nil
31        Mail::SMTP  # <-- 219 Strings alloctated here?

To fight this, either don't use autoload, which can be eased into with a fancy mechanism like mail's #eager_autoload, or rely on the burn mechanism. AllocationStats.trace_rspec always burns each test run once.

Examples

Example from the specs

existing_array = [1,2,3,4,5]

stats = AllocationStats.trace do
  new_string     = "stringy string"
  another_string = "another string"
  an_array       = [1,1,2,3,5,8,13,21,34,55]
  a_foreign_string = allocate_a_string_from_spec_helper
end

results = stats.allocations.group_by(:@sourcefile, :class).to_a

We've grouped all of the traced allocations by the source file that the allocation occurred in, and the class of the object that was allocated. The list of allocations can be "transformed" in a number of ways (including the above #group_by), so the transformations must be ultimately resolved by calling #to_a (similar to ActiveRecord relations). The result is the following Hash of (sourcefile, class) tuple keys and AllocationStats::Allocation values:

{
  [".../spec/spec_helper.rb", String]
    =>
  [#<AllocationStats::Allocation:0x007f132ac3f160
    @object="a string from spec_helper",
    @memsize=0,
    @sourcefile=".../spec/spec_helper.rb",
    @sourceline=14,
    @class_path="Object",
    @method_id=:allocate_a_string_from_spec_helper>
  ],

  [".../spec/allocation_stats_spec.rb", Array]
    =>
  [#<AllocationStats::Allocation:0x007f132ac3e968
    @object=[1, 1, 2, 3, 5, 8, 13, 21, 34, 55],
    @memsize=80,
    @sourcefile=".../spec/allocation_stats_spec.rb",
    @sourceline=78,
    @class_path=nil,
    @method_id=nil>
  ],

  [".../spec/allocation_stats_spec.rb", String]
    =>
  [ #<AllocationStats::Allocation:0x007f132ac3e0d0
      @object="another string",
      @memsize=0,
      @sourcefile=".../spec/allocation_stats_spec.rb",
      @sourceline=77,
      @class_path=nil,
      @method_id=nil>,
    #<AllocationStats::Allocation:0x007f132ac3d838
      @object="stringy string",
      @memsize=0,
      @sourcefile=".../spec/allocation_stats_spec.rb",
      @sourceline=76,
      @class_path=nil,
      @method_id=nil>
  ]
}

(I've manually inserted the ellipses.)

You can see that there are three different groups:

[spec_helper.rb, String]
[allocation_stats_spec.rb, Array]
[object_space_stats.rb, String]

Only one allocation belongs to each of the first two groups, and two allocations make up the second group.

A little slower

Let's look at this example a little slower. Firstly, let's look at how we collect object allocations using AllocationStats:

stats = AllocationStats.trace do
  new_string     = "stringy string"
  another_string = "another string"
  an_array       = [1,1,2,3,5,8,13,21,34,55]
  a_foreign_string = allocate_a_string_from_spec_helper
end

Stats are collected by running a block through AllocationStats.trace. This is largely just a thin wrapper around trace_object_allocations(). You are handed back your new AllocationStats, which essentially just holds all of the allocation information, accessible via #allocations. Let's look at the next line to see how we can pull useful information out:

results = stats.allocations.group_by(:@sourcefile, :class).to_a

If you are used to chaining ActiveRecord relations, some of this might look familiar to you: stats.allocations will hand you back an {AllocationStats::AllocationsProxy} object, designed to hold the various transformations that you wish to run the allocations through. AllocationsProxy uses the Command pattern to store up transformations before they will actually be applied. In this example, we only make one transformation: group_by(:@sourcefile, :class). This method just returns the same AllocationsProxy object back, so that transformations can be chained. The final call that will execute the transformations is #to_a (aliased to #all, just like ActiveRecord).

Psych Example

Let's look at an example with more varied allocations, using Ruby's Psych. This one is found in examples/trace_psych_keys.rb:

stats = AllocationStats.trace do
  y = YAML.dump(["one string", "two string"]) # lots of objects from Rbconfig::CONFIG["rubylibdir"]
end

stats.allocations.group_by(:sourcefile, :class).all.keys.each { |key| puts key.inspect }

["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/visitors/yaml_tree.rb", String]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/visitors/yaml_tree.rb", Array]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/visitors/yaml_tree.rb", MatchData]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/visitors/yaml_tree.rb", Method]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/nodes/node.rb", Array]
["(eval)", Psych::Nodes::Sequence]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/tree_builder.rb", Psych::Nodes::Document]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/tree_builder.rb", Psych::Nodes::Stream]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/visitors/yaml_tree.rb", Proc]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/visitors/yaml_tree.rb", RubyVM::Env]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/visitors/yaml_tree.rb", Hash]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/visitors/yaml_tree.rb", Psych::Visitors::YAMLTree::Registrar]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/visitors/yaml_tree.rb", Psych::Visitors::YAMLTree]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/scalar_scanner.rb", Hash]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/visitors/yaml_tree.rb", Psych::ScalarScanner]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/class_loader.rb", Hash]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/visitors/yaml_tree.rb", Psych::ClassLoader]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/tree_builder.rb", Array]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/visitors/yaml_tree.rb", Psych::TreeBuilder]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych.rb", Hash]
["examples/trace_psych_inspect.rb", Array]
["examples/trace_psych_inspect.rb", String]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/visitors/emitter.rb", String]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/visitors/emitter.rb", Array]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/visitors/emitter.rb", RubyVM::InstructionSequence]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/visitors/visitor.rb", String]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/visitors/visitor.rb", MatchData]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/visitors/visitor.rb", Regexp]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/visitors/emitter.rb", Psych::Emitter]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/nodes/node.rb", Psych::Visitors::Emitter]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/nodes/node.rb", StringIO]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/nodes/node.rb", String]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/tree_builder.rb", Psych::Nodes::Scalar]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/scalar_scanner.rb", String]
["/usr/local/rbenv/versions/2.1.0-dev/lib/ruby/2.1.0/psych/scalar_scanner.rb", MatchData]

Again, it is difficult to find useful information from these results without aggregating. Let's do that (examples/trace_psych_group_by):

stats = AllocationStats.trace do
  y = YAML.dump(["one string", "two string"]) # lots of objects from Rbconfig::CONFIG["rubylibdir"]
end

puts stats.allocations(alias_paths: true).group_by(:sourcefile, :class).to_text

               sourcefile                                class                  count
----------------------------------------  ------------------------------------  -----
<RUBYLIBDIR>/psych/visitors/yaml_tree.rb  Array                                    12
<RUBYLIBDIR>/psych/visitors/yaml_tree.rb  String                                   20
<RUBYLIBDIR>/psych/visitors/yaml_tree.rb  MatchData                                 3
<RUBYLIBDIR>/psych/visitors/yaml_tree.rb  Method                                    5
<RUBYLIBDIR>/psych/nodes/node.rb          Array                                     3
(eval)                                    Psych::Nodes::Sequence                    1
<RUBYLIBDIR>/psych/tree_builder.rb        Psych::Nodes::Document                    1
<RUBYLIBDIR>/psych/tree_builder.rb        Psych::Nodes::Stream                      1
<RUBYLIBDIR>/psych/visitors/yaml_tree.rb  Proc                                      1
<RUBYLIBDIR>/psych/visitors/yaml_tree.rb  RubyVM::Env                               1
<RUBYLIBDIR>/psych/visitors/yaml_tree.rb  Hash                                      3
<RUBYLIBDIR>/psych/visitors/yaml_tree.rb  Psych::Visitors::YAMLTree::Registrar      1
<RUBYLIBDIR>/psych/visitors/yaml_tree.rb  Psych::Visitors::YAMLTree                 1
<RUBYLIBDIR>/psych/scalar_scanner.rb      Hash                                      2
<RUBYLIBDIR>/psych/visitors/yaml_tree.rb  Psych::ScalarScanner                      1
<RUBYLIBDIR>/psych/class_loader.rb        Hash                                      1
<RUBYLIBDIR>/psych/visitors/yaml_tree.rb  Psych::ClassLoader                        1
<RUBYLIBDIR>/psych/tree_builder.rb        Array                                     1
<RUBYLIBDIR>/psych/visitors/yaml_tree.rb  Psych::TreeBuilder                        1
<RUBYLIBDIR>/psych.rb                     Hash                                      1
./examples/trace_psych_raw.rb             Array                                     1
./examples/trace_psych_raw.rb             String                                    2
<RUBYLIBDIR>/psych/visitors/emitter.rb    String                                   29
<RUBYLIBDIR>/psych/visitors/emitter.rb    Array                                     3
<RUBYLIBDIR>/psych/visitors/emitter.rb    RubyVM::InstructionSequence               1
<RUBYLIBDIR>/psych/visitors/visitor.rb    String                                   38
<RUBYLIBDIR>/psych/visitors/visitor.rb    MatchData                                 5
<RUBYLIBDIR>/psych/visitors/visitor.rb    Regexp                                    1
<RUBYLIBDIR>/psych/visitors/emitter.rb    Psych::Emitter                            1
<RUBYLIBDIR>/psych/nodes/node.rb          Psych::Visitors::Emitter                  1
<RUBYLIBDIR>/psych/nodes/node.rb          StringIO                                  1
<RUBYLIBDIR>/psych/nodes/node.rb          String                                    3
<RUBYLIBDIR>/psych/tree_builder.rb        Psych::Nodes::Scalar                      2
<RUBYLIBDIR>/psych/scalar_scanner.rb      String                                    5
<RUBYLIBDIR>/psych/scalar_scanner.rb      MatchData                                 2

References

This new feature was inspired by work that @tmm1 did at GitHub, as described in this post. It was proposed as a feature in Ruby Core by @tmm1 in Ruby issue #8107, and @ko1 wrote it into MRI. He introduces the feature in his Ruby Kaigi 2013 presentation, on slides 29 through 33 [pdf].

allocation_stats

Development