Use Process::CLOCK_MONOTONIC for timing instead of Time.now.to_f.

Work related to #302.
gavinlaking · Nov 12, 2015 · 642eff6 · 642eff6
1 parent ab41103
commit 642eff6
Show file tree

Hide file tree

Showing 8 changed files with 76 additions and 28 deletions.
diff --git a/lib/vedeu/events/event.rb b/lib/vedeu/events/event.rb
@@ -213,7 +213,7 @@ def execute(*args)
       #
       # @return [Boolean]
       def throttling?
-        @now = Time.now.to_f
+        @now = Vedeu.clock_time
 
         options[:delay] > 0
       end
@@ -238,7 +238,7 @@ def throttle_expired?
       #
       # @return [Boolean]
       def debouncing?
-        @now = Time.now.to_f
+        @now = Vedeu.clock_time
 
         @deadline = @now + debounce unless deadline?
 

diff --git a/lib/vedeu/logging/all.rb b/lib/vedeu/logging/all.rb
@@ -9,6 +9,7 @@ module Logging
 
 end # Vedeu
 
+require 'vedeu/logging/clock_time'
 require 'vedeu/logging/lockless_log_device'
 require 'vedeu/logging/mono_logger'
 require 'vedeu/logging/log'

diff --git a/lib/vedeu/logging/clock_time.rb b/lib/vedeu/logging/clock_time.rb
@@ -0,0 +1,34 @@
+module Vedeu
+
+  module Logging
+
+    # If the system supports Process::CLOCK_MONOTONIC use that for
+    # timestamps.
+    #
+    #    Vedeu.clock_time # => 15217.232113 (Process::CLOCK_MONOTONIC)
+    #                     # => 1447196800.3098037 (Time.now)
+    #
+    module ClockTime
+
+      if defined?(Process::CLOCK_MONOTONIC)
+        def self.clock_time
+          Process.clock_gettime(Process::CLOCK_MONOTONIC)
+        end
+
+      else
+        def self.clock_time
+          Time.now
+        end
+
+      end
+
+    end # ClockTime
+
+  end # Logging
+
+  # @!method clock_time
+  #   @see Vedeu::Logging::ClockTime
+  def_delegators Vedeu::Logging::ClockTime,
+                 :clock_time
+
+end # Vedeu
diff --git a/lib/vedeu/logging/log.rb b/lib/vedeu/logging/log.rb
@@ -54,6 +54,24 @@ def log_stderr(type: :info, message:)
           $stderr.puts log_entry(type, message)
         end
 
+        # Returns a formatted timestamp.
+        # eg. [137.7824]
+        #
+        # @return [String]
+        def timestamp
+          @now  = Vedeu.clock_time
+          @time ||= 0.0
+          @last ||= @now
+
+          unless @last == @time
+            @time += (@now - @last).round(4)
+            @last = @now
+          end
+
+          "[#{format('%7.4f', @time.to_s)}] ".rjust(7)
+        end
+        alias_method :log_timestamp, :timestamp
+
         private
 
         # @return [TrueClass]
@@ -163,23 +181,6 @@ def message_types
           }
         end
 
-        # Returns a formatted timestamp.
-        # eg. [137.7824]
-        #
-        # @return [String]
-        def timestamp
-          @now  = Time.now.to_f
-          @time ||= 0.0
-          @last ||= @now
-
-          unless @last == @time
-            @time += (@now - @last).round(4)
-            @last = @now
-          end
-
-          "[#{format('%7.4f', @time.to_s)}] ".rjust(7)
-        end
-
       end # Eigenclass
 
     end # Log
@@ -195,7 +196,8 @@ def timestamp
   def_delegators Vedeu::Logging::Log,
                  :log,
                  :log_stdout,
-                 :log_stderr
+                 :log_stderr,
+                 :log_timestamp
 
   # :nocov:
 

diff --git a/lib/vedeu/logging/timer.rb b/lib/vedeu/logging/timer.rb
@@ -35,7 +35,7 @@ def timer(message = '', &block)
       # @return [Vedeu::Logging::Timer]
       def initialize(message = '')
         @message = message
-        @started = Time.now.to_f
+        @started = Vedeu.clock_time
       end
 
       # Write an entry to the log file stating how long a section of
@@ -75,7 +75,7 @@ def measure
       #
       # @return [Float]
       def elapsed
-        ((Time.now.to_f - started) * 1000).round(3)
+        ((Vedeu.clock_time - started) * 1000).round(3)
       end
 
     end # Timer

diff --git a/lib/vedeu/output/renderers/file.rb b/lib/vedeu/output/renderers/file.rb
@@ -67,7 +67,7 @@ def filename
       # @return [Float]
       def timestamp
         if options[:timestamp]
-          "_#{Time.now.to_f}".freeze
+          "_#{Vedeu.clock_time}".freeze
 
         else
           ''.freeze

diff --git a/test/lib/vedeu/logging/clock_time_test.rb b/test/lib/vedeu/logging/clock_time_test.rb
@@ -0,0 +1,13 @@
+require 'test_helper'
+
+module Vedeu
+
+  module Logging
+
+    describe ClockTime do
+
+    end # ClockTime
+
+  end # Logging
+
+end # Vedeu
diff --git a/test/lib/vedeu/logging/timer_test.rb b/test/lib/vedeu/logging/timer_test.rb
@@ -9,18 +9,16 @@ module Logging
       let(:described) { Vedeu::Logging::Timer }
       let(:instance)  { described.new(_message) }
       let(:_message)  { 'Testing' }
-      let(:_time)     { mock('Time') }
-      let(:started)   { 1434492219.5238185 }
+      let(:_time)     { 1219.523818 }
 
       before do
-        Time.stubs(:now).returns(_time)
-        _time.stubs(:to_f).returns(started)
+        Vedeu.stubs(:clock_time).returns(_time)
       end
 
       describe '#initialize' do
         it { instance.must_be_instance_of(described) }
         it { instance.instance_variable_get('@message').must_equal(_message) }
-        it { instance.instance_variable_get('@started').must_equal(started) }
+        it { instance.instance_variable_get('@started').must_equal(_time) }
       end
 
       describe '.timer' do