타임스탬프 잘림: 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 22.459149000 이 되었습니다.

우리는 perform 이 calendar 개체를 업데이트하지 않는다고 확신했기 때문에 데이터베이스에 의해 타임스탬프가 잘렸다는 가설을 세웠습니다. 이를 테스트하기 위해 알려진 가장 진보된 디버깅 기술, 즉 풋 디버깅을 사용했습니다.

 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의 활성 레코드 타임스탬프를 명시적으로 설정했습니다. 이 변경 사항은 테스트를 수정하고 안정화했습니다.

 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 정밀도는 OS에 따라 다르며 문서 상태에 따라 소수 자릿수 초가 포함될 수 있습니다 .

우리는 분수 부분 길이의 빈도를 계산하는 스크립트를 사용하여 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에서 대부분의 시간에 실패한 이유입니다. RSpec이 Time#nsec 을 사용하여 시간 출력 형식을 지정하기 때문에 테스트 출력의 정밀도가 9자리라는 것을 알 수 있습니다.

Rails 모델이 데이터베이스에 저장될 때 모든 타임스탬프는 PostgreSQL의 timestamp without time zone 이라는 유형을 사용하여 저장됩니다. 이 유형은 마이크로초 단위의 분해능(즉, 소수점 이하 6자리)입니다. 따라서 1577987974.6472975 가 PostgreSQL로 전송되면 소수 부분의 마지막 숫자를 자르고 대신 1577987974.647297 을 저장합니다.

질문

calendar.attributes['created_at'] calendar.reload 호출할 때 왜 calendar.created_at 이 다시 로드되지 않았는지에 대한 질문이 여전히 있습니다.

또한 Time 정밀도 테스트의 결과는 약간 의외입니다. 우리는 MacOS에서 최대 정밀도가 6이라고 예상했습니다. 때때로 7자리 숫자가 있는 이유를 모르겠습니다. 우리를 더 놀라게 한 것은 마지막 숫자 값의 분포였습니다.

 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에게 특별한 감사를 전합니다.