fix: use monotonic clock where possible (#782)

* fix: use monotonic clock where possible

* fix some merge conflicts

* always use relative timestamps

* use correct base

* fix: add start_timestamp tests

* fix: events relative timestamp test

* fix: add finish timestamp test

* fix: rebase merge errors

* chore: Apply francis feedback

Co-authored-by: Francis Bogsanyi <[email protected]>

* chore: time test cleanups

* Simplify tests

Co-authored-by: Robert Laurin <[email protected]>
Co-authored-by: Robert <[email protected]>

Author: fbogsany

instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/tracer_middleware.rb

@@ -107,9 +107,7 @@ def create_frontend_span(env, extracted_context)
 
             span = tracer.start_span('http_server.proxy',
                                      with_parent: extracted_context,
-                                     attributes: {
-                                       'start_time' => request_start_time.to_f
-                                     },
+                                     start_timestamp: request_start_time,
                                      kind: :server)
 
             OpenTelemetry::Trace.context_with_span(span, parent_context: extracted_context)

sdk/lib/opentelemetry/sdk/trace/span.rb

@@ -131,7 +131,7 @@ def add_attributes(attributes)
         #
         # @return [self] returns itself
         def add_event(name, attributes: nil, timestamp: nil)
-          event = Event.new(name, truncate_attribute_values(attributes), wall_clock(timestamp))
+          event = Event.new(name, truncate_attribute_values(attributes), relative_timestamp(timestamp))
 
           @mutex.synchronize do
             if @ended
@@ -233,7 +233,7 @@ def finish(end_timestamp: nil)
               OpenTelemetry.logger.warn('Calling finish on an ended Span.')
               return self
             end
-            @end_timestamp = wall_clock(end_timestamp)
+            @end_timestamp = relative_timestamp(end_timestamp)
             @attributes = validated_attributes(@attributes).freeze
             @events.freeze
             @ended = true
@@ -276,7 +276,7 @@ def to_span_data
         end
 
         # @api private
-        def initialize(context, parent_context, name, kind, parent_span_id, span_limits, span_processors, attributes, links, start_timestamp, resource, instrumentation_library) # rubocop:disable Metrics/AbcSize
+        def initialize(context, parent_context, parent_span, name, kind, parent_span_id, span_limits, span_processors, attributes, links, start_timestamp, resource, instrumentation_library) # rubocop:disable Metrics/AbcSize,  Metrics/CyclomaticComplexity, Metrics/MethodLength,  Metrics/PerceivedComplexity
           super(span_context: context)
           @mutex = Mutex.new
           @name = name
@@ -291,17 +291,45 @@ def initialize(context, parent_context, name, kind, parent_span_id, span_limits,
           @total_recorded_events = 0
           @total_recorded_links = links&.size || 0
           @total_recorded_attributes = attributes&.size || 0
-          @start_timestamp = wall_clock(start_timestamp)
-          @end_timestamp = nil
           @attributes = attributes.nil? ? nil : Hash[attributes] # We need a mutable copy of attributes.
           trim_span_attributes(@attributes)
           @events = nil
           @links = trim_links(links, span_limits.link_count_limit, span_limits.link_attribute_count_limit)
+
+          # Times are hard. Whenever an explicit timestamp is provided
+          # (for Events or for the Span start_timestamp or end_timestamp),
+          # we use that as the recorded timestamp. An implicit Event timestamp
+          # and end_timestamp is computed as a monotonic clock offset from
+          # the realtime start_timestamp. The realtime start_timestamp is
+          # computed as a monotonic clock offset from the realtime
+          # start_timestamp of its parent span, if available, or it is
+          # fetched from the realtime system clock.
+          #
+          # We therefore have 3 start timestamps. The first two are used
+          # internally (and by child spans) to compute other timestamps.
+          # The last is the start timestamp actually recorded in the
+          # SpanData.
+          @monotonic_start_timestamp = monotonic_now
+          @realtime_start_timestamp = if parent_span.recording?
+                                        relative_realtime(parent_span.realtime_start_timestamp, parent_span.monotonic_start_timestamp)
+                                      else
+                                        realtime_now
+                                      end
+          @start_timestamp = if start_timestamp
+                               time_in_nanoseconds(start_timestamp)
+                             else
+                               @realtime_start_timestamp
+                             end
+          @end_timestamp = nil
           @span_processors.each { |processor| processor.on_start(self, parent_context) }
         end
 
         # TODO: Java implementation overrides finalize to log if a span isn't finished.
 
+        protected
+
+        attr_reader :monotonic_start_timestamp, :realtime_start_timestamp
+
         private
 
         def validated_attributes(attrs)
@@ -376,9 +404,26 @@ def append_event(events, event) # rubocop:disable Metrics/AbcSize, Metrics/Cyclo
           events << event
         end
 
-        def wall_clock(timestamp)
-          timestamp = (timestamp.to_r * 1_000_000_000).to_i unless timestamp.nil?
-          timestamp || Process.clock_gettime(Process::CLOCK_REALTIME, :nanosecond)
+        def relative_timestamp(timestamp)
+          return time_in_nanoseconds(timestamp) unless timestamp.nil?
+
+          relative_realtime(realtime_start_timestamp, monotonic_start_timestamp)
+        end
+
+        def time_in_nanoseconds(timestamp)
+          (timestamp.to_r * 1_000_000_000).to_i
+        end
+
+        def relative_realtime(realtime_base, monotonic_base)
+          realtime_base + (monotonic_now - monotonic_base)
+        end
+
+        def realtime_now
+          Process.clock_gettime(Process::CLOCK_REALTIME, :nanosecond)
+        end
+
+        def monotonic_now
+          Process.clock_gettime(Process::CLOCK_MONOTONIC, :nanosecond)
         end
       end
       # rubocop:enable Metrics/ClassLength

sdk/lib/opentelemetry/sdk/trace/tracer.rb

@@ -31,12 +31,14 @@ def start_span(name, with_parent: nil, attributes: nil, links: nil, start_timest
           name ||= 'empty'
 
           with_parent ||= Context.current
+          parent_span = OpenTelemetry::Trace.current_span(with_parent)
           parent_span_context = OpenTelemetry::Trace.current_span(with_parent).context
           if parent_span_context.valid?
             parent_span_id = parent_span_context.span_id
             trace_id = parent_span_context.trace_id
           end
-          @tracer_provider.internal_create_span(name, kind, trace_id, parent_span_id, attributes, links, start_timestamp, with_parent, @instrumentation_library)
+
+          @tracer_provider.internal_create_span(name, kind, trace_id, parent_span_id, attributes, links, start_timestamp, with_parent, parent_span, @instrumentation_library)
         end
       end
     end

sdk/lib/opentelemetry/sdk/trace/tracer_provider.rb

@@ -126,7 +126,13 @@ def add_span_processor(span_processor)
         end
 
         # @api private
-        def internal_create_span(name, kind, trace_id, parent_span_id, attributes, links, start_timestamp, parent_context, instrumentation_library) # rubocop:disable Metrics/MethodLength, Metrics/AbcSize
+        def internal_create_span(name, kind, trace_id, parent_span_id, attributes, links, start_timestamp, parent_context, parent_span, instrumentation_library) # rubocop:disable Metrics/MethodLength, Metrics/AbcSize
+          parent_span_context = parent_span.context
+          if parent_span_context.valid?
+            parent_span_id = parent_span_context.span_id
+            trace_id = parent_span_context.trace_id
+          end
+          name ||= 'empty'
           trace_id ||= @id_generator.generate_trace_id
           kind ||= :internal
           result = @sampler.should_sample?(trace_id: trace_id, parent_context: parent_context, links: links, name: name, kind: kind, attributes: attributes)
@@ -138,6 +144,7 @@ def internal_create_span(name, kind, trace_id, parent_span_id, attributes, links
             Span.new(
               context,
               parent_context,
+              parent_span,
               name,
               kind,
               parent_span_id,

sdk/test/opentelemetry/sdk/trace/span_test.rb

@@ -11,6 +11,7 @@
   SpanKind = OpenTelemetry::Trace::SpanKind
   Status = OpenTelemetry::Trace::Status
   Context = OpenTelemetry::Context
+  SpanLimits = OpenTelemetry::SDK::Trace::SpanLimits
 
   let(:context) { OpenTelemetry::Trace::SpanContext.new }
   let(:mock_span_processor) { Minitest::Mock.new }
@@ -25,7 +26,7 @@
     )
   end
   let(:span) do
-    Span.new(context, Context.empty, 'name', SpanKind::INTERNAL, nil, span_limits,
+    Span.new(context, Context.empty, OpenTelemetry::Trace::Span::INVALID, 'name', SpanKind::INTERNAL, nil, span_limits,
              [], nil, nil, Time.now, nil, nil)
   end
 
@@ -200,14 +201,31 @@
       _(events.first.attributes).must_equal(attrs)
     end
 
-    it 'add event with timestamp' do
-      ts = Time.now
+    it 'honours an explicit timestamp' do
+      ts = Time.new('2021-11-23 12:00:00.000000 -0600')
       span.add_event('added', timestamp: ts)
       events = span.events
       _(events.size).must_equal(1)
       _(events.first.timestamp).must_equal(exportable_timestamp(ts))
     end
 
+    it 'sets the implicit event timestamp relative to the span start' do
+      # Create a span with deterministic time values stored on it.
+      test_span = mock_gettime(monotonic: 100, realtime: 1_000) do
+        Span.new(context, Context.empty, OpenTelemetry::Trace::Span::INVALID, 'span', SpanKind::INTERNAL, nil, span_limits, [], nil, nil, nil, nil, nil)
+      end
+
+      mock_gettime(monotonic: 200, realtime: 1_000_000) do
+        test_span.add_event('record something with relative time')
+        event = test_span.events[0]
+        _(event).wont_be_nil
+
+        # The expect timestamp is that of the parent offset by
+        # the drift in the monotonic clock
+        _(event.timestamp).must_equal(1_000 + 100)
+      end
+    end
+
     it 'does not add an event if span is ended' do
       span.finish
       span.add_event('will_not_be_added')
@@ -372,14 +390,29 @@
       _(span.finish).must_equal(span)
     end
 
-    it 'sets the end timestamp' do
-      span.finish
-      _(span.to_span_data.end_timestamp).wont_be_nil
+    it 'honours an explicit end timestamp' do
+      ts = Time.new('2021-11-23 12:00:00.000000 -0600')
+      _(span.finish(end_timestamp: ts)).must_equal(span)
+      _(span.end_timestamp).must_equal(exportable_timestamp(ts))
+    end
+
+    it 'sets the end timestamp relative to the start time' do
+      # Create a span with deterministic time values stored on it.
+      test_span = mock_gettime(monotonic: 100, realtime: 1_000) do
+        Span.new(context, Context.empty, OpenTelemetry::Trace::Span::INVALID, 'span', SpanKind::INTERNAL, nil, span_limits, [], nil, nil, nil, nil, nil)
+      end
+
+      mock_gettime(monotonic: 200, realtime: 1_000_000) do
+        test_span.finish
+        # The expect timestamp is that of the parent offset by
+        # the drift in the monotonic clock
+        _(test_span.end_timestamp).must_equal(1_000 + 100)
+      end
     end
 
     it 'calls the span processor #on_finish callback' do
       mock_span_processor.expect(:on_start, nil) { |_| true }
-      span = Span.new(context, Context.empty,
+      span = Span.new(context, Context.empty, OpenTelemetry::Trace::Span::INVALID,
                       'name', SpanKind::INTERNAL, nil, span_limits,
                       [mock_span_processor], nil, nil, Time.now, nil, nil)
       mock_span_processor.expect(:on_finish, nil, [span])
@@ -405,54 +438,104 @@
     it 'calls the span processor #on_start callback' do
       yielded_span = nil
       mock_span_processor.expect(:on_start, nil) { |s| yielded_span = s }
-      span = Span.new(context, Context.empty, 'name', SpanKind::INTERNAL, nil, span_limits,
+      span = Span.new(context, Context.empty, OpenTelemetry::Trace::Span::INVALID, 'name', SpanKind::INTERNAL, nil, span_limits,
                       [mock_span_processor], nil, nil, Time.now, nil, nil)
       _(yielded_span).must_equal(span)
       mock_span_processor.verify
     end
 
     it 'trims excess attributes' do
       attributes = { 'foo': 'bar', 'other': 'attr' }
-      span = Span.new(context, Context.empty, 'name', SpanKind::INTERNAL, nil, span_limits,
+      span = Span.new(context, Context.empty, OpenTelemetry::Trace::Span::INVALID, 'name', SpanKind::INTERNAL, nil, span_limits,
                       [], attributes, nil, Time.now, nil, nil)
       _(span.to_span_data.total_recorded_attributes).must_equal(2)
       _(span.attributes.length).must_equal(1)
     end
 
     it 'truncates attributes if configured' do
       attributes = { 'foo': 'oldbaroldbaroldbaroldbaroldbaroldbar' }
-      span = Span.new(context, Context.empty, 'name', SpanKind::INTERNAL, nil, span_limits,
+      span = Span.new(context, Context.empty, OpenTelemetry::Trace::Span::INVALID, 'name', SpanKind::INTERNAL, nil, span_limits,
                       [], attributes, nil, Time.now, nil, nil)
       _(span.attributes[:foo]).must_equal('oldbaroldbaroldbaroldbaroldba...')
     end
 
     it 'counts attributes' do
       attributes = { 'foo': 'bar', 'other': 'attr' }
-      span = Span.new(context, Context.empty, 'name', SpanKind::INTERNAL, nil, span_limits,
+      span = Span.new(context, Context.empty, OpenTelemetry::Trace::Span::INVALID, 'name', SpanKind::INTERNAL, nil, span_limits,
                       [], attributes, nil, Time.now, nil, nil)
       _(span.to_span_data.total_recorded_attributes).must_equal(2)
     end
 
     it 'counts links' do
       links = [OpenTelemetry::Trace::Link.new(context), OpenTelemetry::Trace::Link.new(context)]
-      span = Span.new(context, Context.empty, 'name', SpanKind::INTERNAL, nil, span_limits,
+      span = Span.new(context, Context.empty, OpenTelemetry::Trace::Span::INVALID, 'name', SpanKind::INTERNAL, nil, span_limits,
                       [], nil, links, Time.now, nil, nil)
       _(span.to_span_data.total_recorded_links).must_equal(2)
     end
 
     it 'trims excess links' do
       links = [OpenTelemetry::Trace::Link.new(context), OpenTelemetry::Trace::Link.new(context)]
-      span = Span.new(context, Context.empty, 'name', SpanKind::INTERNAL, nil, span_limits,
+      span = Span.new(context, Context.empty, OpenTelemetry::Trace::Span::INVALID, 'name', SpanKind::INTERNAL, nil, span_limits,
                       [], nil, links, Time.now, nil, nil)
       _(span.links.size).must_equal(1)
     end
 
     it 'prunes invalid links' do
       invalid_context = OpenTelemetry::Trace::SpanContext.new(trace_id: OpenTelemetry::Trace::INVALID_TRACE_ID)
       links = [OpenTelemetry::Trace::Link.new(context), OpenTelemetry::Trace::Link.new(invalid_context)]
-      span = Span.new(context, Context.empty, 'name', SpanKind::INTERNAL, nil, span_limits,
+      span = Span.new(context, Context.empty, OpenTelemetry::Trace::Span::INVALID, 'name', SpanKind::INTERNAL, nil, span_limits,
                       [], nil, links, Time.now, nil, nil)
       _(span.links.size).must_equal(1)
     end
+
+    it 'honours an explicit timestamp' do
+      timestamp = Time.new('2021-11-23 12:00:00.000000 -0600')
+      test_span = Span.new(context, Context.empty, OpenTelemetry::Trace::Span::INVALID, 'child span', SpanKind::INTERNAL, nil, span_limits, [], nil, [], timestamp, nil, nil)
+      _(test_span.start_timestamp).must_equal(exportable_timestamp(timestamp))
+    end
+
+    it 'uses the monotonic offset from the parent_span realtime start timestamp when parent_span is recording' do
+      parent_span = mock_gettime(monotonic: 100, realtime: 1_000) do
+        Span.new(context, Context.empty, OpenTelemetry::Trace::Span::INVALID, 'parent span', SpanKind::INTERNAL, nil, span_limits, [], nil, nil, nil, nil, nil)
+      end
+
+      _(parent_span.recording?).must_equal(true)
+      mock_gettime(monotonic: 200, realtime: 1_000_000) do
+        test_span = Span.new(context, Context.empty, parent_span, 'child span', SpanKind::INTERNAL, nil, span_limits, [], nil, [], nil, nil, nil)
+
+        # We expect to see the start_timestamp to be the parent span timestamp
+        # with the same offset we returned with our stubbed
+        # monotonic_now value we returned above
+        _(test_span.start_timestamp).must_equal(1_000 + 100)
+      end
+    end
+
+    it 'uses the realtime clock when the parent_span is not recording' do
+      non_recording_span = OpenTelemetry::Trace.non_recording_span(span.context)
+
+      mock_gettime(monotonic: 100, realtime: 1_000) do
+        test_span = Span.new(context, Context.empty, non_recording_span, 'name', SpanKind::INTERNAL, nil, span_limits, [], nil, [], nil, nil, nil)
+
+        # We expect for the timestamp to be the value returned from
+        # the call to realtime_now as we have no timestamp and no parent
+        # span time to try and get a relative offset from.
+        _(test_span.start_timestamp).must_equal(1_000)
+      end
+    end
+  end
+
+  def mock_gettime(monotonic:, realtime:)
+    timestamps = {
+      Process::CLOCK_MONOTONIC => monotonic,
+      Process::CLOCK_REALTIME => realtime
+    }
+
+    clock_gettime_mock = lambda do |clock_id, unit|
+      _(timestamps).must_include(clock_id)
+      _(unit).must_equal(:nanosecond)
+      timestamps[clock_id]
+    end
+
+    Process.stub(:clock_gettime, clock_gettime_mock) { yield }
   end
 end