Tenderlove Making

I am a puts debuggerer

I love puts debugging

I am a puts debuggerer. I don’t say this to disparage people that use a Real Debugger. I think Real Debuggers are great, I’ve just never taken the time to learn one well. Every time I try to lean one, I end up not using it for a while and have to re-learn how to use it. Anyway, I want to share some tricks I use for puts debugging with you. I use these tricks whenever I don’t understand how something works and I want to know more. Most of the stuff below is definitely not a “best practice” and you should never leave this code around when you’re done with a debugging session. However, I think it’s important to say that when you’re debugging anything goes. I mean anything. Global variables, redefining methods, adding conditionals, manipulating the load path, monkey patching, printing the call stack, anything.

I’ve tried to stick to real world examples in this post. However, many of these examples came from when I was trying to debug security issues in Rails, so please reuse the techniques I’m showing here but not the target code. The target code I’m trying to debug is broken, and I don’t want you to use it.

I’ve tried to organize each section in to a headline with the problem I have, and the body as the solution I used.

Also, I gave up on using a consistent voice because this is a blog post and I don’t care.

I know where I am but not how I got here

Sometimes I’ll be debugging an issue and know where the problem is, but not how I got there. For those times I’ll just do puts caller to get the callstack.

For example I have this code:

  LOOKUP           = Hash.new { |h, k| h[k] = Type.new(k) unless k.blank? }

But I need to know how the default block is getting called, I do this:

  LOOKUP           = Hash.new { |h, k|
    puts "#" * 90
    puts caller
    puts "#" * 90
    h[k] = Type.new(k) unless k.blank?
  }

The above code will print out 90 hash tags, then the call stack, then 90 more hash tags. I print out the hash tags so that if it gets called multiple times, I can easily differentiate the call stacks. Note that I am calling them “hash tags” in order to annoy you.

I do this pretty frequently, so I have a Vim shortcut to do it:

" puts the caller
nnoremap <leader>wtf oputs "#" * 90<c-m>puts caller<c-m>puts "#" * 90<esc>

That lets me do <leader>wtf and inserts those three lines below the line that I’m on.

I only want to print the call stack once

Just use exit! after printing the callstack, or call raise. raise will show an exception so you see the stack anyway.

I only want to see the stack in certain cases

This is debugging code, so you can do whatever you want. Lets say I just want to see the stack when adding something to the hash. Just do this:

  LOOKUP           = Hash.new { |h, k|
    unless k.blank?
      puts "#" * 90
      puts caller
      puts "#" * 90
      h[k] = Type.new(k)
    end
  }

Since I’m going to throw this code away anyway, I’m free to add any kind of weird conditionals I’d like!

I’m calling a method, but I don’t know where it goes

In the case where I’m calling a method, but I don’t know where that method is implemented, I’ll use the method method along with the source_location method. For example, I have an action in a controller that calls render and I want to find that method:

def show
  render params[:id]
end

I’ll change the above code to this:

def index
  p method(:render).source_location
  render params[:id]
end

Run this:

$ curl http://localhost:3000/users/xxxx

Then in the logs I see this:

Processing by UsersController#show as */*
  Parameters: {"id"=>"xxxx"}
["/Users/aaron/git/rails/actionpack/lib/action_controller/metal/instrumentation.rb", 40]
Completed 500 Internal Server Error in 35ms (ActiveRecord: 0.0ms)

Now I know that the render method is in instrumentation.rb on line 40.

I’m calling super but I don’t know where that goes

Here I can see that render calls super, but I don’t know where that is implemented. In that case, I use super_method on the return value of method.

So I change this:

def index
  p method(:render).source_location
  render params[:id]
end

To this:

def index
  p method(:render).super_method.source_location
  render params[:id]
end

Run the same request through, and I get this for the output:

Processing by UsersController#show as */*
  Parameters: {"id"=>"xxxx"}
["/Users/aaron/git/rails/actionpack/lib/action_controller/metal/rendering.rb", 34]
Completed 500 Internal Server Error in 34ms (ActiveRecord: 0.0ms)

Now I see that super goes here. That method also calls super, but I can just rinse and repeat the above process (or use a loop!) to find the method I actually care about.

What if the thing implements the method method?

Sometimes the method trick doesn’t work because the object I want to know about implements it’s own version of method. For example, I am trying to find where the headers method is implemented on the request object with this code:

def index
  p request.method(:headers).source_location
  @users = User.all
end

When I run a request, I get this error:

ArgumentError (wrong number of arguments (given 1, expected 0)):
  app/controllers/users_controller.rb:5:in `index'

This is because the request object implements it’s own method called method. To figure out where the headers method is, I will unbind the method from Kernel, rebind it to the request, then execute it like this:

def index
  method = Kernel.instance_method(:method)
  p method.bind(request).call(:headers).source_location
  @users = User.all
end

Running the request again, I get this for the output:

Processing by UsersController#index as */*
["/Users/aaron/git/rails/actionpack/lib/action_dispatch/http/request.rb", 201]

Now I know the headers method is implemented here.

I can even find the implementation of the method method like this:

def index
  method = Kernel.instance_method(:method)
  p method.bind(request).call(:method).source_location
  @users = User.all
end

I’m calling something but I don’t know where it goes (again)

Sometimes the immediate method isn’t the method I actually care about, so using the method trick to figure out where I’m going won’t help. In that case, I’ll use a larger hammer which is TracePoint. We can redo the render example to get a list of all methods that are called from render. The methods we’ll see listed may not be called directly from render but from somewhere.

  # GET /users
  # GET /users.json
  def index
    @users = User.all
    tp = TracePoint.new(:call) do |x|
      p x
    end
    tp.enable
    render 'index'
  ensure
    tp.disable
  end

The TracePoint allocated here will fire on every “call” event and the block will print out the method name and location of the call. A “call” even it when a Ruby method gets called (not a C method). If you want to see C methods as well, use :c_call. This example will produce a ton of output. I really only use this technique when the number of methods being called is fairly small, or I don’t even know where to begin looking.

I know an exception is getting raised, but I don’t know where

Sometimes an exception gets raised, but I don’t know where the exception actually got raised. This example uses Rails 3.0.0 (we’ve since fixed this issue), but say you have this code:

ActiveRecord::Base.logger = Logger.new $stdout

User.connection.execute "oh no!"

I know this SQL won’t work, and there will be an exception. But lets see what the exception actually looks like:

  SQL (0.1ms)  oh no!
SQLite3::SQLException: near "oh": syntax error: oh no!
activerecord-3.0.0/lib/active_record/connection_adapters/abstract_adapter.rb:202:in `rescue in log': SQLite3::SQLException: near "oh": syntax error: oh no! (ActiveRecord::StatementInvalid)
	from activerecord-3.0.0/lib/active_record/connection_adapters/abstract_adapter.rb:194:in `log'
	from activerecord-3.0.0/lib/active_record/connection_adapters/sqlite_adapter.rb:135:in `execute'
	from test.rb:6:in `<top (required)>'
	from railties-3.0.0/lib/rails/commands/runner.rb:48:in `eval'
	from railties-3.0.0/lib/rails/commands/runner.rb:48:in `<top (required)>'
	from railties-3.0.0/lib/rails/commands.rb:39:in `require'
	from railties-3.0.0/lib/rails/commands.rb:39:in `<top (required)>'
	from script/rails:6:in `require'
	from script/rails:6:in `<main>'

If you read this backtrace, it looks like the exception came from abstract_adapter.rb line 202. However, what you’ll quickly notice is that this code is rescuing an exception, and then re-raising. So where did the real exception get raised? To find it, we could add some puts statements, or use the -d flag on Ruby like this:

[aaron@TC okokok (master)]$ bundle exec ruby -d script/rails runner test.rb

The -d flag will enable warnings and also print out every line where an exception was raised. Yes, this definitely prints a bunch of stuff, but if you look at the output near the end it will look something like this:

Exception `NameError' at activesupport-3.0.0/lib/active_support/core_ext/module/remove_method.rb:3 - method `_validators' not defined in Class
Exception `SQLite3::SQLException' at sqlite3-1.3.11/lib/sqlite3/database.rb:91 - near "oh": syntax error
Exception `SQLite3::SQLException' at activesupport-3.0.0/lib/active_support/notifications/instrumenter.rb:24 - near "oh": syntax error
  SQL (0.1ms)  oh no!
SQLite3::SQLException: near "oh": syntax error: oh no!
Exception `ActiveRecord::StatementInvalid' at activerecord-3.0.0/lib/active_record/connection_adapters/abstract_adapter.rb:202 - SQLite3::SQLException: near "oh": syntax error: oh no!
Exception `ActiveRecord::StatementInvalid' at railties-3.0.0/lib/rails/commands/runner.rb:48 - SQLite3::SQLException: near "oh": syntax error: oh no!
activerecord-3.0.0/lib/active_record/connection_adapters/abstract_adapter.rb:202:in `rescue in log': SQLite3::SQLException: near "oh": syntax error: oh no! (ActiveRecord::StatementInvalid)
	from activerecord-3.0.0/lib/active_record/connection_adapters/abstract_adapter.rb:194:in `log'
	from activerecord-3.0.0/lib/active_record/connection_adapters/sqlite_adapter.rb:135:in `execute'
	from test.rb:6:in `<top (required)>'
	from railties-3.0.0/lib/rails/commands/runner.rb:48:in `eval'
	from railties-3.0.0/lib/rails/commands/runner.rb:48:in `<top (required)>'
	from railties-3.0.0/lib/rails/commands.rb:39:in `require'
	from railties-3.0.0/lib/rails/commands.rb:39:in `<top (required)>'
	from script/rails:6:in `require'
	from script/rails:6:in `<main>'

You’ll see the original exception happened here:

Exception `SQLite3::SQLException' at sqlite3-1.3.11/lib/sqlite3/database.rb:91 - near "oh": syntax error

And it was re-raised here:

Exception `SQLite3::SQLException' at activesupport-3.0.0/lib/active_support/notifications/instrumenter.rb:24 - near "oh": syntax error

Cases where exceptions are getting wrapped and re-raised should expose the originating backtrace. So this is a bug, but it has been fixed, and we can cover how to fix that another day.

I want to run a command line tool with -d

Say you want to use the above technique to run your RSpec tests with the -d flag, you can do this:

$ ruby -d -S rspec

I want to use the -d flag but I don’t know how to run the process

The default Rake test task will run your tests in a sub process. This means that running ruby -d -S rake will not set the debug flag in the sub-process that runs your tests. In this case I use the RUBYOPT environment variable like this:

[aaron@TC okokok (master)]$ RUBYOPT=-d bundle exec rake test

The RUBYOPT environment variable will get applied to every Ruby program that is executed in this shell, even sub shells executed by rake. This means the rspec command above could be rewritten as:

$ RUBYOPT=-d rspec

I need to find where this object came from

Usually printing the callstack will tell me where an object came from. But sometimes the object is allocated outside of the stack, so it’s difficult to figure out where it came from. Take this code for example:

def foo
  x = baz
  bar x
end

def bar x
  puts "#" * 90
  puts caller
  puts "#" * 90
  p x
end

def baz; zot;        end
def zot; Object.new; end

foo

I used the “wtf" technique from "I know where I am but not how I got here", and printed out the value of `x`. From that, I learned that I really care how that `x` value was allocated, but if I trace back up the stack to the `foo` method, I can see that it calls `baz` to get the value. In large code bases, it can be very tricky to follow all the calls and logic through a sibling tree (if you think about the code as a graph, then the `foo` method has two children, `baz` and `bar`, so you can think of `baz` as being a sibling to `bar`). I am lazy and I don't want to go chasing through all the methods to find how this object came to be, so I like to use Ruby's object allocation tracer. Ruby's allocation tracer has been available since Ruby 2.1 (don't quote me on that). When I use it, I require and enable it as soon as possible. Then I print out the allocation location at the place I care about, like this:

require 'objspace'
ObjectSpace.trace_object_allocations_start

def foo
  x = baz
  bar x
end

def bar x
  p ObjectSpace.allocation_sourcefile(x) => ObjectSpace.allocation_sourceline(x)
end

def baz; zot;        end
def zot; Object.new; end

foo

When I run the program, the output is like this:

[aaron@TC tlm.com (master)]$ ruby x.rb 
{"x.rb"=>14}
[aaron@TC tlm.com (master)]$ 

I see that the object is allocated on line 14 in x.rb. So I go to that line and that method, then repeat the “wtf" trick or this trick until I figure out what is wrong with the program.

I usually start object tracing ASAP because I don’t know where my object will be allocated. The tracing slows down the program, but not enough to really matter while I’m debugging.

I need to require something really, really early

The above technique will only give you allocation information for objects that have been allocated after trace_object_allocations_start has been called. Lets say the object is being allocated at file require time, but you don’t know what file or where. In this case, I want to execute some code way before anything in the framework gets required. To do that, I’ll use the -r flag and write a script.

Say there’s a script where we’re trying to find the allocation location of User::BLACKLISTED_CLASS_METHODS.

require 'active_record'

ActiveRecord::Base.establish_connection adapter: 'sqlite3', database: ':memory:'

ActiveRecord::Base.connection.instance_eval do
  create_table :users
end

class User < ActiveRecord::Base; end
p ObjectSpace.allocation_sourcefile(User::BLACKLISTED_CLASS_METHODS) =>
    ObjectSpace.allocation_sourceline(User::BLACKLISTED_CLASS_METHODS)

But we don’t know which file allocates that constant, and don’t want to figure it out (yes this is slightly contrived). I will write a file, in this case named y.rb that looks like this:

require 'objspace'
ObjectSpace.trace_object_allocations_start

Then I’ll use the command line arguments to Ruby to require this file and execute my program:

[aaron@TC tlm.com (master)]$ ruby -I. -ry x.rb
{"/Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/activerecord-5.0.0.beta1/lib/active_record/attribute_methods.rb"=>35}
[aaron@TC tlm.com (master)]$ 

If we break down the arguments to Ruby, the -I. says “add . to the load path”, -ry is the same as require 'y', then run x.rb. So . is added to the load path, and y.rb is required before Ruby even starts running x.rb. Then we see that the BLACKLISTED_CLASS_METHODS was allocated in attribute_methods.rb line 35. You can combine this technique with the RUBYOPT technique in case you code is run in a sub process like this:

$ RUBYOPT='-I. -ry' rake test

An object is being mutated, but I don’t know where

Sometimes I run in to an object that I know is being mutated, but I don’t know where the mutation is happening. In that case, I will call freeze on the object, run my test, and then see where an exception occurs. As an example, I needed to figure out where this variable is being mutated. I knew it was being mutated, I could see in the code it’s being mutated, but I didn’t know where that was happening first. So I changed the code to be like this:

def initialize
  super()

  @cv = new_cond

  @sharing = Hash.new(0)
  @sharing.freeze
  @waiting = {}
  @exclusive_thread = nil
  @exclusive_depth = 0
end

Booting the server gave me a exception with stack trace:

active_support/concurrency/share_lock.rb:151:in `delete': can't modify frozen Hash (RuntimeError)
	from active_support/concurrency/share_lock.rb:151:in `yield_shares'
	from active_support/concurrency/share_lock.rb:79:in `block in stop_exclusive'

Now I know where the first mutation happened. If that’s not the one I care about, I can remove the freeze I added earlier, and add it after this mutation.

I have a deadlock, but I don’t know where

When I’m having issues with threads and I don’t know where it is, I’ll add some code to inspect the live threads. For example, I was debugging this issue. The application server was hanging, but I didn’t know where. To find where the threads were hanging, I wrote a file called x.rb with code like this:

trap(:INFO) {
  Thread.list.each do |t|
    puts "#" * 90
    p t
    puts t.backtrace
    puts "#" * 90
  end
}

Then booted the app server like this:

$ ruby -I. -rx bin/rails s

Now when the app server hangs, I hit Ctrl-T (sorry, this only works on OS X, you’ll need to use kill on Linux), and I’ll see a stack trace for every thread:

##########################################################################################
#<Thread:0x007f90bc07cb38 run>
omglolwut/x.rb:7:in `backtrace'
omglolwut/x.rb:7:in `block (2 levels) in <top (required)>'
omglolwut/x.rb:4:in `each'
omglolwut/x.rb:4:in `block in <top (required)>'
gems/puma-2.16.0/lib/rack/handler/puma.rb:43:in `join'
gems/puma-2.16.0/lib/rack/handler/puma.rb:43:in `run'
gems/rack-2.0.0.alpha/lib/rack/server.rb:296:in `start'
rails/commands/server.rb:78:in `start'
rails/commands/commands_tasks.rb:90:in `block in server'
rails/commands/commands_tasks.rb:85:in `tap'
rails/commands/commands_tasks.rb:85:in `server'
rails/commands/commands_tasks.rb:49:in `run_command!'
rails/command.rb:20:in `run'
rails/commands.rb:19:in `<top (required)>'
bin/rails:4:in `require'
bin/rails:4:in `<main>'
##########################################################################################
##########################################################################################
#<Thread:0x007f90bef3b668@/Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/puma-2.16.0/lib/puma/reactor.rb:136 sleep>
lib/puma/reactor.rb:29:in `select'
lib/puma/reactor.rb:29:in `run_internal'
lib/puma/reactor.rb:138:in `block in run_in_thread'
##########################################################################################
##########################################################################################
#<Thread:0x007f90bef3b500@/Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/puma-2.16.0/lib/puma/thread_pool.rb:216 sleep>
lib/puma/thread_pool.rb:219:in `sleep'
lib/puma/thread_pool.rb:219:in `block in start!'
##########################################################################################
##########################################################################################
#<Thread:0x007f90bef3b3c0@/Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/puma-2.16.0/lib/puma/thread_pool.rb:187 sleep>
lib/puma/thread_pool.rb:190:in `sleep'
lib/puma/thread_pool.rb:190:in `block in start!'
##########################################################################################
##########################################################################################
#<Thread:0x007f90bef3b258@/Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/puma-2.16.0/lib/puma/server.rb:296 sleep>
lib/puma/server.rb:322:in `select'
lib/puma/server.rb:322:in `handle_servers'
lib/puma/server.rb:296:in `block in run'
##########################################################################################
##########################################################################################
#<Thread:0x007f90c1ef9a08@/Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/puma-2.16.0/lib/puma/thread_pool.rb:61 sleep>
lib/ruby/2.4.0/monitor.rb:111:in `sleep'
lib/ruby/2.4.0/monitor.rb:111:in `wait'
lib/ruby/2.4.0/monitor.rb:111:in `wait'
lib/ruby/2.4.0/monitor.rb:132:in `wait_until'
action_dispatch/http/response.rb:170:in `block in await_commit'
lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'
action_dispatch/http/response.rb:169:in `await_commit'
action_controller/metal/live.rb:270:in `process'
action_controller/metal.rb:193:in `dispatch'
action_controller/metal.rb:265:in `dispatch'
action_dispatch/routing/route_set.rb:50:in `dispatch'
action_dispatch/routing/route_set.rb:32:in `serve'
##########################################################################################
##########################################################################################
#<Thread:0x007f90bd1d5f38@/Users/aaron/git/rails/actionpack/lib/action_controller/metal/live.rb:279 sleep>
lib/ruby/2.4.0/monitor.rb:111:in `sleep'
lib/ruby/2.4.0/monitor.rb:111:in `wait'
lib/ruby/2.4.0/monitor.rb:111:in `wait'
lib/ruby/2.4.0/monitor.rb:123:in `wait_while'
active_support/concurrency/share_lock.rb:57:in `block (2 levels) in start_exclusive'
active_support/concurrency/share_lock.rb:154:in `yield_shares'
active_support/concurrency/share_lock.rb:56:in `block in start_exclusive'
lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'
active_support/concurrency/share_lock.rb:51:in `start_exclusive'
active_support/concurrency/share_lock.rb:113:in `exclusive'
active_support/dependencies/interlock.rb:12:in `loading'
active_support/dependencies.rb:37:in `load_interlock'
active_support/dependencies.rb:369:in `require_or_load'
active_support/dependencies.rb:529:in `load_missing_constant'
active_support/dependencies.rb:212:in `const_missing'
active_support/dependencies.rb:561:in `load_missing_constant'
active_support/dependencies.rb:212:in `const_missing'
app/controllers/users_controller.rb:9:in `index'
##########################################################################################

I’ve trimmed the output a bit to make it easier to read, but you can now see what each thread is doing, and it’s clear which two threads are deadlocking (it’s the last two).

I want to know when a method is executed, but only at a certain time

Sometimes I want to know when a method is executed, but I want to do it after a certain time. For example, I want to know when start_exclusive is called, but after the application boots up. In these cases, I’ll mix global variables along with the trap trick I showed earlier.

First I modify start_exclusive to look like this:

def start_exclusive(purpose: nil, compatible: [], no_wait: false)
  if $foo
    puts "#" * 90
    puts caller
    puts "#" * 90
  end
  # ..
end

Then I write an x.rb file like this:

trap(:INFO) {
  puts "turning on debugging!"
  $foo = true
}

Then I boot the app server, and once everything has warmed up, I hit Ctrl-T and now my global variable is set to true and I start seeing logging messages.

END

This is everything I can think of right now. You should also check out Richard’s post on puts debugging. Have a good day. The End.

read more »

Inline caching in MRI

Inline Caching

Every time you call a method, Ruby must look up the method you want to call before actually calling that method. Trying to figure out what method needs to be called can be a costly operation. So one thing that virtual machine authors try to do is to speed up that process by caching the method lookup. MRI (and most other Ruby virtual machines) store this cache “inline”. Most of us know what a cache is, but what is “inline”?

What is an “inline cache”?

Inline caches are just caches that are stored “inline” with the bytecode generated from your Ruby program. If we write a simple program and disassemble it, we can see the inline caches.

Try out this program:

def foo bar, baz
  bar.baz
  baz.baz
end

ins = RubyVM::InstructionSequence.of method(:foo)
puts ins.disasm

If you run the above program, you’ll get output that looks very similar to this:

$ ruby x.rb 
== disasm: #<ISeq:foo@x.rb>=============================================
local table (size: 3, argc: 2 [opts: 0, rest: -1, post: 0, block: -1, kw: -1@-1, kwrest: -1])
[ 3] bar<Arg>   [ 2] baz<Arg>   
0000 trace            8                                               (   1)
0002 trace            1                                               (   2)
0004 getlocal_OP__WC__0 3
0006 opt_send_without_block <callinfo!mid:baz, argc:0, ARGS_SIMPLE>, <callcache>
0009 pop              
0010 trace            1                                               (   3)
0012 getlocal_OP__WC__0 2
0014 opt_send_without_block <callinfo!mid:baz, argc:0, ARGS_SIMPLE>, <callcache>
0017 trace            16                                              (   4)
0019 leave                                                            (   3)

On lines 0006 and 0014, you’ll see three values. The first value opt_send_without_block is the virtual machine instruction, and the next two values are the parameters to the instruction. The first parameter is the method you want to call along with some information about the method parameters. The second parameter <callcache> is an instance of a “call cache” and it is stored inline with the bytecode (hence “inline cache”).

What is the cache key and value?

This bit differs from VM to VM, but in MRI, there are two keys to the cache. The two keys are the “global method state” and a “class serial number”. The value of the cache is the method we’re going to call.

Global Method State

The “global method state” is a global serial number that increments every time certain classes get mutated (for example with monkey patching). You can see the current value of the global method state with RubyVM.stat. Here is an example to demonstrate changing the global state:

p RubyVM.stat

module Kernel
  def aaron
  end
end

p RubyVM.stat

If you run the above code, you’ll see output like this:

{:global_method_state=>132, :global_constant_state=>824, :class_serial=>5664}
{:global_method_state=>133, :global_constant_state=>824, :class_serial=>5664}

Adding a method to Kernel caused the global method state number to change. Changing this value at runtime is very bad because it invalidates all of the call caches (remember the call cache key is the “class serial number” and the “global method state”).

Class Serial Number

The other cache key is called the “class serial number”. This number is derived from the class (also any singleton classes associated with the object) of the instance which is the recipient of the method call at a particular call site. Each class in Ruby has a serial number associated with that class. We can see the class serial number change by looking at RubyVM.stat again:

p RubyVM.stat

class A
end

p RubyVM.stat

class B
end

p RubyVM.stat

If you run the above program, it will look something like this:

{:global_method_state=>132, :global_constant_state=>824, :class_serial=>5664}
{:global_method_state=>132, :global_constant_state=>825, :class_serial=>5666}
{:global_method_state=>132, :global_constant_state=>826, :class_serial=>5668}

You’ll notice that the class serial number is increasing. Each class gets assigned a serial number. Now, doing certain things to the class will increase the serial number. For example, if we reopen the class, the serial number will change:

p RubyVM.stat

class A
  def foo; end
end

p RubyVM.stat

class A
  def bar; end
end

p RubyVM.stat

Output:

{:global_method_state=>132, :global_constant_state=>824, :class_serial=>5664}
{:global_method_state=>132, :global_constant_state=>825, :class_serial=>5667}
{:global_method_state=>132, :global_constant_state=>825, :class_serial=>5668}

We can’t inspect the serial number associated with each class, but inspecting the output of RubyVM.stat does show the side effects of reopening the class on the serial numbers. The lesson from this is don’t reopen classes at runtime because this will invalidate caches that use that class as a key.

Recap

Lets have a short recap. Given this code:

class A
  def baz; end
end

def foo bar
  bar.baz
end

foo(A.new)

There will be one call cache at the bar.baz line, the key for that cache will be the “global method state” (just some global value) and the class serial number for A. The value of the cache will be the location of the method baz for that class.

Types of call sites and caches

So far, we’ve talk about where the inline caches are, as well as the key and value for the cache. But we haven’t talked about the size of the cache, or different types of caches. The size of the cache in MRI is one. Yes, one. It caches exactly one key and one value. This is called a “monomorphic” cache. Lets take the following example:

class A
  def baz; end
end

def foo bar
  bar.baz
end

foo(A.new)
foo(A.new)

The first time foo is called, MRI compares the cache entry’s global method state with the current global method state, and the serial number for the A class with the caches serial number. You can see the code for that here. Since there is no entry in the cache at this point, it is a cache miss, so Ruby goes through the slow path and looks up the method and caches it. You can see the cache value being stored here. The second time the method is called in this example, it’s a hit and we don’t have to do the slow path.

Now consider the following code:

class A
  def baz; end
end

class B
  def baz; end
end

def foo bar
  bar.baz
end

loop do
  foo(A.new)
  foo(B.new)
end

The above example will never hit the cache because the type for bar changes every time foo is called. Remember that part of the cache key is the class serial number. Since the serial number for A is different than the serial number for B, the cache at the bar.baz call site is never hit. We can call this call site “polymorphic” because it has multiple types for the variable bar.

Lets do one more example:

def foo bar
  bar.baz
end

loop do
  klass = Class.new {
    def baz
    end
  }
  foo(klass.new)
end

This example never hits the cache either because every instance of the class has it’s own serial number. Also, in the previous example, the bar.baz call site only ever saw two types, A and B. This case sees an infinite number of types. We can call this case “megamorphic”. I consider this case to be “too hot to handle”.

Recap

So, we essentially have 3 types of call sites: “monomorphic” is a call site that only sees one type, “polymorpic” sees many types, and “megamorphic” that sees too many types. Megamorphic call sites are also polymorphic, but they just see so many types that we don’t want to deal with them.

Ruby’s inline cache only caches one value, and is most effective when the call site is monomorphic. However, Ruby’s cache always stores the last value seen. This means that if a call site is polymorphic, but doesn’t switch types very frequently, then the cost of method lookup when switching types will be amortized.

Inspecting cache hits / misses

I’ve posted a fork of Ruby that you can find here that has a patch to let you see cache hits and misses. It adds a tracepoint for tracking those inline cache hits and misses. Don’t use this in production as it slows down your interpreter, but it is fun for testing.

Lets take our first example, and trace the cache hit and misses:

class A
  def baz; end
end

def foo bar
  bar.baz
end

tp = TracePoint.new(:inline_cache_hit, :inline_cache_miss) do |x|
  p x => x.callcache_id
end

tp.enable
foo(A.new)
foo(A.new)

If you run with my fork, you’ll see this output:

{#<TracePoint:inline_cache_miss@x.rb:14>=>[3386, 5666, "Class"]}
{#<TracePoint:inline_cache_miss@x.rb:14>=>[3387, 4052, "Object"]}
{#<TracePoint:inline_cache_miss@x.rb:6>=>[3380, 5667, "A"]}
{#<TracePoint:inline_cache_miss@x.rb:15>=>[3388, 5666, "Class"]}
{#<TracePoint:inline_cache_miss@x.rb:15>=>[3389, 4052, "Object"]}
{#<TracePoint:inline_cache_hit@x.rb:6>=>[3380, 5667, "A"]}

The left side of the hash is the tracepoint type, and the right side is an array containing a unique ID for that call site, the serial number of the class, and the class name itself. You can see the very last line is a cache hit for A (as we expected).

Lets try with the second example:

class A
  def baz; end
end

class B
  def baz; end
end

def foo bar
  bar.baz
end

tp = TracePoint.new(:inline_cache_hit, :inline_cache_miss) do |x|
  p x => x.callcache_id
end

tp.enable
2.times do
  foo(A.new)
  foo(B.new)
end

The output looks like this:

{#<TracePoint:inline_cache_miss@x.rb:18>=>[3391, 4869, "Fixnum"]}
{#<TracePoint:inline_cache_miss@x.rb:19>=>[3384, 5666, "Class"]}
{#<TracePoint:inline_cache_miss@x.rb:19>=>[3385, 4052, "Object"]}
{#<TracePoint:inline_cache_miss@x.rb:10>=>[3381, 5667, "A"]}
{#<TracePoint:inline_cache_miss@x.rb:20>=>[3386, 5669, "Class"]}
{#<TracePoint:inline_cache_miss@x.rb:20>=>[3387, 4052, "Object"]}
{#<TracePoint:inline_cache_miss@x.rb:10>=>[3381, 5670, "B"]}
{#<TracePoint:inline_cache_hit@x.rb:19>=>[3384, 5666, "Class"]}
{#<TracePoint:inline_cache_hit@x.rb:19>=>[3385, 4052, "Object"]}
{#<TracePoint:inline_cache_miss@x.rb:10>=>[3381, 5667, "A"]}
{#<TracePoint:inline_cache_hit@x.rb:20>=>[3386, 5669, "Class"]}
{#<TracePoint:inline_cache_hit@x.rb:20>=>[3387, 4052, "Object"]}
{#<TracePoint:inline_cache_miss@x.rb:10>=>[3381, 5670, "B"]}

You’ll see some cache hits in here, but none of them are inside the foo method.

END

I’m getting tired of writing this post. For those that want a sneak peek at what I’ll write about next, you can find a patch I wrote to give MRI a polymorphic inline cache here. The TL;DR for that post will be “yes the PIC works, no it doesn’t speed up our app”.

read more »

Predicting Test Failures

Running tests is the worst. Seriously. It takes forever, and by the time they’re all done running, I forgot what I was doing. Some apps take 20 to 30 min to run all the tests, and I just can’t wait that long. What bothers me even more than waiting so long, is that after I make a change to the code, 99% of the tests aren’t even running the code that I changed! Why am I spending time running code that is unrelated to the change I made?

On the Rails team, we keep talking about ways to generally make Rails app test suites faster by introducing things like parallel testing. But what if we could predict which tests are likely to fail after we’ve changed the code? If we run just those tests, then we could send a pull request and let Travis run the thousands of unrelated tests in the whole suite.

An excellent way to cut your test time in half is to only run half the tests!

Regression Test Selection

Picking the tests that may fail depending on the code you’ve changed is called Regression Test Selection. Today we’re going to build a regression test selector for Minitest and RSpec. The goal of this program is to answer the question:

If I modify line A of file B, what tests should I run?

In order to build this, we need to:

  • Collect code coverage info on a per test basis
  • Figure out what code has changed
  • Map changed code back to existing tests

Lets start with collecting per test coverage.

Collecting per-test coverage

At a high level, in order to collect per-test coverage, what we’ll do is:

  1. Record a snapshot of the current coverage info
  2. Run the test
  3. Record a snapshot of the current coverage info

In order to do this, you’ll need to be running trunk Ruby which has this patch. Our code will look somewhat like this:

require 'coverage'

Coverage.start # start the coverage tool

before = Coverage.peek_result # grab the current coverage
somehow_run_the_test
after = Coverage.peek_result # grab the current coverage

save_the_test_info_with_coverage(before, after)

For each test framework we need to figure out how to wrap each test case with the code to collect coverage information, and record that coverage information along with enough information to rerun just that one test.

First we’ll implement this using Minitest, then implement with RSpec.

Here is our code for Minitest:

require 'coverage'
require 'json'

Coverage.start

require 'minitest'

class Minitest::Runnable
  LOGS = []

  Minitest.after_run {
    File.open('run_log.json', 'w') { |f| f.write JSON.dump LOGS }
  }

  class << self
    alias :old_run_one_method :run_one_method

    def run_one_method klass, method_name, reporter
      before = Coverage.peek_result
      old_run_one_method klass, method_name, reporter
      after = Coverage.peek_result
      LOGS << [ klass.name, method_name.to_s, before, after ]
    end
  end
end

To integrate in Minitest, we need to monkey patch it. I couldn’t figure out a better way to do this than by adding a monkey patch. Anyway, the run_one_method method is the method that will run one test case. We alias off Minitest’s implementation, then add our own. Our implementation grabs the current coverage info, then calls the old implementation which runs the test, then grabs coverage info again. Once we have coverage info and test info, we add that in to the LOGS array. When Minitest is done running, it will execute the block we provided to after_run, where we write out the test and coverage information.

Now the RSpec version:

require 'coverage'
require 'json'
require 'rspec'

LOGS = []
Coverage.start

RSpec.configuration.after(:suite) {
  File.open('run_log.json', 'w') { |f| f.write JSON.dump LOGS }
}

RSpec.configuration.around(:example) do |example|
  before = Coverage.peek_result
  example.call
  after = Coverage.peek_result
  LOGS << [ example.full_description, before, after ]
end

There’s really not much difference between the two. The main changes in the RSpec version are that I don’t have to monkey patch anything, and we record example.full_description rather than the class and method name.

Now that we’ve got this code, we can run the whole suite and collect coverage information that is split by test. We can figure out what code each test executes. Next we need to figure out what code changed.

What code changed?

This example is only going to work with git repositories. To figure out what code changed, we’ll be using the rugged gem. The rugged gem wraps up libgit2 and gives you access to information about git repositories. With it, we can figure out what files and lines were modified.

To keep these examples short, we’ll take a very naive approach and just say that we’re only interested in lines that have been added or deleted. If the lines were added or deleted, we want to run that same line.

require 'rugged'
require 'set'

repo = Rugged::Repository.new '.'
lines_to_run = Set.new

repo.index.diff.each_patch { |patch|
  file = patch.delta.old_file[:path]

  patch.each_hunk { |hunk|
    hunk.each_line { |line|
      case line.line_origin
      when :addition
        lines_to_run << [file, line.new_lineno]
      when :deletion
        lines_to_run << [file, line.old_lineno]
      when :context
        # do nothing
      end
    }
  }
}

This code opens the git repository, gets a diff from the index, and iterates over each patch. For each patch, it looks at each hunk, and each line of the hunk. If the line was an addition or deletion, we store the file name and line number of the change.

So if the output of git diff looks like this:

diff --git a/lib/my_thing.rb b/lib/my_thing.rb
index 806deff..eb057b9 100644
--- a/lib/my_thing.rb
+++ b/lib/my_thing.rb
@@ -4,7 +4,7 @@ class Whatever
   end
 
   def bar
-    "bar #{@foo}"
+    raise
   end
 
   def baz

The lines_to_run set will contain one array like this:

#<Set: {["lib/my_thing.rb", 7]}>

Now that we have the lines to execute, lets map those back to tests.

Mapping back to tests

For each test, we recorded two pieces of coverage information. We recorded the coverage before the test ran, then we recorded the coverage after the test ran. We need to compute the difference between the two in order to figure out what lines the test ran.

The following function computes the difference:

def diff before, after
  after.each_with_object({}) do |(file_name,line_cov), res|
    before_line_cov = before[file_name]

    # skip arrays that are exactly the same
    next if before_line_cov == line_cov

    # subtract the old coverage from the new coverage
    cov = line_cov.zip(before_line_cov).map do |line_after, line_before|
      if line_after
        line_after - line_before
      else
        line_after
      end
    end

    # add the "diffed" coverage to the hash
    res[file_name] = cov
  end
end

Coverage information is returned from the coverage tool as a hash, where the keys are file names, and the value is an array where each index of the array represents one line in the source. The value at that index represents how many times that line has been run.

The above function iterates through the before and after hashes, subtracting the “before” coverage from the “after” coverage and produces a hash where the keys are file names and the value is the coverage information just for that test.

Now that we can compute per-test coverage information, we need to map the code changes back to test methods. The modified file and line numbers are the key. We need to be able to look up tests by file name and line number.

cov_map = Hash.new { |h, file|
  h[file] = Hash.new { |i, line|
    i[line] = []
  }
}

File.open('run_log.json') do |f|
  # Read in the coverage info
  JSON.parse(f.read).each do |desc, before, after|

    # calculate the per test coverage
    delta = diff before, after

    delta.each_pair do |file, lines|
      file_map = cov_map[file]

      lines.each_with_index do |val, i|
        # skip lines that weren't executed
        next unless val && val > 0

        # add the test name to the map. Multiple tests can execute the same
        # line, so we need to use an array.  Arrays are 0 indexed, but `rugged`
        # gives line numbers starting at 1, so we need to add one to `i`.
        file_map[i + 1] << desc
      end
    end
  end
end

The above snippet reads in the coverage JSON, calculates the coverage for each test, then inserts the test in to cov_map, where the file name and line number are the key, and the value is a list of tests. More than one test can run any particular line of source, so we need to keep a list of tests for each file name and line number.

Now we need to combine the information from Rugged, and the information from our coverage map to produce a list of tests to run:

lines_to_run.each do |file, line|
  cov_map[File.expand_path(file)][line].each do |desc|
    puts desc
  end
end

lines_to_run came from Rugged, and of course cov_map came from our coverage information. All this snippet does is iterate over the lines of code that have changed, and looks up tests that will execute that particular line, then prints it out.

I guess this is pretty anti-climactic, but now you are able to predict which tests will fail given a change to your codebase.

All of this code is available here. If you won’t actually want to type stuff, you can see a video of me predicting which tests will fail here.

Conclusion

I think that failure prediction and regression test selection can be a great tool for people like me that work on legacy code bases. Obviously, the value of a tool like this diminishes as your tests get faster, but if you have to work with slow tests, then I think this is a good way to save time.

Also, please take this idea. Please please please take this idea. I want this tool to exist as a gem, but I don’t have time to maintain it. So if you want to take this idea and package it up, then please do it!

Other ideas

Now that we can collect coverage information incrementally, I was thinking it would be nice if we made a Rack handler that recorded the coverage information on a per-request basis. Then we could do interesting things like cross reference code execution in the real world with what our tests actually execute.

I hope you enjoyed this article. Please have a good day!!

read more »

Weird stuff with hashes

Ok, so this isn’t really weird stuff, I don’t think. But maybe people don’t know about it so I thought I would post.

Hashes dup string keys

When you assign a string key to a hash, the hash copies the string and freezes it. Here is an example:

>> x = 'string'
=> "string"
>> y = {}
=> {}
>> y[x] = :value
=> :value
>> { x => y.keys.first }
=> {"string"=>"string"}
>> { x.object_id => y.keys.first.object_id }
=> {70157126548460=>70157126526760} # object ids are different
>> { x.frozen? => y.keys.first.frozen? }
=> {false=>true} # frozen value is different

You can prevent the string from being duped by freezing the string before putting it in the hash:

>> x = 'string'
=> "string"
>> x.freeze
=> "string"
>> y = {}
=> {}
>> y[x] = :value
=> :value
>> { x.object_id => y.keys.first.object_id }
=> {70157126414020=>70157126414020} # note that both object ids are the same

Why is this important?

I’ve been working with @eileencodes to improve the performance of integration tests in Rails. It turns out that the tests are spending a significant amount of time in the garbage collector. We started tracking down allocations, and found that setting values in the header hash was creating many strings.

To partially fix this, we added a freeze to the string before inserting it in to the header hash. This cut the allocations down. The code used to allocate one string for the “downcased” version, then another when the downcased version was inserted in to the hash.

Setting strings as hash keys may be a source of unnecessary object allocation in your application. Now, don’t go freezing all the strings. Make sure to measure where object allocations are happening in your app first (a subject that I’ll cover in a later blog post), then freeze strings where appropriate.

Why does the Hash dup strings?

I think there are a few reasons.

One, if you mutate the string after adding it to the hash, it would be surprising (to me anyway) if the key for the hash was mutated too. For example:

>> x = 'string'
=> "string"
>> y = {}
=> {}
>> y[x] = :value
=> :value
>> x.sub!(/r/, '')
=> "sting"
>> y.key? x
=> false
>> { y.keys => x }
=> {["string"]=>"sting"}

I think it would be pretty surprising if, after mutating the object in place, it would still be part of the hash.

I think the other more technical reason is that mutating the string changes the hash value of the string, and means your hash would need to be rehashed in order to find the same key:

>> x.hash
=> 4078764570319932244
>> x.sub!(/r/, '')
=> "sting"
>> x.hash
=> -1518905602476999392

Note that the hash value changed.

Hash value, what does that have to do with anything?

If you change the hash value of a hash key, then the key will be in the wrong place in the hash. I think this might be more clear with a code example.

You may know about the two methods you need to implement for creating a custom hash key: hash indicates where in the hash the object will be stored, and eql? is used in the case there is a hash collision.

Lets make an object that allows us to mutate the hash value, and see how it behaves after inserting it in a hash:

class Foo
  attr_accessor :hash
end

x = Foo.new
x.hash = 10

hash = {}
hash[x] = :hello

p hash.key?(x)          # => true
p hash.keys.include?(x) # => true

x.hash = 11 # change the hash value

p hash.key?(x)          # => false
p hash.keys.include?(x) # => true

hash.rehash

p hash.key?(x)          # => true
p hash.keys.include?(x) # => true

First we see that x is a key to the hash, and is in the list of keys. After we mutate the hash value, Hash#key? returns false, yet Array#include? returns true when we check for the object in the list of keys.

The reason Hash#key? returns false is because it’s using the value of hash to find the object in the hash buckets. When we first inserted the object in the hash, it went in to the “10” bucket. But now that we’ve changed the value to “11”, the hash will look for the object in the “11” bucket, which is the wrong place!

To fix this, we call the rehash method on the hash. The rehash method will redistribute the keys. Since the object in the “10” bucket is now supposed to be in the “11” bucket, it will move the object to the right place, and Hash#key? will work correctly.

Wouldn’t it be annoying if you had to do the same song and dance as this if you mutated your strings? I think this is the main reason why hashes dup and freeze string keys.

What is the lesson?

Don’t mutate the hash value on hash keys! You’ll have a bad time.

Anyway, I don’t think this is weird or anything, it’s just something that we don’t have to deal with on a day to day basis. Maybe I should have titled the post “Uncommon things to do with hashes”.

Thanks for reading!!! <3<3<3<3<3

Performance P.S. (is that a P.P.S.?)

An interesting thing is that Hash#dup will rehash the newly created hash, where Hash[] will not:

class Foo
  attr_accessor :hash
end

x = Foo.new
x.hash = 10

hash = {}
hash[x] = :hello

p hash.key?(x)          # => true

x.hash = 11 # change the hash value

p hash.key?(x)          # => false
p hash.dup.key?(x)      # => true
p Hash[hash].key?(x)    # => false

This means that duping a hash with Hash[] can end up being faster than using Hash#dup. Here is a benchmark to demonstrate:

require 'benchmark/ips'

hash = Hash[*('a'..'z').to_a]
Benchmark.ips do |x|
  x.report("Hash#dup") do
    hash.dup
  end

  x.report("Hash[]") do
    Hash[hash]
  end
end

Results on my machine:

Calculating -------------------------------------
            Hash#dup     7.705k i/100ms
              Hash[]    15.978k i/100ms
-------------------------------------------------
            Hash#dup     93.648k (± 4.9%) i/s -    470.005k
              Hash[]    230.497k (±11.2%) i/s -      1.150M

Does this mean that you should switch to Hash[]? Only if your benchmarks can prove that it’s a bottleneck. Please please please don’t change all of your code because this shows it’s faster. Make sure to measure your app performance first. But you already knew that, which is why you’re reading the PS section. ;-)

read more »

My experience with Minitest and RSpec

I’ve been using RSpec in earnest for the past 6 months now, so I thought it’s time to write a blurrrgh poast comparing RSpec with Minitest. I’ve used Minitest for years, and RSpec only for 6 months, so please keep that in mind when reading!

PLEASE REMEMBER, I don’t care what test framework you use, as long as you are testing your code. This is a post just about my experience with these two frameworks. In other words, this is an opinion piece.

INTRO!!!

I really believe that all test frameworks are essentially the same. No test framework can do something that’s impossible for another to do. It’s just code. So what differentiates test frameworks? I would say the main difference would be user interface. So I’m really going to compare user interfaces between these frameworks.

Things I like about RSpec.

By far and away, my favorite thing about RSpec is that if there is a failure, it prints how to run just that one test at the bottom of the output. I can easily copy and paste that line and run just the one test. For people who don’t know, here is an example:

describe "something" do
  it "works" do
    expect(10).to equal(11)
  end

  it "really works" do
    expect(11).to equal(11)
  end
end

When you run this, the output looks like this:

[aaron@TC tlm.com (master)]$ rspec code/fail_spec.rb 
F.

Failures:

  1) something works
     Failure/Error: expect(10).to eq(11)
       
       expected: 11
            got: 10
       
       (compared using ==)
     # ./code/fail_spec.rb:3:in `block (2 levels) in <top (required)>'

Finished in 0.00504 seconds (files took 0.20501 seconds to load)
2 examples, 1 failure

Failed examples:

rspec ./code/fail_spec.rb:2 # something works
[aaron@TC tlm.com (master)]$ 

All you have to do to rerun just the one failing spec is to copy and paste that one line like this:

rerun demo

I don’t have to think or type, I just “copy, paste, run”. I like to think of this as a “learn as you play” feature.

The other thing I like about RSpec is that it ships with a colored output formatter, so if you do rspec --color, you’ll get colored output. I’ve used Minitest for years without colored output, but I’ve come to really like the colored output from RSpec. It helps me quickly see the most important parts of the test output, the assertion failure, and stack traces (though I highly suspect that the RSpec core team all use black backgrounds in their terminals because sometimes the colors aren’t so nice on my white terminal).

Things I like about Minitest

The main thing that I like about Minitest is that a Minitest test is just a Ruby class. Here is an example test similar to the RSpec sample I showed earlier:

require 'minitest/autorun'

class Something < Minitest::Test
  def test_works
    assert_equal 11, 10
  end

  def test_really_works
    assert_equal 11, 11
  end
end

I like this because I know exactly where the test_works method is defined. It’s no different than any other class in Ruby, so I don’t have to learn anything new. I like it because I am a heavy user of CTags, so I can easily jump to test methods or classes inside my editor. Another thing that’s nice about using regular Ruby classes is that when I need to refactor my tests, I just use my normal refactoring skills: I extract methods, classes, modules, change to inheritance, etc. I use the same refactoring techniques on my test files as I do on my library files. I think that is where Minitest really shines.

Things I dislike about RSpec

RSpec is a DSL for writing tests. I think this is probably RSpec’s largest weakness. I am a programmer, I can read code, so I don’t particularly care whether or not my test code “reads like English”. I don’t understand the value of the DSL, especially when I have a nearly 4000 line specfile that I’d like to refactor. How do I go about refactoring? I can extract methods:

describe "something" do
  def helper
    11
  end

  it "works" do
    expect(10).to eq(helper)
  end

  it "really works" do
    expect(11).to eq(helper)
  end
end

But where is the helper method defined? What’s its visibility? Can I put it in a module? Can I use inheritance? Who can call it? Can I call super from the extracted method? If so, where does super go? These are not the types of questions I want to be pondering when I have 3000 test failures and really long spec files to read through. My mind spins off in to thoughts like “I wonder how RSpec works?”, and “I wonder what my cat is doing?”

From what I can gather, calling describe in RSpec essentially defines a class. But if that’s the case, why not just use Ruby classes? Then I don’t need to guess about method visibility, modules, inheritance, etc. Not to mention, the library code that I’m working with is just using Ruby classes. Why do I need to switch to some other language for testing?

Nesting a describe seems to perform inheritance, but only for certain things like before blocks. If you run this code:

describe "something" do
  before do
    puts "hi!"
  end

  it "works" do
    expect(10).to eq(helper)
  end

  it "really works" do
    expect(11).to eq(helper)
  end

  context "another thing" do
    before do
      puts "hello!"
    end

    it "really really works" do
      expect(11).to eq(helper)
    end
  end

  def helper
    11
  end
end

You’ll see “hi!” printed 3 times, once for each it, and “hello!” printed once. For the nested context, I would like to print “hello!” before it prints “hi!”. In a normal inheritance situation, I would change the call to super. I am not sure how to do what I just described without learning a new thing (I think I would need let but I don’t know). For now, I’m coping with this by refactoring to classes outside of the specs themselves, then calling the objects from the specs. Essentially “composition” in my tests.

Another thing that bugs me is that if I do try to refactor my RSpec tests, and I change any lines, then the line that I copy and pasted to run just the one test won’t work anymore. I have to figure out the new line. I can use the name of the test by specifying the -e flag on RSpec, but then I lose the “copy, paste, run” feature that I love so much.

Anyway, I will stop picking on RSpec now. To me, RSpec seems to have some sort of identity crisis and is caught somewhere between “a language for writing tests” and “just Ruby”. That is RSpec’s biggest weakness.

Things I dislike about Minitest

If RSpec does one thing better than Minitest, I would say that the command line UI easily outshines Minitest. Here is one example.

I can run one test at a time like so:

$ ruby code/fail_test.rb -n Something#test_works

This will run the test_works method on the Something class. The problem for me is that it’s not clear to do that when you see the failing test output. If we run the whole suite, the output looks like this:

[aaron@TC tlm.com (master)]$ ruby code/fail_test.rb 
Run options: --seed 5990

# Running:

.F

Finished in 0.002047s, 977.0396 runs/s, 977.0396 assertions/s.

  1) Failure:
Something#test_works [code/fail_test.rb:5]:
Expected: 11
  Actual: 10

2 runs, 2 assertions, 1 failures, 0 errors, 0 skips
[aaron@TC tlm.com (master)]$

Looking at this, how would you know how to run just that one test? With RSpec, it’s no problem. I was able to learn how to run just one test the first time I ever used RSpec. I didn’t read any docs, just ran the tests, and the info was right there. Coming from RSpec, you might need to think you could do this:

$ ruby code/fail_test.rb:5

But of course that doesn’t work because you’re just using Ruby on the command line.

Here is a short video of me running the single test:

demo

The disadvantages of this over RSpec’s output is I have to type a few characters and know a commandline interface in advance. You might think “it’s just a few characters”, but every time I have to type something is a potential for a mistake that I’ll have to correct, which takes even more time. I really think the advantages of “copy, paste, run” can’t be understated. (Yes, I know there are tools like autotest for both Minitest and RSpec that will run tests for you, but sometimes I can’t / don’t use them)

The other thing I wish Minitest would do is to ship with a color formatter like RSpec does. I am used to the color output from RSpec, and I don’t really want to go back. It really helps me focus on what’s important about my test failures.

Conclusion

Both of these frameworks have things I like and dislike. Being able to reuse my debugging and refactoring skills in my tests is pretty important to me, especially since I deal with lots of legacy code. This is why I’ll stick with Minitest in my personal projects. However, I am sure I will get better at refactoring and debugging in RSpec tests, and when I get better at it, I will share what I learn.

Now, do I care which one you use? No. As long as you test your code, I am happy. A professional developer should be able to work in either one of these because they essentially do the same thing: test your code.

read more »

YAGNI methods slow us down

TL;DR: OutputBuffer subclasses SafeBuffer which forces us to do runtime checks that are probably unnecessary

I made a post about YAGNI methods hurting you where I said I would provide two examples, but then I got tired of writing the article so I just did one example. Here is the other example! The previous example demonstrated a memory leak that was introduced because the “footprint” (the number of methods implemented on the object) was too large.

This example will show how these YAGNI methods are impacting performance of your Rails application, and we’ll talk about how to fix it.

This problem is in ActionView::OutputBuffer which inherits from ActiveSupport::SafeBuffer, which inherits from Ruby’s String. Let’s talk about the behavior ActiveSupport::SafeBuffer first, then we’ll see how it impacts to the performance of ActionView::OutputBuffer.

ActiveSupport::SafeBuffer

This class is the class that’s used to mark a string as being “html safe”. It’s how Rails detects whether a string has been html escaped or not. In Rails, a normal Ruby string is considered to be not “html safe”. For example:

>> x = "foo"
=> "foo"
>> x.class
=> String
>> x.html_safe?
=> false

If we call html_safe on the string, it returns an instance of ActiveSupport::SafeBuffer that is “tagged” as html safe:

>> x = "foo"
=> "foo"
>> y = x.html_safe
=> "foo"
>> y.class
=> ActiveSupport::SafeBuffer
>> y.html_safe?
=> true

Whenever we html escape a string in Rails, it returns a safe buffer:

>> x = "<html>"
=> "<html>"
>> x.html_safe?
=> false
>> y = ERB::Util.html_escape x
=> "&lt;html&gt;"
>> y.class
=> ActiveSupport::SafeBuffer
>> y.html_safe?
=> true

Now, using the html_safe? predicate, we can easily tell the difference between strings that have been tagged as “html safe” and strings that haven’t been tagged as “html safe” (side note: just like encodings, tagging something does not mean that it actually is correct. We can tag things as “html safe” without them actually being html safe).

We can also concatenate unsafe strings to a safe string, and it will be automatically escaped:

>> x = ERB::Util.html_escape "<html>"
=> "&lt;html&gt;"
>> x.concat "<blink>"
=> "&lt;html&gt;&lt;blink&gt;"
>> x.html_safe?
=> true

Finally, we can concatenate safe strings and they will not be double escaped:

>> x = ERB::Util.html_escape "<html>"
=> "&lt;html&gt;"
>> x.concat ERB::Util.html_escape "<blink>"
=> "&lt;html&gt;&lt;blink&gt;"
>> x.html_safe?
=> true

Infecting a SafeBuffer

So far, the html_safe? predicate is a 1:1 relationship with the class. Meaning that if the class of the string is ActiveSupport::SafeBuffer, then html_safe? would return true, and if the class was String, html_safe? would return false.

Unfortunately it is not a 1:1 relationship. We can mutate a SafeBuffer, making it unsafe again. For example:

>> x = ERB::Util.html_escape "<html>"
=> "&lt;html&gt;"
>> dangerous = "&gt;<script>"
=> "&gt;<script>"
>> x.gsub!(/&gt;/, dangerous)
=> "&lt;html&gt;<script>"
>> x
=> "&lt;html&gt;<script>"
>> x.class
=> ActiveSupport::SafeBuffer
>> x.html_safe?
=> false

You can see that the string in dangerous has been embedded in to the SafeBuffer without being escaped. The class of x is still SafeBuffer, but calling html_safe? will return false. As you can see, the return value of html_safe? is not a 1:1 relationship with the class.

Concatenating to an infected SafeBuffer

Our infected SafeBuffer still supports concatenation:

>> x
=> "&lt;html&gt;<script>"
>> x.class
=> ActiveSupport::SafeBuffer
>> x.html_safe?
=> false
>> x.concat "<blink>"
=> "&lt;html&gt;<script><blink>"

But you can see that the “<blink>” string was not escaped. This means that the concat behavior on a SafeBuffer changes depending on the value of html_safe?. If you look at the implementation of concat, along with it’s helper method, you can indeed see that this is true.

What is OutputBuffer?

OutputBuffer is a buffer that is fed to Rack and then output to the client over the wire. Templates instantiate an OutputBuffer and concatenate computed output to the buffer.

Impact of SafeBuffer on OutputBuffer

How does SafeBuffer impact OutputBuffer? Let’s take a look at a compiled ERB template to find out. Here is an ERB template after it’s been compiled to Ruby:

@output_buffer = output_buffer || ActionView::OutputBuffer.new
@output_buffer.safe_append='      <tr>
        <td>'.freeze
@output_buffer.append=( book.name )

The output isn’t pretty, but you can see that we essentially call two methods on the output buffer: append=, and safe_append= (why we have an = is a mystery for the ages). append= is used when there are dynamic values like <%= link_to ... %>, and safe_append= is used for string literals in your template.

Let’s look at the implementation of safe_append=:

def safe_concat(value)
  return self if value.nil?
  super(value.to_s)
end
alias :safe_append= :safe_concat

First, notice that value is never nil. The ERB compiler ensures that fact, so the value.nil? check is useless. However, this blurrrggghhh post is about how YAGNI methods are hurting us. We do need to concatenate, so you are gonna need this.

OutputBuffer is a subclass of SafeBuffer, and safe_concat supers in to SafeBuffer. Let’s look at the implementation of safe_concat on SafeBuffer:

def safe_concat(value)
  raise SafeConcatError unless html_safe?
  original_concat(value)
end

safe_concat raises an exception if the current object is not html_safe?. Every time our ERB template concatenates a string, it checks whether or not the current object is “html safe”.

As we saw earlier, the only way to make an instance of a SafeBuffer not html safe is by calling an unsafe method on that instance.

YAGNI method pain

Every time we concatenate to an OutputBuffer object, we’re forced to check a flag. This flag is directly related to people calling gsub! on the OutputBuffer. This bothers me because, as you can imagine, we concatenate on to the OutputBuffer extremely frequently.

I’m betting that it’s extremely rare for someone to call gsub! on an OutputBuffer. I’m also willing to bet that people calling gsub! on an OutputBuffer would be willing to call to_s on it before doing their mutation, so why do we “support” this?

Our OutputBuffer is punishing most people for a feature that is extremely rare. This is thanks to the features we got “for free” from our superclass.

Secondly, if you look in the same file that defines OutputBuffer, you’ll see a class called StreamingBuffer. This class is meant to be a replacement for OutputBuffer, but it streams to the client. Notice that this class does not inherit from SafeBuffer. Further evidence that gsub! on OutputBuffer is a YAGNI method.

How do we fix this?

I think we can fix this by disconnecting OutputBuffer from it’s superclass. I suspect that the methods people actually use on OutputBuffer are extremely few. I’d also say that this class should be completely private. In other words, we (the Rails team) should design our API such that people never actually touch instances of the OutputBuffer.

If we disconnect OutputBuffer from it’s superclass, I think we can even do some tricks with the ERB compiler to attain faster output.

read more »

YAGNI methods are killing me

TL;DR: Inheriting from Hash will bite you. ¯\_(ツ)_/¯

This is Yet Another Post about preferring composition over inheritance, but I will try to drive it home with Real World Examples™. I’m not saying “don’t use inheritance”, I am saying “use inheritance conservatively, and when it is appropriate” (I know it’s not very controversial). I think I can confidently say “don’t inherit from String, Hash, or Array in Ruby”, and in this post we’ll look at two concrete examples about why you shouldn’t inherit from those classes.

YAGNI methods

YAGNI methods are baggage that your subclasses are carrying around. They’re methods that you may never use, but you have to deal with them because your parent class implemented them. The thing about these methods is that when you sit at your keyboard, innocently pecking out the characters class Parameters < Hash, you don’t realize that these YAGNI methods are there waiting in the shadows getting ready to ruin your day.

Let’s look at a couple examples of how these YAGNI methods make our lives harder.

Memory Leaks

I showed this off during my Keynote at RailsConf, but we’ll dive in a little more here. As of e2a97adb, this code leaks memory:

require 'action_controller'

params = ActionController::Parameters.new({
  foo:[Object.new]
})

loop do
  params[:foo]
  params.delete :foo
  params[:foo] = [Object.new]
end

If you run this code, you’ll see that the process’s memory grows unbounded.

ActionController::Parameters is used for the parameters hash in your controller. When you do params[:id], params returns an instance of ActionController::Parameters. This class inherits from ActiveSupport::HashWithIndifferentAccess, which in turn inherits from Ruby’s Hash.

Why does this leak?

There are two methods involved in our leak. One method is the delete method, and ActionController::Parameters does not implement that method. The other method is the [] method, so let’s look there.

If you read the implementation of the square brace method, you’ll see it calls convert_hashes_to_parameters, which calls convert_value_to_parameters.

Here is the convert_value_to_parameters method:

def convert_value_to_parameters(value)
  if value.is_a?(Array) && !converted_arrays.member?(value)
    converted = value.map { |_| convert_value_to_parameters(_) }
    converted_arrays << converted
    converted
  elsif value.is_a?(Parameters) || !value.is_a?(Hash)
    value
  else
    self.class.new(value)
  end
end

This method seems to do some sort of conversions on Array, and appends the conversion to the converted_arrays object. Each time we iterate through the loop, we delete a key, but that value is never deleted from the converted_arrays object. Each time we access the Array value, it gets “converted”, and that converted array is added to the converted_arrays object. So, the converted_arrays object grows unbounded.

Why do we need to convert stuff? Why do we need to mutate a thing? This method leaves me with more questions than I have time to deal with here, but presumably the function is necessary.

How do we fix it?

Well, we need to implement the delete method. Whenever the delete method is called, we need to remove any “converted arrays” from the converted_arrays list.

This solution may work for the delete method, but what about the delete_if method? What about the merge! method? How about keep_if? How about reject!? How about select!? The list goes on, and soon we feel like we’re playing whack-a-mole with method implementations.

Rather than “How do we fix it?” I think a better question is “Do we need it?”. For these mutation methods, I think the answer is “no”. The author of convert_value_to_parameters probably didn’t think about these mutation methods, and I’m willing to bet that very few people actually mutate their own params object. I’ll also bet that of the people who do mutate their params object, 100% of those people would be OK with calling to_hash on params before making mutations.

Ok! Lets remove the method!

Whoa! Not so fast there, friend. We can’t just remove the method. We need to add deprecation warnings so that we don’t break applications when people upgrade. That means we need to add a warning on merge!, and keep_if, and delete_if, and select!, and reject!, etc.

Feels like we’re playing method whack-a-mole again, doesn’t it?

These methods are what I think of as YAGNI methods. Methods that we probably don’t need, but we got them for “free” through inheritance. Remember that even in life, inheriting something isn’t always a good thing.

So how do we really fix it?

¯\_(ツ)_/¯

We should probably switch this to use composition, but it will be a breaking change so it must wait until Rails 5.

The End

I said I was going to write about two issues with YAGNI methods, but I don’t really want to right now. I will write more later. However, the next installment will be about ActionView::OutputBuffer which is (eventually) a subclass of String. We will talk about how the YAGNI methods on OutputBuffer are hurting performance of your Rails application.

Remember: stay conservative with your API. It’s easier to add a new method than it is to take one away.

read more »

Webcam photos with Ruby

Let’s do something fun! In this post we’ll take a photo using your webcam in Ruby.

NOTE: This only works on OS X

I haven’t tried making it work on other operating systems. Not that I don’t like other operating systems, I just haven’t made it work. :-)

Installing the Gem

We’ll use the av_capture gem. It wraps the AVCapture framework on OS X. To install it, just do:

$ gem install av_capture

Using the Gem

I’ll paste the code here first, then explain it:

require 'av_capture'

# Create a recording session
session = AVCapture::Session.new

# Find the first video capable device
dev = AVCapture.devices.find(&:video?)

# Output the camera's name
$stderr.puts dev.name

# Connect the camera to the recording session
session.run_with(dev) do |connection|

  # Capture an image and write it to $stdout
  $stdout.write connection.capture
end

First the program creates a new capture session. OS X can capture from many multimedia devices, and we hook them together through a session. Next, it grabs the first device attached to the machine that has video capability. If your machine has multiple cameras, you may want to adjust this code. After it outputs the name of the camera, we tell the session to start and use that device.

The camera can only be used while the session is open, inside the block provided to run_with. Inside the block, we ask the connection to capture an image, then write the image to $stdout.

Running the code

I’ve saved the program in a file called thing.rb. If you run the program like this:

$ ruby thing.rb | open -f -a /Applications/Preview.app

it should open Preview.app with an image captured from the camera.

Taking Photos Interactively

Let’s make this program a little more interactive:

require 'av_capture'
require 'io/console'

session = AVCapture::Session.new
dev = AVCapture.devices.find(&:video?)

session.run_with(dev) do |connection|
  loop do
    case $stdin.getch
    when 'q' then break # quit when you hit 'q'
    else
      IO.popen("open -g -f -a /Applications/Preview.app", 'w') do |f|
        f.write connection.capture
      end
    end
  end
end

This program will just sit there until you press a button. Press ‘q’ to quit, any other button to take a photo and display it in Preview.app. Requiring io/console lets us read one character from $stdin as soon as possible, and the call to IO.popen lets us write the data to Preview.app.

A Photo Server using DRb

It takes a little time for the camera to turn on before the program can take a photo. This causes a little lag time when we want to take a photo. In the spirit of over-engineering things, lets create a photo server using DRb. The server will keep the camera on and ready to take photos. The client will ask the server for photos.

Server code

Here is our server code:

require 'av_capture'
require 'drb'

class PhotoServer
  attr_reader :photo_request, :photo_response

  def initialize
    @photo_request  = Queue.new
    @photo_response = Queue.new
    @mutex          = Mutex.new
  end

  def take_photo
    @mutex.synchronize do
      photo_request << "x"
      photo_response.pop
    end
  end
end

server = PhotoServer.new

Thread.new do
  session = AVCapture::Session.new
  dev = AVCapture.devices.find(&:video?)

  session.run_with(dev) do |connection|
    while server.photo_request.pop
      server.photo_response.push connection.capture
    end
  end
end

URI = "druby://localhost:8787"
DRb.start_service URI, server
DRb.thread.join

The PhotoServer object has a request queue and a response queue. When a client asks to take a photo by calling the take_photo method, it writes a request to the queue, then waits for a photo to be pushed on to the response queue.

The AVCapture session’s run block waits for a request to appear on the photo_request queue. When it gets a request on the queue, it takes a photo and writes the photo to the response queue.

At the bottom of the file, we connect the PhotoServer object to DRb on port 8787, and join the DRb server thread.

Client Code

Here is our client code:

require 'drb'

SERVER_URI = "druby://localhost:8787"

photoserver = DRbObject.new_with_uri SERVER_URI
print photoserver.take_photo

The client code connects to the DRb server on port 8787, requests a photo, then writes the photo to $stdout.

Running the code

In one terminal, run the server code like this:

$ ruby server.rb

Then in another terminal, run the client code like this:

$ ruby client.rb | open -f -a /Applications/Preview.app

You should have a photo show up in Preview.app. You can kill the server program by doing Ctrl-C.

Speed comparison

Just for fun, let’s compare the speed of the first program to the speed of the client program just using time. Here is the first program:

$ time ruby thing.rb > /dev/null
FaceTime HD Camera (Built-in)

real	0m3.217s
user	0m0.151s
sys	0m0.069s

Here is the client program:

$ time ruby client.rb > /dev/null

real	0m0.183s
user	0m0.070s
sys	0m0.038s

The first program takes about 3 seconds to take a photo where the second “client” program only takes 200ms or so. The reason the second program is much faster is because the server keeps the camera “hot”. Most of our time is spent getting the camera ready rather than taking photos.

Weird photos

Here are some weird photos that I made while I was writing this:

one two three

Happy Wednesday! <3<3<3<3

read more »

AdequateRecord Pro™: Like ActiveRecord, but more adequate

TL;DR: AdequateRecord is a set of patches that adds cache stuff to make ActiveRecord 2x faster

I’ve been working on speeding up Active Record, and I’d like to share what I’ve been working on! First, here is a graph:

transformations

This graph shows the number of times you can call Model.find(id) and Model.find_by_name(name) per second on each stable branch of Rails. Since it is “iterations per second”, a higher value is better. I tried running this benchmark with Rails 1.15.6, but it doesn’t work on Ruby 2.1.

Here is the benchmark code I used:

require 'active_support'
require 'active_record'

p ActiveRecord::VERSION::STRING

ActiveRecord::Base.establish_connection adapter: 'sqlite3', database: ':memory:'
ActiveRecord::Base.connection.instance_eval do
  create_table(:people) { |t| t.string :name }
end

class Person < ActiveRecord::Base; end

person = Person.create! name: 'Aaron'

id   = person.id
name = person.name

Benchmark.ips do |x|
  x.report('find')         { Person.find id }
  x.report('find_by_name') { Person.find_by_name name }
end

Now let’s talk about how I made these performance improvements.

What is AdequateRecord Pro™?

AdequateRecord Pro™ is a fork of ActiveRecord with some performance enhancements. In this post, I want to talk about how we achieved high performance in this branch. I hope you find these speed improvements to be “adequate”.

Group discounts for AdequateRecord Pro™ are available depending on the number of seats you wish to purchase.

How Does ActiveRecord Work?

ActiveRecord constructs SQL queries after doing a few transformations. Here’s an overview of the transformations:

transformations

The first transformation comes from your application code. When you do something like this in your application:

Post.where(...).where(...).order(..)

Active Record creates an instance of an ActiveRecord::Relation that contains the information that you passed to where, or order, or whatever you called. As soon as you call a method that turns this Relation instance in to an array, Active Record does a transformation on the relation objects. It turns the relation objects in to ARel objects which represent the SQL query AST. Finally, it converts the AST to an actually SQL string and passes that string to the database.

These same transformations happen when you run something like Post.find(id), or Post.find_by_name(name).

Separating Static Data

Let’s consider this statement:

Post.find(params[:id])

In previous versions of Rails, when this code was executed, if you watched your log files, you would see something like this go by:

SELECT * FROM posts WHERE id = 10
SELECT * FROM posts WHERE id = 12
SELECT * FROM posts WHERE id = 22
SELECT * FROM posts WHERE id = 33

In later versions of Rails, you would see log messages that looked something like this:

SELECT * FROM posts WHERE id = ? [id, 10]
SELECT * FROM posts WHERE id = ? [id, 12]
SELECT * FROM posts WHERE id = ? [id, 22]
SELECT * FROM posts WHERE id = ? [id, 33]

This is because we started separating the dynamic parts of the SQL statement from the static parts of the SQL statement. In the first log file, the SQL statement changed on every call. In the second log file, you see the SQL statement never changes.

Now, the problem is that even though the SQL statement never changes, Active Record still performs all the translations we discussed above. In order to gain speed, what do we do when a known input always produces the same output? Cache the computation.

Keeping the static data separated from the dynamic data allows AdequateRecord to cache the static data computations. What’s even more cool is that even databases that don’t support prepared statements will see an improvement.

Supported Forms

Not every call can benefit from this caching. Right now the only forms that are supported look like this:

Post.find(id)
Post.find_by_name(name)
Post.find_by(name: name)

This is because calculating a cache key for these calls is extremely easy. We know these statements don’t do any joins, have any “OR” clauses, etc. Both of these statements indicate the table to query, the columns to select, and the where clauses right in the Ruby code.

This isn’t to say that queries like this:

Post.where(...).where(...).etc

can’t benefit from the same techniques. In those cases we just need to be smarter about calculating our cache keys. Also, this type of query will never be able to match speeds with the find_by_XXX form because the find_by_XXX form can completely skip creating the ActiveRecord::Relation objects. The “finder” form is able to skip the translation process completely.

Using the “chained where” form will always create the relation objects, and we would have to calculate our cache key from those. In the “chained where” form, we could possibly skip the “relation -> AST” and “AST -> SQL statement” translations, but you still have to pay the price of allocating ActiveRecord::Relation objects.

When can I use this?

You can try the code now by using the adequaterecord branch on GitHub. I think we will merge this code to the master branch after Rails 4.1 has been released.

What’s next?

Before merging this to master, I’d like to do this:

  1. The current incarnation of AdequateRecord needs to be refactored a bit. I have finished the “red” and “green” phases, and now it’s time for the “refactor” step.
  2. The cache should probably be an LRU. Right now, it just caches all of the things, when we should probably be smarter about cache expiry. The cache should be bounded by number of tables and combination of columns, but that may get too large.

After merging to master I’d like to start exploring how we can integrate this cache to the “chained where” form.

On A Personal Note

Feel free to quit reading now. :-)

The truth is, I’ve been yak shaving on this performance improvement for years. I knew it was possible in theory, but the code was too complex. Finally I’ve payed off enough technical debt to the point that I was able to make this improvement a reality. Working on this code was at times extremely depressing. Paying technical debt is really not fun, but at least it is very challenging. Some time I will blurrrgh about it, but not today!

Thanks to work (AT&T) for giving me the time to do this. I think we can make the next release of Rails (the release after 4.1) the fastest version ever.

EDIT: I forgot to add that newer Post.find_by(name: name) syntax is supported, so I put it in the examples.

read more »

Me And Facebook Open Academy

TL;DR: I am working with many students to improve Rails and it is fun!

WARNING: This is a non-technical blog post. I usually like to write about tech stuff, but I think this is pertinent so I’m going to write about it!

What is the Open Academy?

Facebook Open Academy is basically a program that gives Computer Science students at different universities the opportunity to work with various projects in the Open Source community. I think there are about 20 Open Source projects involved, and Rails is one of them. This year there are about 250 students participating, and the Rails team has 22 students. This is the second year that the Open Academy has been running, and I participated last year too.

How I got involved

I was contacted by Jay Borenstein who is a professor at Stanford and also works for Facebook. He told me that the idea of the program is that there are many CS students learning theory, but maybe not learning the skills they need to work on older code bases, with remote teams, or with Open Source code bases, and that he wanted to provide students with the opportunity to work closely with people in the Open Source community so that they could get these skills.

This struck a chord with me because I had to learn this stuff on my own, and I would have loved to have this kind of opportunity. For payment, I asked Jay to give me an Honorary Degree from Stanford. He has not gotten back to me on that.

Our Team

I’m not sure how many schools are involved total, but our team of 22 students is from 8 different schools: Sichuan University, University of Helsinki, Cornell University, Harvard, Princeton, University of Waterloo, UC Berkeley, and University of Washington.

I am extremely honored to work with these students, but I have to admit that as a college dropout it is extremely intimidating. The students we’re working with are very bright and have lots of potential. It’s inspiring to work with them, and I am slightly jealous because they are much better than I was at their age. I think this is a good thing because it means that the next generation of programmers will be even better than my generation.

Last year I was the only mentor. This year I was able to trick convince @_matthewd, @pixeltrix, and @bitsweat to help out as mentors.

Our Timeline

We started a couple weeks ago. But this weekend Facebook sponsored travel and lodging for all students, faculty, and mentors, to go to Palo Alto for a hackathon. So this weekend I was able to work with our team in person.

The timeline for this program is rather challenging because each school has a different schedule, so we will be working with all students for a different length of time.

Our Work

For the first few weeks we will have the students work on bug fixes in Rails. This will help us to assess their skill levels so that we can give them longer term projects that are a good fit. Fixing bugs has turned out to be a challenge because most “easy” bugs in Rails have been fixed, so most of the bugs left in the tracker are particularly challenging. I haven’t figured out a solution to this problem yet, but we are managing (I think). So if you find easy bugs in Rails, don’t fix them, but tell my students to fix them. ;-)

Anyway, after a couple weeks we will give them larger projects to work on (and I’ll describe those in a later post).

Improvements for the Rails team

Getting the students up and running with a dev environment was a huge challenge. Some students tried the Rails dev box, but running a VM on their hardware was just too slow, so we ended up with all of the students developing on their native hardware. Of course this was also a pain because some students had issues like having Fink, MacPorts, and homebrew all installed at the same time. For the Agile Web Development with Rails book, Sam Ruby has tests that start with a completely blank Ubuntu VM, and go all the way through getting a Rails app up and running. I think we need to do something like that, but for doing dev work against Rails.

One extremely frustrating example of why we need tests for setting up the dev environment is that in the guides it says that you should execute bundle install --without db. This is fine, except that when you do that, the --without db option is written to .bundle/config and persists between runs of bundler. We (the mentors) didn’t know the students had done that, and were ripping our hair out for an hour or so trying to figure out why ActiveRecord couldn’t find the adapter gems, or why running bundle install wouldn’t install the database gems. I find this to be an extremely frustrating behavior of bundler.

These are some things that I think we can improve.

Improvements for Universities

All of our students can program. Maybe not in Ruby, but they know some other language. They have to pick up Ruby, but I don’t think that’s a big deal. A larger problem is that not all of them knew about git, or about VCS in general. Jay tried to help with this problem by inviting @chacon to give a talk on git. I think this helped, but I really think that git should be part of normal CS curriculum. It’s very difficult for me to imagine writing any amount of code without some kind of VCS. What if you mess up? What if your computer dies? How do you remember what the code used to be? Not using a VCS seems like a huge waste of time. Some of the students were already familiar with git, but some weren’t. I am unclear about the role VCS plays among Universities, but I strongly believe it should be taught in all CS programs.

Maybe I can get people at GitHub in contact with people at different Universities?

Departing thoughts

It blows my mind that we have students from such prestigious Universities, and that these Universities are forward thinking enough to participate in this program. I am extremely honored to work with them. I also have to say thank you to Facebook for sponsoring this work even though Rails has basically nothing to do with Facebook. I also have to say thanks to my work (AT&T) for allowing me to have the job that I do, and also giving me some time to work with these students.

All of our students are part of the Friends of Rails organization on GitHub so you can watch some of our progress there. I will try to make more blurrrrgggghhh posts as we progress.

Post Script

Since I am a College dropout, I have an extreme case of Impostor Syndrome. Working with such prestigious schools made me extremely nervous. Last year I went to dinner with some of the faculty members of University of Helsinki. After a few beers, I was able to muster my courage and said “Before we start this program, I have to admit something. I never graduated college.” Their response: “So?”

<3<3<3<3

read more »