ZOMG! Thanks to @drbrain, mechanize 2.0.0 has been released!

See the full announcement here!

tl;dr: You can return nil from to_ary and to_a.

Today I discovered that it's OK for to_ary to return nil. Ruby spec tests this behavior, and the ruby implementation supports it. But why would you want to implement this?

Array#flatten and to_ary

Consider the following code:

class Item
  def respond_to?(name, visibility = false)
    p "respond to: #{name}"
    false # we don't respond to anything!!
  end

  def method_missing(name, *args)
    p "method missing: #{name}"
    super # if something?
    # do something else
  end
end

[[Item.new]].flatten

In Ruby 1.9, flatten will actually call to_ary on each of the items in the collection. If the method table for this object contains to_ary, Ruby will call to_ary, and if method_missing is implemented, it will call method_missing regardless of how your respond_to? returns. The reason ruby will call method_missing is because it could implement to_ary. (As for why it ignores the return value of respond_to?, I don't know)

Naturally, if we were to call to_ary directly on this object it would raise a NoMethodError exception. When calling flatten, ruby will swallow the exception. If we enable $DEBUG by running ruby with -d, we can see the exception:

[aaron@higgins ~]$ ruby -d test.rb
Exception `LoadError' at /Users/aaron/.local/lib/ruby/site_ruby/1.9.1/rubygems.rb:1215 - cannot load such file -- rubygems/defaults/operating_system
Exception `LoadError' at /Users/aaron/.local/lib/ruby/site_ruby/1.9.1/rubygems.rb:1224 - cannot load such file -- rubygems/defaults/ruby
"method missing: to_ary"
Exception `NoMethodError' at test.rb:9 - undefined method `to_ary' for #<Item:0x00000101079e80>
"respond to: to_ary"
[aaron@higgins ~]$

Dispatching to method_missing can be expensive, and using exceptions for flow control even more problematic. The way we can get around this issue is by implementing to_ary and having it return nil:

class Item
  def respond_to?(name, visibility = false)
    p "respond to: #{name}"
    false # we don't respond to anything!!
  end

  def method_missing(name, *args)
    p "method missing: #{name}"
    super # if something?
    # do something else
  end

  private
  def to_ary
    nil
  end
end

[[Item.new]].flatten

Run the code again with -d, and you'll see no more calls to respond_to?, no more calls to method_missing, and no more exceptions raised:

[aaron@higgins ~]$ ruby -d test.rb
Exception `LoadError' at /Users/aaron/.local/lib/ruby/site_ruby/1.9.1/rubygems.rb:1215 - cannot load such file -- rubygems/defaults/operating_system
Exception `LoadError' at /Users/aaron/.local/lib/ruby/site_ruby/1.9.1/rubygems.rb:1224 - cannot load such file -- rubygems/defaults/ruby
[aaron@higgins ~]$

Array() and to_a

The Array() function exhibits a similar behavior, but with the to_a method. Try this same code, but rather than using Array#flatten, do this:

Array(Item.new)

We can fix the error produced by this code with a slight change to our class:

class Item
  def respond_to?(name, visibility = false)
    p "respond to: #{name}"
    false # we don't respond to anything!!
  end

  def method_missing(name, *args)
    p "method missing: #{name}"
    super # if something?
    # do something else
  end

  private
  def to_ary
    nil
  end
  alias :to_a :to_ary
end

[[Item.new]].flatten
Array(Item.new)

Hmmmm

Are warnings annoying? Yes. Is this strange behavior? I tend to think so. But if I'm forced to deal with a class the implements method_missing, I'd like to reduce the number of calls to method_missing.

Anyway. I hope you found this informative. Have a Happy Tuesday!!!!

<3 <3 <3 <3

Small Side Note

The reason there are exceptions coming from rubygems when -d is enabled is because rubygems attempts to require files that are not shipped with rubygems. These files are for packagers to provide. For example someone packaging rubygems for debian, may need to do customizations and those files are where that happens.

Recently I was debugging a performance regression in Rails 3.1. The ticket reported for the regression just indicated a speed problem. Namely allocating new active record objects was very slow in Rails 3.1 compared to Rails 3.0.

The benchmark program

Here is the program I was using for benchmarking. It's slightly modified from the original program that @paul so kindly submitted:

require 'active_record'
require 'benchmark'

p ActiveRecord::VERSION::STRING

ActiveRecord::Base.establish_connection(
  :adapter  => "sqlite3",
  :database => ":memory:"
)

ActiveRecord::Base.connection.execute("CREATE TABLE active_record_models (id INTEGER UNIQUE, title STRING, text STRING)")

class ActiveRecordModel < ActiveRecord::Base; end
ActiveRecordModel.new

N = 100_000
Benchmark.bm { |x| x.report('new') { N.times { ActiveRecordModel.new } } }

I could tell from perftools.rb output we were calling new methods, and those new methods took plenty of time.

Here is the call graph for this benchmark on Rails 3.0:

Compared to the call graph on Rails 3.1:

After some work, I was able to remove the method calls to scope when allocating new AR objects, but the benchmark still showed 3.1 to be slower than 3.0. I noticed we were spending more time in the Garbage Collector on 3.1 than on 3.0. This lead me to believe that we were creating more objects in the newer version.

Counting Object Allocations

Counting object allocations with Ruby 1.9 is actually pretty easy. We can call ObjectSpace.count_objects to get a list of the live objects in the system. That method returns a hash where the keys are the object type and the values are the number of that object in the system (there are other keys, be we don't care about them for now).

Knowing this information, we can write a function that will calculate a rough difference in object allocations:

def allocate_count
  GC.disable
  before = ObjectSpace.count_objects
  yield
  after = ObjectSpace.count_objects
  after.each { |k,v| after[k] = v - before[k] }
  GC.enable
  after
end

p allocate_count { 100.times { {} } }

The first thing we do in this function is disable the garbage collector. It's possible that the code we're investigating could trigger GC, and that will impact our allocated object count.

Then we grab our current list of objects, yield to the code we want to profile, grab the list again, calculate our delta, enable GC and return!

If you run this code, you should see output similar to this (I've removed keys I don't care about):

{ ... :T_HASH=>101, ... }

You can see from the output that we've allocated 101 hashes. 100 came from our 100.times call, and one came from calling the method on ObjectSpace.

Since inspecting our code can impact object allocations, these counts can't be 100% accurate. Another annoying thing is that we can't determine where our code is allocating these hashes. It's easy enough to see the hash literals in this code, but imagine a project like rails. You may be able to find hash literals in your source, but determining which ones are being called is difficult.

After running this against the profile, I found that ActiveRecord in 3.1 was allocating 2x the number of hashes that 3.0 allocated. Now the problem is figuring out where these hashes were being allocated.

DTrace

DTrace gives us hooks in to our processes. Many of the hooks provided are for system calls, or other various functions. DTrace requires that we write probes in our code, and unfortunately Ruby does not have DTrace probes built in.

Adding DTrace to Ruby

To find these Hash allocations, I decided to add DTrace support. I usually run Ruby built from Ruby trunk, so running a modified Ruby seemed acceptible. It turns out adding DTrace support is pretty easy.

First I added a probe definition file. This file describes the probes that I want to add to Ruby. It contains the probe names and the signatures of the probes:

provider ruby {
  probe hash__alloc(const char *, int);
};

This definition says we're declaring a probe called hash-alloc and it will take a string (the file name) and an int (the line number).

Next I used this definition file to generate a header file that ruby would use:

$ dtrace -o probes.h -h -s probes.d

Finally, I modified hash.c to trigger the probe:

diff --git a/hash.c b/hash.c
index b49aff8..c40d94d 100644
--- a/hash.c
+++ b/hash.c
@@ -15,6 +15,7 @@
 #include "ruby/st.h"
 #include "ruby/util.h"
 #include "ruby/encoding.h"
+#include "probes.h"
 #include <errno.h>
 
 #ifdef __APPLE__
@@ -221,6 +222,9 @@ hash_alloc(VALUE klass)
     OBJSETUP(hash, klass, T_HASH);
 
     RHASH_IFNONE(hash) = Qnil;
+    if(RUBY_HASH_ALLOC_ENABLED()) {
+       RUBY_HASH_ALLOC(rb_sourcefile(), rb_sourceline());
+    }
 
     return (VALUE)hash;
 }

After this, I built and installed ruby. Then I wrote a dtrace script to display the filename and line number where hash allocations were happening:

ruby*:::hash-alloc
{
  printf("%s:%d", copyinstr(arg0), arg1);
}

Then I ran the benchmark with dtrace:

$ sudo dtrace -s x.d -c 'ruby -I lib test.rb'

Here is an excerpt of the output:

~~~ 1 126930 hash_alloc:hash-alloc /Users/aaron/git/rails/activerecord/lib/active_record/base.rb:1528 1 126930 hash_alloc:hash-alloc /Users/aaron/git/rails/activerecord/lib/active_record/base.rb:1529 1 126930 hash_alloc:hash-alloc /Users/aaron/git/rails/activerecord/lib/active_record/base.rb:1534 1 126930 hash_alloc:hash-alloc /Users/aaron/git/rails/activerecord/lib/active_record/base.rb:1535 1 126930 hash_alloc:hash-alloc /Users/aaron/git/rails/activerecord/lib/active_record/base.rb:1525 1 126930 hash_alloc:hash-alloc /Users/aaron/git/rails/activerecord/lib/active_record/persistence.rb:322 1 126930 hash_alloc:hash-alloc /Users/aaron/git/rails/activerecord/lib/active_record/base.rb:1527 1 126930 hash_alloc:hash-alloc /Users/aaron/git/rails/activerecord/lib/active_record/base.rb:1528 1 126930 hash_alloc:hash-alloc /Users/aaron/git/rails/activerecord/lib/active_record/base.rb:1529 1 126930 hash_alloc:hash-alloc /Users/aaron/git/rails/activerecord/lib/active_record/base.rb:1534 1 126930 hash_alloc:hash-alloc /Users/aaron/git/rails/activerecord/lib/active_record/base.rb:1535 1 126930 hash_alloc:hash-alloc /Users/aaron/git/rails/activerecord/lib/active_record/base.rb:1525</code></pre>

I was able to compare the output from this script on Rails 3.0 vs Rails 3.1. From this output, I was able to determine:

• The number of hash allocations
• Where the hashes were allocated
• Which allocations were new in Rails 3.1

Armed with this information, I was able to eliminate some allocations and return speed in Rails 3.1 to that of Rails 3.0.

DTrace vs gdb vs memprof

I probably could have accomplished this task with memprof, but it requires that I use 1.8.7 from rvm. Working with RVM on my machine is difficult (don't ask, let's just say I'm a "special needs" user), and I wanted to use 1.9. So memprof was out the window.

I was able to get the same information by scripting gdb. I set a breakpoint at the correct function, called rb_sourcefile() and rb_sourceline() and redirected to a file. The problem with gdb is that it seemed very slow, and scripting it was a pain (though I am not a gdb expert!).

DTrace was fast, relatively easy to use, and very scriptable. It made me happy!

OMG!!!

I would like to see dtrace probes officially added to ruby trunk. The ruby that ships with OS X has them built in, but they don't give us information like hash literal allocations. It looks like they were in ruby trunk at one point, but were then reverted. I would like to see them added again.

If you want to play with them on ruby trunk, here is my full patch. Make sure to run make probes.h before make && make install.

HAPPY WEDNESDAY!!!! <3 <3 <3 <3

(it feels good to blog on a non “professional” blog)