Archive

Archive for the ‘Testing’ Category

Strange Rails Timestamp Errors

12/11/2010 1 comment

Strange Timestamp Errors
Occasionally (once or twice a week), we see strange failures in our Rails tests, with errors like the following:

<Wed Dec 08 23:47:09 -0600 2010> expected but was
<Wed Dec 08 23:47:09 -0600 2010>.

… generated from a test like the following:


    t = 2.days.ago
    Timecop.freeze(t) do
      saved_search = Factory(:user).saved_searches.create!(:name => 'My Search', :params => {'foo' => '1'}.to_json)
    end

    Timecop.freeze(1.day.ago) do
      get :show, :id => saved_search.id
      saved_search.reload
      assert_equal t, saved_search.last_used_at, "should not be updated"
    end

Off By Less Than 1s
If you’re familiar with Ruby Time objects, you can see that the time value is different, but at a resolution well below the seconds printed in the messages used. How can this be? We’re using Timecop to freeze all of the Ruby/Rails Time interfaces at a fixed point for this test.

We’re creating a record with a known Timestamp, reloading it from the database, and seeing that Timestamp off, but just slightly (by less than a second).

Background Info: Timecop
Timecop is one of my favorite Rails plugins, it allows you to pass a block of code that executes in a different Time, by stubbing out all the Ruby/Rails Time APIs to return the time you’ve chosen. You can see it used here to “travel” in time back to 2 days ago, then 1 day ago, and execute different parts of the test. This “freezes” time and makes any real difference in Timestamps impossible. So how is the Timestamp for this record changing? And in such a strange way?

Mystery Revealed: ActiveRecord DB Time Parsing/Rounding Error
It turns out there’s a bug in Rails 2.3/3.0 in Timestamp database value parsing, causing rounding errors for some edge case values. There’s a pending patch on it’s way into Rails, but I’ve manually patched our version of Rails to prevent this in the meantime. This means that when a test runs and happens to hit one of these category of Timestamp values (based on Time.now) this will blow up, since the Timestamp written to the DB will not be the one read back (off by less than a second). A truly maddening intermittent bug.

Much respect to Jacob Lauemøller who discovered/fixed this Rails bug. Here’s hoping this patch makes it in to the next 2.3.x release.

We’ve been suffering these erroneous failures for years and never knowing why. Glad to finally knock this off the list.

Advertisements
Categories: Debugging, Rails, Testing

Rails Tests Run in 2/3 Time w/ GC Tuning

12/10/2010 Comments off

Run Your Unit Tests in 2/3 the Time
Tweaking the Ruby Enterprise Edition (REE) garbage collection (GC) parameters, I was able to run my unit tests in 2/3 the normal time. Total test time w/ Ruby 1.8.7 down from 20mins to approx 6mins on tuned REE 1.8.7.

This data was measured on the PatientsLikeMe Rails codebase, a very mature and large Rails app. The hardware is a MacBook Pro w/ Rails 2.3.5 on OSX 10.6.4. Your mileage may vary.

Background: Garbage Collection & Tuning
Ruby is a dynamic language with GC managing dynamic memory allocation. Most Ruby programmers have the benefit of ignoring the garbage collector during development, but tuning the GC parameters can have dramatic benefits in production and running your tests locally. Using REE allows the tuning of many GC parameters.

37Signals Production Settings

# NOTE: These only take effect when running Ruby Enterprise Edition

export RUBY_HEAP_MIN_SLOTS=600000
export RUBY_GC_MALLOC_LIMIT=59000000
export RUBY_HEAP_FREE_MIN=100000

Measured Performance

# Before (REE, no GC settings)
#
$> ruby -v
ruby 1.8.7 (2010-04-19 patchlevel 253) [i686-darwin10.4.0], MBARI 0x6770, Ruby Enterprise Edition 2010.02
$> rake test:units
#Snip...
Finished in 666.310269 seconds.

3883 tests, 11523 assertions, 0 failures, 0 errors, 0 pendings, 0 omissions, 0 notifications
# After (REE, w/ 37Signals GC tuning)
#
$> ruby -v
ruby 1.8.7 (2010-04-19 patchlevel 253) [i686-darwin10.4.0], MBARI 0x6770, Ruby Enterprise Edition 2010.02
$> env | grep RUBY
RUBY_HEAP_FREE_MIN=100000
RUBY_HEAP_MIN_SLOTS=600000
RUBY_GC_MALLOC_LIMIT=59000000
$> rake test:units
#Snip...
Finished in 411.319884 seconds.

3883 tests, 11523 assertions, 0 failures, 0 errors, 0 pendings, 0 omissions, 0 notifications

Why? What Do These Settings Mean?

  • RUBY_HEAP_MIN_SLOTS – Number of slots in Ruby heap, directly controls initial heap size in your VM. Should be large enough to hold entire Rails environment. This is 6x the default heap size.
  • RUBY_GC_MALLOC_LIMIT – Wait until # of malloc() calls to trigger GC, this is much longer wait than Ruby default period for less collections. The value above collects every 59mil malloc()s
  • RUBY_HEAP_FREE_MIN – Minimum free heap post-collection, if not met will allocate a whole new heap. We’ve set it here to 17% the size of the heap. Default is 25% of heap.

REE Cuts Rails Test Time in Half

12/07/2010 Comments off

Ruby Enterprise Edition (REE)
I spent the night after work switching our build/stage server to Ruby Enterprise Edition. I switched both our Hudson based builds and our Passenger staging servers.

REE is well known for it’s superior garbage collection and memory management, but I was shocked to see how much faster it executed in Ruby CPU-bound contexts. We saw about a 55% drop in runtime, taking our average build times from 55min to 30min.

Build/Test Times Cut Almost in Half
Hudson Screen Shot

Performance Drill-down

  • Unit Tests: From 1036s to 579s (to run 3880 tests)
  • Functional Tests: From 844s to 448s (to run 860 tests)
  • Cucumber Tests: From 498s to 255s (to run 1078 steps)

The nginx/REE/Passenger stack is known as the best of breed production Rails stack, but I can’t believe how much of a benefit we’ve gotten from introducing the same components into our build and staging systems.

This effort was initially a functional testing pass to verify our system performed correctly under REE, I never expected to achieve such massive performance gains on it’s own merits.

Tips/Tricks & Gotchas

  • RVM is the best way to test/incrementally introduce a new ruby interpreter
  • If you’re using bundler w/ file-system bundles (via –path) you need to completely rebuild them when you switch Ruby interpreters
  • If you have a previous Passenger Apache module installer, you need to rebuild/reinstall the REE based Apache module

Footnotes:
Original Ruby Version
ruby 1.8.7 (2009-06-12 patchlevel 174) [x86_64-linux]
REE Version
ruby 1.8.7 (2010-04-19 patchlevel 253) [x86_64-linux], MBARI 0x6770, Ruby Enterprise Edition 2010.02