การตัดทอนเวลา: A Ruby on Rails ActiveRecord Tale

การทดสอบควรช่วยให้แอปไม่หลุดลอก แต่บางครั้ง การทดสอบตัวเองอาจกลายเป็นสะเก็ด—แม้แต่การทดสอบที่ตรงไปตรงมาที่สุด ต่อไปนี้คือวิธีที่เราทดสอบแอป Ruby on Rails ที่มีปัญหาซึ่งสนับสนุนโดย PostgreSQL และสิ่งที่เราค้นพบ

เราต้องการตรวจสอบว่าตรรกะทางธุรกิจบางอย่าง (เรียกโดยวิธีการ 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 เราจึงตั้งสมมติฐานว่าฐานข้อมูลกำลังตัดการประทับเวลา เพื่อทดสอบสิ่งนี้ เราใช้เทคนิคการดีบักขั้นสูงสุดที่รู้จัก กล่าวคือ ทำการดีบั๊ก:

 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

แทนที่จะใช้ accessor 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

นั่นทำให้การทดสอบเป็นสีเขียว

The Fix

เนื่องจากทราบว่าเป็นฐานข้อมูลที่ตัดการประทับเวลาของเราและไม่ผ่านการทดสอบ เราจึงตัดสินใจป้องกันไม่ให้เกิดการตัดทอน เราสร้างวัตถุ DateTime และปัดเศษเป็นวินาทีทั้งหมด จากนั้น เราใช้วัตถุนี้เพื่อตั้งค่าการประทับเวลา Active Record ของ 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 ถูกกำหนดโดยโมดูล ActiveRecord::Timestamp ของ Rails โดยใช้ Time.now ความแม่นยำของ Time ขึ้นอยู่กับระบบปฏิบัติการ และตามสถานะของเอกสาร อาจรวมเศษเสี้ยววินาที

เราทดสอบความละเอียด Time.now บน MacOS และ Linux ด้วยสคริปต์ที่นับความถี่ของความยาวเศษส่วน:

 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}

อย่างที่คุณเห็น ประมาณ 70% ของการประทับเวลาบน Linux มีความแม่นยำเจ็ดหลักหลังจุดทศนิยม ในขณะที่บน MacOS มีเพียง 25% เท่านั้น นี่คือเหตุผลที่การทดสอบผ่านเกือบตลอดเวลาบน MacOS และล้มเหลวเกือบตลอดเวลาบน Linux คุณอาจสังเกตเห็นว่าผลการทดสอบมีความแม่นยำเก้าหลัก นั่นเป็นเพราะ RSpec ใช้ Time#nsec เพื่อจัดรูปแบบเอาต์พุตเวลา

เมื่อโมเดล Rails ถูกบันทึกลงในฐานข้อมูล การประทับเวลาใดๆ ก็ตามที่มีจะถูกจัดเก็บโดยใช้ประเภทใน PostgreSQL ที่เรียกว่า timestamp without time zone ซึ่งมีความละเอียดระดับไมโครวินาที นั่นคือ ตัวเลขหลังทศนิยมหกหลัก ดังนั้นเมื่อส่ง 1577987974.6472975 ไปยัง PostgreSQL มันจะตัดทอนหลักสุดท้ายของส่วนที่เป็นเศษส่วนและจะบันทึก 1577987974.647297 แทน

คำถาม

ยังมีคำถามว่าเหตุใด calendar.created_at จึงไม่โหลดซ้ำเมื่อเราเรียก calendar.reload แม้ว่า calendar.attributes['created_at'] จะถูกโหลดซ้ำ

นอกจากนี้ ผลการทดสอบความแม่นยำของ Time ยังค่อนข้างน่าประหลาดใจอีกด้วย เราคาดหวังว่าใน MacOS ความแม่นยำสูงสุดคือหก เราไม่รู้ว่าทำไม บางครั้ง จึงมีเจ็ดหลัก สิ่งที่ทำให้เราประหลาดใจมากกว่านั้นคือการกระจายมูลค่าของหลักสุดท้าย:

 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 เสมอ

หากคุณทราบคำตอบของคำถามเหล่านี้ โปรดแบ่งปันคำอธิบายกับเรา

อนาคต

ความจริงที่ว่าการประทับเวลา Active Record ของ Ruby on Rails นั้นถูกสร้างขึ้นในฝั่งแอปพลิเคชันอาจส่งผลเสียเช่นกันเมื่อการประทับเวลาเหล่านั้นถูกใช้เพื่อการจัดลำดับเหตุการณ์ที่บันทึกไว้ในฐานข้อมูลที่เชื่อถือได้และแม่นยำ เนื่องจากนาฬิกาเซิร์ฟเวอร์ของแอปพลิเคชันอาจถูกยกเลิกการซิงโครไนซ์ เหตุการณ์ที่เรียงลำดับโดย created_at อาจปรากฏขึ้นในลำดับที่ต่างไปจากที่เกิดขึ้นจริง เพื่อให้ได้พฤติกรรมที่น่าเชื่อถือมากขึ้น จะเป็นการดีกว่าถ้าให้เซิร์ฟเวอร์ฐานข้อมูลจัดการการประทับเวลา (เช่น PostgreSQL's now() )

อย่างไรก็ตามนั่นเป็นเรื่องราวที่คุ้มค่าบทความอื่น

ขอขอบคุณเป็นพิเศษกับ Gabriele Renzi ที่ช่วยในการสร้างบทความนี้