Merge pull request #1672 from nanoc/denis/fix-tests

Fix time/duration tests
nanoc · Nov 30, 2023 · f194079 · f194079
2 parents 7d0196e + 9c56353
commit f194079
Show file tree

Hide file tree

Showing 4 changed files with 91 additions and 61 deletions.
diff --git a/nanoc-cli/spec/nanoc/cli/compile_listeners/file_action_printer_spec.rb b/nanoc-cli/spec/nanoc/cli/compile_listeners/file_action_printer_spec.rb
@@ -14,19 +14,25 @@
     end
   end
 
-  before { Timecop.freeze(Time.local(2008, 1, 2, 14, 5, 0)) }
+  let(:original_timestamp) { Process.clock_gettime(Process::CLOCK_MONOTONIC, :nanosecond) }
+
+  def mock_time(seconds)
+    allow(Process)
+      .to receive(:clock_gettime)
+      .with(Process::CLOCK_MONOTONIC, :nanosecond)
+      .and_return(original_timestamp + seconds * 1_000_000_000)
+  end
 
   after do
-    Timecop.return
     listener.stop_safely
   end
 
   it 'records from compilation_started to rep_write_ended' do
     listener.start_safely
 
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 0))
+    mock_time(0)
     Nanoc::Core::NotificationCenter.post(:compilation_started, rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 1))
+    mock_time(1)
 
     expect { Nanoc::Core::NotificationCenter.post(:rep_write_ended, rep, false, '/foo.html', true, true).sync }
       .to output(/create.*\[1\.00s\]/).to_stdout
@@ -45,13 +51,13 @@
   it 'records from compilation_started over compilation_suspended to rep_write_ended' do
     listener.start_safely
 
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 0))
+    mock_time(0)
     Nanoc::Core::NotificationCenter.post(:compilation_started, rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 1))
+    mock_time(1)
     Nanoc::Core::NotificationCenter.post(:compilation_suspended, rep, :__irrelevant__).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 3))
+    mock_time(3)
     Nanoc::Core::NotificationCenter.post(:compilation_started, rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 6))
+    mock_time(6)
 
     expect { Nanoc::Core::NotificationCenter.post(:rep_write_ended, rep, false, '/foo.html', true, true).sync }
       .to output(/create.*\[4\.00s\]/).to_stdout
@@ -60,13 +66,13 @@
   it 'records from compilation_started over rep_write_{enqueued,started} to rep_write_ended' do
     listener.start_safely
 
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 0))
+    mock_time(0)
     Nanoc::Core::NotificationCenter.post(:compilation_started, rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 1))
+    mock_time(1)
     Nanoc::Core::NotificationCenter.post(:rep_write_enqueued, rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 3))
+    mock_time(3)
     Nanoc::Core::NotificationCenter.post(:rep_write_started, rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 6))
+    mock_time(6)
 
     expect { Nanoc::Core::NotificationCenter.post(:rep_write_ended, rep, false, '/foo.html', true, true).sync }
       .to output(/create.*\[4\.00s\]/).to_stdout
@@ -85,7 +91,7 @@
 
     it 'prints nothing' do
       Nanoc::Core::NotificationCenter.post(:compilation_started, rep).sync
-      Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 1))
+      mock_time(1)
 
       expect { Nanoc::Core::NotificationCenter.post(:rep_write_ended, rep, false, '/foo.html', false, false).sync }
         .not_to output(/identical/).to_stdout
@@ -94,7 +100,7 @@
     it 'prints nothing' do
       Nanoc::Core::NotificationCenter.post(:compilation_started, rep).sync
       Nanoc::Core::NotificationCenter.post(:cached_content_used, rep).sync
-      Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 1))
+      mock_time(1)
 
       expect { Nanoc::Core::NotificationCenter.post(:rep_write_ended, rep, false, '/foo.html', false, false).sync }
         .not_to output(/cached/).to_stdout
@@ -114,7 +120,7 @@
 
     it 'prints “identical” if not cached' do
       Nanoc::Core::NotificationCenter.post(:compilation_started, rep).sync
-      Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 1))
+      mock_time(1)
 
       expect { Nanoc::Core::NotificationCenter.post(:rep_write_ended, rep, false, '/foo.html', false, false).sync }
         .to output(/identical/).to_stdout
@@ -123,7 +129,7 @@
     it 'prints “cached” if cached' do
       Nanoc::Core::NotificationCenter.post(:compilation_started, rep).sync
       Nanoc::Core::NotificationCenter.post(:cached_content_used, rep).sync
-      Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 1))
+      mock_time(1)
 
       expect { Nanoc::Core::NotificationCenter.post(:rep_write_ended, rep, false, '/foo.html', false, false).sync }
         .to output(/cached/).to_stdout

diff --git a/nanoc-cli/spec/nanoc/cli/compile_listeners/timing_recorder_spec.rb b/nanoc-cli/spec/nanoc/cli/compile_listeners/timing_recorder_spec.rb
@@ -19,35 +19,42 @@
     end
   end
 
+  let(:original_timestamp) { Process.clock_gettime(Process::CLOCK_MONOTONIC, :nanosecond) }
+
+  def mock_time(seconds)
+    allow(Process)
+      .to receive(:clock_gettime)
+      .with(Process::CLOCK_MONOTONIC, :nanosecond)
+      .and_return(original_timestamp + seconds * 1_000_000_000)
+  end
+
   before do
-    Timecop.freeze(Time.local(2008, 1, 2, 14, 5, 0))
     Nanoc::CLI.verbosity = 2
     listener.start_safely
   end
 
   after do
-    Timecop.return
     listener.stop_safely
   end
 
   it 'prints filters table' do
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 0))
+    mock_time(0)
     Nanoc::Core::NotificationCenter.post(:filtering_started, rep, :erb).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 1))
+    mock_time(1)
     Nanoc::Core::NotificationCenter.post(:filtering_ended, rep, :erb).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 14, 1))
+    mock_time(100)
     Nanoc::Core::NotificationCenter.post(:filtering_started, rep, :erb).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 14, 3))
+    mock_time(102)
     Nanoc::Core::NotificationCenter.post(:filtering_ended, rep, :erb).sync
 
     expect { listener.stop_safely }
       .to output(/^\s*erb │     2   1\.00s   1\.50s   1\.90s   1\.95s   2\.00s   3\.00s$/).to_stdout
   end
 
   it 'records single from filtering_started to filtering_ended' do
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 0))
+    mock_time(0)
     Nanoc::Core::NotificationCenter.post(:filtering_started, rep, :erb).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 1))
+    mock_time(1)
     Nanoc::Core::NotificationCenter.post(:filtering_ended, rep, :erb).sync
 
     expect(listener.filters_summary.get(name: 'erb').min).to eq(1.00)
@@ -58,13 +65,13 @@
   end
 
   it 'records multiple from filtering_started to filtering_ended' do
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 0))
+    mock_time(0)
     Nanoc::Core::NotificationCenter.post(:filtering_started, rep, :erb).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 1))
+    mock_time(1)
     Nanoc::Core::NotificationCenter.post(:filtering_ended, rep, :erb).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 14, 1))
+    mock_time(100)
     Nanoc::Core::NotificationCenter.post(:filtering_started, rep, :erb).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 14, 3))
+    mock_time(102)
     Nanoc::Core::NotificationCenter.post(:filtering_ended, rep, :erb).sync
 
     expect(listener.filters_summary.get(name: 'erb').min).to eq(1.00)
@@ -75,13 +82,13 @@
   end
 
   it 'records filters in nested filtering_started/filtering_ended' do
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 0))
+    mock_time(0)
     Nanoc::Core::NotificationCenter.post(:filtering_started, rep, :outer).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 1))
+    mock_time(1)
     Nanoc::Core::NotificationCenter.post(:filtering_started, rep, :inner).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 3))
+    mock_time(3)
     Nanoc::Core::NotificationCenter.post(:filtering_ended, rep, :inner).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 6))
+    mock_time(6)
     Nanoc::Core::NotificationCenter.post(:filtering_ended, rep, :outer).sync
 
     expect(listener.filters_summary.get(name: 'inner').min).to eq(2.00)
@@ -98,16 +105,16 @@
   end
 
   it 'pauses outer stopwatch when suspended' do
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 0))
+    mock_time(0)
     Nanoc::Core::NotificationCenter.post(:compilation_started, rep).sync
     Nanoc::Core::NotificationCenter.post(:filtering_started, rep, :outer).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 1))
+    mock_time(1)
     Nanoc::Core::NotificationCenter.post(:filtering_started, rep, :inner).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 3))
+    mock_time(3)
     Nanoc::Core::NotificationCenter.post(:compilation_suspended, rep, :__anything__).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 6))
+    mock_time(6)
     Nanoc::Core::NotificationCenter.post(:compilation_started, rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 10))
+    mock_time(10)
     Nanoc::Core::NotificationCenter.post(:filtering_ended, rep, :inner).sync
     Nanoc::Core::NotificationCenter.post(:filtering_ended, rep, :outer).sync
 
@@ -120,13 +127,13 @@
 
   it 'records single from filtering_started over compilation_{suspended,started} to filtering_ended' do
     Nanoc::Core::NotificationCenter.post(:compilation_started, rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 0))
+    mock_time(0)
     Nanoc::Core::NotificationCenter.post(:filtering_started, rep, :erb).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 1))
+    mock_time(1)
     Nanoc::Core::NotificationCenter.post(:compilation_suspended, rep, :__anything__).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 3))
+    mock_time(3)
     Nanoc::Core::NotificationCenter.post(:compilation_started, rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 7))
+    mock_time(7)
     Nanoc::Core::NotificationCenter.post(:filtering_ended, rep, :erb).sync
 
     expect(listener.filters_summary.get(name: 'erb').min).to eq(5.00)
@@ -137,9 +144,9 @@
   end
 
   it 'records single phase start+stop' do
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 0))
+    mock_time(0)
     Nanoc::Core::NotificationCenter.post(:phase_started, 'donkey', rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 1))
+    mock_time(1)
     Nanoc::Core::NotificationCenter.post(:phase_ended, 'donkey', rep).sync
 
     expect(listener.phases_summary.get(name: 'donkey').min).to eq(1.00)
@@ -150,13 +157,13 @@
   end
 
   it 'records multiple phase start+stop' do
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 0))
+    mock_time(0)
     Nanoc::Core::NotificationCenter.post(:phase_started, 'donkey', rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 1))
+    mock_time(1)
     Nanoc::Core::NotificationCenter.post(:phase_ended, 'donkey', rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 11, 6, 0))
+    mock_time(100)
     Nanoc::Core::NotificationCenter.post(:phase_started, 'donkey', rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 11, 6, 2))
+    mock_time(102)
     Nanoc::Core::NotificationCenter.post(:phase_ended, 'donkey', rep).sync
 
     expect(listener.phases_summary.get(name: 'donkey').min).to eq(1.00)
@@ -167,13 +174,13 @@
   end
 
   it 'records single phase start+yield+resume+stop' do
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 0))
+    mock_time(0)
     Nanoc::Core::NotificationCenter.post(:phase_started, 'donkey', rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 1))
+    mock_time(1)
     Nanoc::Core::NotificationCenter.post(:phase_yielded, 'donkey', rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 11, 6, 0))
+    mock_time(100)
     Nanoc::Core::NotificationCenter.post(:phase_resumed, 'donkey', rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 11, 6, 2))
+    mock_time(102)
     Nanoc::Core::NotificationCenter.post(:phase_ended, 'donkey', rep).sync
 
     expect(listener.phases_summary.get(name: 'donkey').min).to eq(3.00)
@@ -184,15 +191,15 @@
   end
 
   it 'records single phase start+yield+abort+start+stop' do
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 0))
+    mock_time(0)
     Nanoc::Core::NotificationCenter.post(:phase_started, 'donkey', rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 1))
+    mock_time(1)
     Nanoc::Core::NotificationCenter.post(:phase_yielded, 'donkey', rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 11, 6, 0))
+    mock_time(100)
     Nanoc::Core::NotificationCenter.post(:phase_aborted, 'donkey', rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 12, 7, 2))
+    mock_time(200)
     Nanoc::Core::NotificationCenter.post(:phase_started, 'donkey', rep).sync
-    Timecop.freeze(Time.local(2008, 9, 1, 12, 7, 5))
+    mock_time(203)
     Nanoc::Core::NotificationCenter.post(:phase_ended, 'donkey', rep).sync
 
     expect(listener.phases_summary.get(name: 'donkey').min).to eq(1.00)

diff --git a/nanoc-core/spec/nanoc/core/compilation_stage_spec.rb b/nanoc-core/spec/nanoc/core/compilation_stage_spec.rb
@@ -21,14 +21,23 @@
     end
 
     context 'actual implementation' do
+      before do
+        a = Process.clock_gettime(Process::CLOCK_MONOTONIC, :nanosecond)
+
+        # Go to a few seconds in the future
+        allow(Process)
+          .to receive(:clock_gettime)
+          .with(Process::CLOCK_MONOTONIC, :nanosecond)
+          .and_return(a, a + 13_570_000_000)
+      end
+
       let(:klass) do
         Class.new(described_class) do
           def self.to_s
             'My::Klazz'
           end
 
           def run
-            Timecop.freeze(Time.now + 13.57)
             :i_like_donkeys
           end
         end
@@ -71,9 +80,9 @@ def run
           end
         end
 
-        it 'does not send timing notification' do
+        it 'sends timing notification' do
           expect { subject rescue nil }
-            .not_to send_notification(:stage_ran, 13.57, klass)
+            .to send_notification(:stage_ran, 13.57, klass)
         end
 
         it 'sends stage_started' do

diff --git a/nanoc-core/spec/nanoc/core/instrumentor_spec.rb b/nanoc-core/spec/nanoc/core/instrumentor_spec.rb
@@ -23,11 +23,19 @@
       described_class.enable { ex.run }
     end
 
+    before do
+      a = Process.clock_gettime(Process::CLOCK_MONOTONIC, :nanosecond)
+
+      allow(Process)
+        .to receive(:clock_gettime)
+        .with(Process::CLOCK_MONOTONIC, :nanosecond)
+        .and_return(a, a + 5_000_000_000)
+    end
+
     it 'sends notification' do
       expect do
         subject.call(:sample_notification, 'garbage', 123) do
-          # Go to a few seconds in the future
-          Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 5))
+          # pass time, as defined by the clock_gettime mock
         end
       end.to send_notification(:sample_notification, 5.0, 'garbage', 123)
     end