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

本文概述

• 调查
• 修复
• 原因
• 问题
• 未来

测试应该有助于防止应用出现问题。但是有时, 测试本身可能会变得不稳定—甚至是最直接的测试。这是我们在PostgreSQL支持的Ruby on Rails应用上进行问题测试的方法, 以及发现的内容。

我们想要检查某些业务逻辑(由perform方法调用)不会更改日历模型(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块中, created_at和updated_at时间戳有所变化：

{"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不会更新日历对象, 因此我们形成了一个假设, 认为时间戳记会被数据库截断。为了测试这一点, 我们使用了已知的最先进的调试技术, 即调试：

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应该具有与attribute [‘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, 但重新加载了。

为了确保更改不会在另一个日历实例上发生, 然后再保存, 我们进行了另一个实验。我们在测试前重新加载了日历：

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设置的。时间精度取决于操作系统, 并且如文档所述, 时间精度可能包括小数秒。

我们在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％的时间戳精确到小数点后7位, 而在MacOS上只有25％。这就是测试在MacOS上大部分时间通过而在Linux上大多数时间未通过的原因。你可能已经注意到测试输出的精度为9位数, 这是因为RSpec使用Time＃nsec格式化时间输出。

将Rails模型保存到数据库时, 它们使用的任何时间戳都使用PostgreSQL中的一种称为timestamp(无时区)的类型存储, 该类型具有微秒的分辨率, 即小数点后六位。因此, 当1577987974.6472975发送到PostgreSQL时, 它将截断小数部分的最后一位, 而保存1577987974.647297。

问题

仍然存在一个问题, 即使我们重新加载了calendar.attributes [‘created_at’], 为什么当我们调用calendar.reload时也没有重新加载calendar.created_at。

同样, 时间精度测试的结果也令人惊讶。我们期望在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帮助撰写本文。