AllocationStats 
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
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#fromtakes one String argument, which will matched against the allocation filename.#not_fromis the opposite of#from.#from_pwdwill filter the allocations down to those originating frompwd(e.g. allocations originating from "my project")#whereaccepts 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 leastnallocations 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:sizeif 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].