時間戳截斷：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 幫助撰寫本文。