时间戳截断：Ruby on Rails ActiveRecord 故事

测试应该有助于防止应用程序变得不稳定。 但有时，测试本身可能会变得不稳定——即使是最直接的测试。 以下是我们如何对 PostgreSQL 支持的 Ruby on Rails 应用程序进行有问题的测试，以及我们发现了什么。

我们想检查某些业务逻辑（由方法perform调用）不会改变calendar模型（ Calendar的实例，Ruby on Rails ActiveRecord 模型类），所以我们写了：

 let(:calendar) { create(:calendar) } specify do expect do perform # call the business action calendar.reload end .not_to change(calendar, :attributes) end

这在一个开发环境 (MacOS) 中传递，但在 CI (Linux) 中几乎总是失败。

幸运的是，我们设法在另一个开发环境 (Linux) 上重现了它，但它失败并显示一条消息：

 expected `Calendar#attributes` not to have changed, but did change from {"calendar_auth_id"=>8, "created_at"=>2020-01-02 13:36:22.459149334 +0000, "enabled"=>false, "events_...t_sync_token"=>nil, "title"=>nil, "updated_at"=>2020-01-02 13:36:22.459149334 +0000, "user_id"=>100} to { "calendar_auth_id"=>8, "created_at"=>2020-01-02 13:36:22.459149000 +0000, "enabled"=>false, "events_...t_sync_token"=>nil, "title"=>nil, "updated_at"=>2020-01-02 13:36:22.459149000 +0000, "user_id"=>100}

看到什么可疑的东西了吗？

调查

经过仔细检查，我们注意到created_at和updated_at时间戳在expect块内略有变化：

 {"created_at"=>2020-01-02 13:36:22.459149334 +0000, "updated_at"=>2020-01-02 13:36:22.459149334 +0000} {"created_at"=>2020-01-02 13:36:22.459149000 +0000, "updated_at"=>2020-01-02 13:36:22.459149000 +0000}

秒的小数部分被截断，因此13:36:22.459149334变为13:36:22.459149000 。

我们确信perform没有更新calendar对象，因此我们假设时间戳被数据库截断。 为了测试这一点，我们使用了已知的最先进的调试技术，即 puts 调试：

 let(:calendar) { create(:calendar) } specify do expect do puts "before perform: #{calendar.created_at.to_f}" perform puts "after perform: #{calendar.created_at.to_f}" calendar.reload puts "after reload: #{calendar.created_at.to_f}" end .not_to change(calendar, :attributes) end

但截断在输出中不可见：

 before perform: 1577983568.550754 after perform: 1577983568.550754 after reload: 1577983568.550754

这非常令人惊讶——访问器#created_at应该具有与attributes['created_at']的属性哈希值相同的值。 为了确保我们打印的值与断言中使用的值相同，我们更改了访问created_at的方式。

我们没有使用访问器calendar.created_at.to_f ，而是直接从属性哈希中获取它： calendar.attributes['created_at'].to_f 。 我们对calendar.reload的怀疑得到了证实！

 before perform: 1577985089.0547702 after perform: 1577985089.0547702 after reload: 1577985089.05477

如您所见，调用perform并没有改变created_at ，但reload改变了。

为了确保更改不会发生在另一个calendar实例上然后被保存，我们又进行了一次实验。 我们在测试前重新加载了calendar ：

 let(:calendar) { create(:calendar).reload } specify do expect do perform calendar.reload end .not_to change(calendar, :attributes) end

这使测试变绿了。

修复

知道是数据库截断了我们的时间戳并导致我们的测试失败，我们决定防止截断发生。 我们生成了一个DateTime对象并将其四舍五入到整秒。 然后，我们使用这个对象显式地设置 Rails 的 Active Record 时间戳。 此更改修复并稳定了测试：

 let(:time) { 1.day.ago.round } let(:calendar) { create(:calendar, created_at: time, updated_at: time) } specify do expect do perform calendar.reload end .not_to change(calendar, :attributes) end

原因

为什么会这样？ Active Record 时间戳由 Rails 的ActiveRecord::Timestamp模块使用Time.now 。 Time精度取决于操作系统，并且如文档所述，可能包括小数秒。

我们使用计算小数部分长度频率的脚本在 MacOS 和 Linux 上测试Time.now分辨率：

 pry> 10000.times.map { Time.now.to_f.to_s.match(/\.(\d+)/)[1].size }.group_by{|a| a}.map{|k, v| [k, v.count]}.to_h # MacOS => {6=>6581, 7=>2682, 5=>662, 4=>67, 3=>7, 2=>1} # Linux => {6=>2399, 7=>7300, 5=>266, 4=>32, 3=>3}

如您所见，Linux 上大约 70% 的时间戳在小数点后具有七位精度，而在 MacOS 上只有 25%。 这就是测试在 MacOS 上大部分时间通过而在 Linux 上大部分时间失败的原因。 您可能已经注意到测试输出具有九位精度——这是因为 RSpec 使用Time#nsec来格式化时间输出。

当 Rails 模型被保存到数据库时，它们所拥有的任何时间戳都使用 PostgreSQL 中的一种称为timestamp without time zone的类型进行存储，该类型具有微秒级分辨率——即小数点后六位。 因此，当1577987974.6472975被发送到 PostgreSQL 时，它会截断小数部分的最后一位，而是保存1577987974.647297 。

问题

仍然存在一个问题，为什么在我们调用calendar.reload时calendar.created_at没有重新加载，即使calendar.attributes['created_at']已重新加载。

此外， Time精度测试的结果有点令人惊讶。 我们期望在 MacOS 上，最大精度为 6。 我们不知道为什么它有时有七位数。 更让我们吃惊的是最后一位数字的值的分布：

 pry> 10000.times.map { Time.now}.map{|t| t.to_f.to_s.match(/\.(\d+)/)[1] }.select{|s| s.size == 7}.group_by{|e| e[-1]}.map{|k, v| [k, v.size]}.to_h # MacOS => {"9"=>536, "1"=>555, "2"=>778, "8"=>807} # Linux => {"5"=>981, "1"=>311, "3"=>1039, "9"=>309, "8"=>989, "6"=>1031, "2"=>979, "7"=>966, "4"=>978}

如您所见，MacOS 上的第七位数字始终是 1、2、8 或 9。

如果您知道其中任何一个问题的答案，请与我们分享解释。

未来

Ruby on Rails 的 Active Record 时间戳是在应用程序端生成的，当这些时间戳用于对保存到数据库的事件进行可靠和精确的排序时，也可能会受到伤害。 由于应用程序服务器时钟可能不同步，由created_at排序的事件可能会以与实际发生的顺序不同的顺序出现。 为了获得更可靠的行为，最好让数据库服务器处理时间戳（例如，PostgreSQL 的now() ）。

然而，这是一个值得另一篇文章的故事。

特别感谢 Gabriele Renzi 帮助撰写本文。