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
2 Comments
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.
Thanks for posting, incredibly useful. You rock for fixing this!