ActiveRecord timestamp Conversions Fail — Sometimes

We recently started to see some timestamp-based tests fail seemingly at random. At first, the usual suspects in the form of time-dependencies were dragged in for a serious round of questioning, but to our surprise none of them were involved.

The bad guy, it turns out, was the microsecond handling in ActiveRecord::ConnectionAdapters::Column#fast_string_to_time and ActiveRecord::ConnectionAdapters::Column#microseconds. It simply fails for some values causing our tests which generated, saved, reloaded and compared timestamps to fail — sometimes.

In slightly more than 1% of all possible 6-digit cases, writing a timestamp to a database column and then reading it back in will result in a different value being returned to the program.

So, for instance, saving the timestamp

2010-01-12 12:34:56.125014

and then loading it again from the database yields

2010-01-12 12:34:56.125013

Here’s a simple test that works directly with the conversion functions to illustrate the problem:

   converted = ActiveRecord::ConnectionAdapters::Column.send(
      'fast_string_to_time', "2010-01-12 12:34:56.125014"
   )
 
   assert_equal 125014, converted.usec

This test case (and a similar one for #microseconds) fail on plain vanilla Rails 2.3.5.
The problem occurs when the value read is converted from string form to a Ruby timestamp, so it is largely database independent (the exception being drivers that override the methods, or databases that don’t support timestamps at all).

UPDATE I should point out, however, that the problem only manifests itself if the sub-second part of the timestamp is stored with 4 or more significant digits in the database. Otherwise the rounding error simply isn’t large enough to affect the conversion. In practical terms, this means that you will see it on PostgreSQL, but not on SQLite, MySQL, or SQLServer.

The conversion code lives in active_record/connection_adapters/abstract/schema_definitions.rb and looks like this:

   def microseconds(time)
      ((time[:sec_fraction].to_f % 1) * 1_000_000).to_i
   end

and

   def fast_string_to_time(string)
      if string =~ Format::ISO_DATETIME
         microsec = ($7.to_f * 1_000_000).to_i
         new_time $1.to_i, $2.to_i, $3.to_i, $4.to_i, $5.to_i, $6.to_i, microsec
       end
   end

The underlying problem is the use of to_i to convert from floats to ints inside the affected methods. As you know, to_i simply truncates the result and in some cases this causes rounding errors introduced by inherent inaccuracies in the multiplication operations and decimal representation to bubble up and affect the least significant digit.

I guess the best solution would be to change the ISO_DATETIME regex used to extract the microsecond-part from timestamps to not include the decimal point at all and then avoid the to_f and subsequent floating point multiplication completely inside the failing methods. However, these regexes are defined as constants on ActiveRecord::ConnectionAdapters::Column::Format and therefore publicly available, so the impact of changing these is difficult to ascertain.

A simpler solution is to use round() instead of to_i to convert from the intermediate floating point result to int. This works (I have verified that the precision is sufficient for all possible 6-digit cases) but is about 15% slower than the current method. A small price to pay for correctness, in my opinion.

I have reported my findings (along with a patch) to the rails core team and created a matching Lighthouse ticket.

In the meantime, you can easily apply the fix by placing the following code in a file in config/initializers:

module ActiveRecord
  module ConnectionAdapters #:nodoc:
    class Column
      class << self
        protected
          def microseconds(time)
            ((time[:sec_fraction].to_f % 1) * 1_000_000).round
          end
 
          def fast_string_to_time(string)
            if string =~ Format::ISO_DATETIME
              microsec = ($7.to_f * 1_000_000).round
              new_time $1.to_i, $2.to_i, $3.to_i, $4.to_i, $5.to_i, $6.to_i, microsec
            end
          end
      end
    end
  end
end
Share and Enjoy:
  • Digg
  • del.icio.us
  • Facebook
  • Slashdot
This entry was posted in Rails and tagged , , , , . Bookmark the permalink. Post a comment or leave a trackback: Trackback URL.

2 Comments

  1. Winfield
    Posted December 11, 2010 at 19:46 | Permalink

    Thanks for discovering this bug and patching it! I’ve seen erroneous unit test fails in our Rails automated build for years occur once or twice a week and never figured out why. In researching it I found your Patch for Rails. Hell of a job debugging this, writing it up, and patching Rails.

    Keep up the good work.

  2. Rich Thornett
    Posted February 2, 2011 at 16:24 | Permalink

    Thanks for posting, incredibly useful. You rock for fixing this!

Post a Comment

Your email is never published nor shared. Required fields are marked *

*
*