Tobi Labs: June 2008

When I started at Tobi, our test cases would run in less than 5 minutes, ahhh good times, good times! I remember this emphatically since Dileep's tests would take twice as long to run on his Linux box. As more and more tests were introduced, including integration tests with our own DSL (another post) our tests started to take so long that we needed a continuous build solution (again, another post) since we could no longer run them locally. Now, I am aware that there are things we can do and have since done to speed up the tests, mainly writing better tests, however that is not the point here.

Since just the unit tests now take upwards of 45 minutes to run locally on a 2.4 GHz Intel Core 2 Duo it was extremely useless and a bit ridiculous seeing .............EEFFF....E...F.......E........F......FFFEEEEE...... and having to wait until the end of the run to see what actually happened! Tobi Test Timer will show you immediately when an error or failure occurs. It is a bit funny since this is very useful and yet a side affect of the plugin!

The plugin's main functionality is to show you slow tests. That is, tests that take longer than the threshold will be echo'd out as slow.
SLOW TEST: 69.055537 - test_should_search_for_customers_with_multiple_cancelled_orders_by_category(CustomerSearchTest) SLOW TEST: 12.595146 - test_multiple_even_exchanges(OrderProcessReturnTest) SLOW TEST: 10.899179 - test_return_and_exchange_with_store_credit_reused(OrderProcessReturnTest)
The spirit of the plugin is to display your slow tests so you can speed them up and then re-adjust the threshold, hence slowly speeding up your build.

The plugin can be found here on Github and you can use git to install it.

Lets talk about the code, it is only 38 lines and basically opens up Test::Unit::TestCase and does a few alias_method_chains. There are a few interesting pieces of code. First the fact that you MUST extend the instance of Test::Unit::TestResult. I was unable to get this to work by extending the actual class or even opening up the class. The other interesting pieces is that you do not want to define the alias method more than once.

class Test::Unit::TestCase
def run_with_test_timing(*args, &block)
result = args[0] # Test::Unit::TestResult
# extend the class to do what we want
# Note this does not work with the regular class_eval
# I was unable to successfully oepn up Test::Unit::TestResult
result.class.class_eval do
def add_error_with_log_error(error)
puts "\nERROR: #{error.test_name}"
add_error_without_log_error(error)
end
def add_failure_with_log_failure(failure)
puts "\nFAILURE: #{failure.test_name}"
add_failure_without_log_failure(failure)
end
alias_method_chain :add_error, :log_error unless method_defined?(:add_error_without_log_error)
alias_method_chain :add_failure, :log_failure unless method_defined?(:add_failure_without_log_failure)
end
#time the test
begin_time = Time.now
run_without_test_timing(*args, &block)
end_time = Time.now
duration = (end_time - begin_time)
long_test = duration > '5.0'.to_f
puts "\nSLOW TEST: #{duration} - #{self.name}" if long_test
end
# Since we require the test helper in all tests we need to check this out.
alias_method_chain :run, :test_timing unless method_defined?(:run_without_test_timing)
end

References

http://agilewebdevelopment.com/plugins/tobi_test_timer
http://github.com/gittobi/tobi_test_timer/tree/master
git://github.com/gittobi/tobi_test_timer.git

I fell in love with Ruby's OpenStruct class a few months ago after reading "Jay Fields' Thoughts" and "ERR THE BLOG" posts on OpenStruct.

I immediately liked the concept. It was right in line with how easily you can get things done in Ruby. I carefully tucked the OpenStruct nugget into the back of my head for later use. It wasn't too long until I had the opportunity to implement a solution with it. Due to issues and limitations with ActiveRecord::Base (another time, another post) Tobi needed to use a more flexible and generic architecture for reporting (again, another post). Anyway, in order to get this done quickly I pulled out the OpenStruct nugget.

We ended up with a couple of really simple classes to encapsulate our data. Now we could simply extend DataRow and decorate it with the particulars of the specific report.

# code snippet
def query
query = <<-EOS
SELECT ...
FROM ...
INNER JOIN ...
WHERE ...
GROUP BY ...
...
EOS
end
# code snippet
def run
rows = ActiveRecord::Base.connection.select_all(query)
rows.collect{|row| Backorder::Row.new(row)}
end
class DataRow < OpenStruct
def initialize(row)
# Allows us to use an anonymous ActiveRecord or a hash
attributes = case row
when Hash then row
else row.attributes
end
super(attributes)
end
end
module Backorder
class Row < DataRow
def order_number
order_id.to_i + 1000
end
def order_ids
Array.postgres_to_ruby(orders)
end
def purchase_order_ids
Array.postgres_to_ruby(purchase_orders)
end
end
# ...
end

The preceding code gave us a simple and generic way to use complex SQL to load from an arbitrary number of tables as well as temporary tables. Additionally, we did not have to pollute models with report specific logic. The testing benefits were another major plus!

This solution solved one performance problem (Rails' n+1 queries) but introduced another one. Unfortunately we didn't catch that one until production :(

The DataRow extending OpenStruct worked exceptionally well with a small working set. However, in production, when real users hit up some of the reports, the working sets became quite large and mongrels started to crash. We have excellent monitoring in place so we were able to quickly recover and the crashes where localized to the back-end enterprise Rails application so the bug was not too terrible. However, the reporting "fix" quickly became a serious issue as getting stuck behind a slow mongrel is an awful user experience. What made matters worse was the fact that the mongrel was crashing and not just taking forever. This meant we had to go in and clean up. All in all, it was a bad situation and a horrible headache.

Why were we crashing? What was going on? Didn't we take a report that would either time out or take 10 minutes due to the n+1 Rails issue down to a singular query? What could it be? Of course the issue was obvious, we were running out of memory because we were creating so many objects. Still, why were we running out of memory? The object count wasn't that high after all.

Turns out that the problem was in ostruct.rb#new_ostruct_member. Every time we instantiated a DataRow it created a new class and then defined the corresponding methods. Of course it does, how did we think OpenStruct worked! Actually, we thought it would define the methods once on the class DataRow that was extending it. Anyway, this was the issue and it was killing us!

def initialize(hash=nil)
@table = {}
if hash
for k,v in hash
@table[k.to_sym] = v
new_ostruct_member(k)
end
end
end
def new_ostruct_member(name)
name = name.to_sym
unless self.respond_to?(name)
meta = class << self; self; end
meta.send(:define_method, name) { @table[name] }
meta.send(:define_method, :"#{name}=") { |x| @table[name] = x }
end
end

We needed to quickly code ourselves out of this mess. Here comes the new version of the DataRow and Backorder::Row class.

class DataRow
def initialize(attributes)
@attributes = attributes
end
def self.define_row_attribute_methods(row_attributes)
self.class_eval do
row_attributes.each do |attribute|
attribute = attribute.to_s
define_method(attribute) do
@attributes.fetch(attribute, nil)
end
end
end
end
end
module Backorder
class Row < DataRow
define_row_attribute_methods(
[:item_id, :order_id, :order_date, :customer_name, :product_name, :brand_name,:color_name,
:size_name, :gender, :price, :backordered_quantity, :purchase_order_quantity, :received_quantity,
:outstanding_quantity, :on_order_quantity, :inventory_quantity, :orders, :purchase_orders])
def order_number
order_id.to_i + 1000
end
def order_ids
Array.postgres_to_ruby(orders)
end
def purchase_order_ids
Array.postgres_to_ruby(purchase_orders)
end
end
end

Basically we are defining the methods that we need on the class level when we first load the class. DataRow's internal data structure is a hash, so we can easily instantiate it and we still have all of the functionality that we needed from OpenStruct. Because of the loosely-coupled architecture we were able to swap out the general DataRow and specific Row classes.

Note: I still love the OpenStruct class. It is actually a beautiful class with some great Ruby code. It epitomizes why Ruby is superior to Java. I mean it uses recursion, meta-programming, aliasing, and method missing functionality! All of this in about 100 lines of easy to ready and understand code.

Second Note: I tried to keep the code in context as much as possible, this is Tobi's real code and it is test covered.

N'th Note: There is still much more we have done to DRY this up and simplify but it was not germane to how OpenStruct bit us in the ass.

References

http://www.tobi.com
http://errtheblog.com/posts/28-strut-your-structs
http://blog.jayfields.com/2006/09/ruby-stub-variations-openstruct.html
http://www.ruby-doc.org/stdlib/libdoc/ostruct/rdoc/classes/OpenStruct.html

Tobi Labs

Tobi Test Timer Ruby on Rails Plugin

OpenStruct crashed my Mongrel

Authors

Category

Archives