Improve duration counting using monotonic clock

ddtrace.gemspec

@@ -33,6 +33,7 @@ EOS
   spec.require_paths = ['lib']
 
   spec.add_dependency 'msgpack'
+  spec.add_dependency 'concurrent-ruby'
 
   spec.add_development_dependency 'rake', '~> 10.5'
   spec.add_development_dependency 'rubocop', '= 0.49.1' if RUBY_VERSION >= '2.1.0'

lib/ddtrace/contrib/active_support/notifications/subscription.rb

@@ -73,8 +73,8 @@ def start_span(name, id, payload, start = nil)
 
             # Start a trace
             tracer.trace(@span_name, @options).tap do |span|
-              # Assign start time if provided
-              span.start_time = start unless start.nil?
+              # start span if time is provided
+              span.start(start) unless start.nil?
             end
           end
 

lib/ddtrace/contrib/grape/endpoint.rb

@@ -83,7 +83,7 @@ def self.endpoint_run(name, start, finish, id, payload)
             span.set_tag('grape.route.endpoint', api_view)
             span.set_tag('grape.route.path', path)
           ensure
-            span.start_time = start
+            span.start(start)
             span.finish(finish)
           end
         rescue StandardError => e
@@ -124,7 +124,7 @@ def self.endpoint_render(name, start, finish, id, payload)
           begin
             span.set_error(payload[:exception_object]) unless payload[:exception_object].nil?
           ensure
-            span.start_time = start
+            span.start(start)
             span.finish(finish)
           end
         rescue StandardError => e
@@ -152,7 +152,7 @@ def self.endpoint_run_filters(name, start, finish, id, payload)
             span.set_error(payload[:exception_object]) unless payload[:exception_object].nil?
             span.set_tag('grape.filter.type', type.to_s)
           ensure
-            span.start_time = start
+            span.start(start)
             span.finish(finish)
           end
         rescue StandardError => e

lib/ddtrace/span.rb

@@ -1,8 +1,10 @@
 require 'time'
 require 'thread'
+require 'forwardable'
 
 require 'ddtrace/utils'
 require 'ddtrace/ext/errors'
+require 'ddtrace/span/duration'
 
 module Datadog
   # Represents a logical unit of work in the system. Each trace consists of one or more spans.
@@ -11,6 +13,8 @@ module Datadog
   # within a larger operation. Spans can be nested within each other, and in those instances
   # will have a parent-child relationship.
   class Span
+    extend Forwardable
+
     # The max value for a \Span identifier.
     # Span and trace identifiers should be strictly positive and strictly inferior to this limit.
     #
@@ -19,13 +23,14 @@ class Span
     MAX_ID = 2**63
 
     attr_accessor :name, :service, :resource, :span_type,
-                  :start_time, :end_time,
                   :span_id, :trace_id, :parent_id,
                   :status, :sampled,
                   :tracer, :context
 
     attr_reader :parent
 
+    def_delegators :@duration, :start_time, :end_time, :started?, :finished?
+
     # Create a new span linked to the given tracer. Call the \Tracer method <tt>start_span()</tt>
     # and then <tt>finish()</tt> once the tracer operation is over.
     #
@@ -56,8 +61,7 @@ def initialize(tracer, name, options = {})
       @parent = nil
       @sampled = true
 
-      @start_time = nil # set by Tracer.start_span
-      @end_time = nil # set by Span.finish
+      @duration = Duration.new
     end
 
     # Set the given key / value tag pair on the span. Keys and values
@@ -100,20 +104,36 @@ def set_error(e)
       set_tag(Ext::Errors::STACK, e.backtrace) unless e.backtrace.empty?
     end
 
+    # Mark the span started at the current time.
+    def start(start_time = nil)
+      # A span should not be started twice. Note that this is not thread-safe,
+      # start is called from multiple threads, a given span might be started
+      # several times. Again, one should not do this, so this test is more a
+      # fallback to avoid very bad things and protect you in most common cases.
+      return if started?
+      @duration.start(start_time)
+
+      self
+    end
+
+    # for backwards compatibility
+    def start_time=(time)
+      time.tap { start(time) }
+    end
+
+    # for backwards compatibility
+    def end_time=(time)
+      time.tap { @duration.finish(time) }
+    end
+
     # Mark the span finished at the current time and submit it.
     def finish(finish_time = nil)
       # A span should not be finished twice. Note that this is not thread-safe,
       # finish is called from multiple threads, a given span might be finished
       # several times. Again, one should not do this, so this test is more a
       # fallback to avoid very bad things and protect you in most common cases.
       return if finished?
-
-      # Provide a default start_time if unset, but this should have been set by start_span.
-      # Using now here causes 0-duration spans, still, this is expected, as we never
-      # explicitely say when it started.
-      @start_time ||= Time.now.utc
-
-      @end_time = finish_time.nil? ? Time.now.utc : finish_time # finish this
+      @duration.finish(finish_time)
 
       # Finish does not really do anything if the span is not bound to a tracer and a context.
       return self if @tracer.nil? || @context.nil?
@@ -132,11 +152,6 @@ def finish(finish_time = nil)
       self
     end
 
-    # Return whether the span is finished or not.
-    def finished?
-      !@end_time.nil?
-    end
-
     # Return a string representation of the span.
     def to_s
       "Span(name:#{@name},sid:#{@span_id},tid:#{@trace_id},pid:#{@parent_id})"
@@ -165,7 +180,7 @@ def parent=(parent)
 
     # Return the hash representation of the current span.
     def to_hash
-      h = {
+      {
         span_id: @span_id,
         parent_id: @parent_id,
         trace_id: @trace_id,
@@ -176,21 +191,18 @@ def to_hash
         meta: @meta,
         metrics: @metrics,
         error: @status
-      }
-
-      if !@start_time.nil? && !@end_time.nil?
-        h[:start] = (@start_time.to_f * 1e9).to_i
-        h[:duration] = ((@end_time - @start_time) * 1e9).to_i
+      }.tap do |h|
+        if @duration.complete?
+          h[:start] = (@duration.start_time.to_f * 1e9).to_i
+          h[:duration] = (@duration.to_f * 1e9).to_i
+        end
       end
-
-      h
     end
 
     # Return a human readable version of the span
     def pretty_print(q)
-      start_time = (@start_time.to_f * 1e9).to_i rescue '-'
-      end_time = (@end_time.to_f * 1e9).to_i rescue '-'
-      duration = ((@end_time - @start_time) * 1e9).to_i rescue 0
+      start_time = (@duration.start_time.to_f * 1e9).to_i rescue '-'
+      end_time = (@duration.end_time.to_f * 1e9).to_i rescue '-'
       q.group 0 do
         q.breakable
         q.text "Name: #{@name}\n"
@@ -203,7 +215,7 @@ def pretty_print(q)
         q.text "Error: #{@status}\n"
         q.text "Start: #{start_time}\n"
         q.text "End: #{end_time}\n"
-        q.text "Duration: #{duration}\n"
+        q.text "Duration: #{@duration.to_f}\n"
         q.group(2, 'Tags: [', "]\n") do
           q.breakable
           q.seplist @meta.each do |key, value|

lib/ddtrace/span/duration.rb

@@ -0,0 +1,69 @@
+require 'concurrent/utility/monotonic_time'
+module Datadog
+  class Span
+    # Stateful class used to track and calculate the duration of a Span.
+    class Duration
+      attr_reader :start_time, :end_time
+
+      def initialize
+        @start_time = nil
+        @duration_start = nil
+        @end_time = nil
+        @duration_end = nil
+        @wall_clock_duration = false
+      end
+
+      # Return whether the duration is started or not
+      def started?
+        !@start_time.nil?
+      end
+
+      # Return whether the duration is finished or not.
+      def finished?
+        !@end_time.nil?
+      end
+
+      def complete?
+        started? && finished?
+      end
+
+      def start(start_time)
+        if start_time
+          @start_time = start_time
+          @duration_start = start_time
+          @wall_clock_duration = true
+        else
+          @start_time = Time.now.utc
+          @duration_start = duration_marker
+        end
+      end
+
+      def finish(finish_time)
+        now = Time.now.utc
+
+        # Provide a default start_time if unset.
+        # Using `now` here causes duration to be 0; this is expected
+        # behavior when start_time is unknown.
+        start(finish_time || now) unless started?
+
+        if finish_time
+          @end_time = finish_time
+          @duration_start = @start_time
+          @duration_end = finish_time
+          @wall_clock_duration = true
+        else
+          @end_time = now
+          @duration_end = @wall_clock_duration ? now : duration_marker
+        end
+      end
+
+      def to_f
+        (@duration_end - @duration_start).to_f rescue 0.0
+      end
+
+      def duration_marker
+        Concurrent.monotonic_time
+      end
+    end
+  end
+end

lib/ddtrace/tracer.rb

@@ -203,7 +203,7 @@ def guess_context_and_parent(child_of)
     # * +start_time+: when the span actually starts (defaults to \now)
     # * +tags+: extra tags which should be added to the span.
     def start_span(name, options = {})
-      start_time = options.fetch(:start_time, Time.now.utc)
+      start_time = options[:start_time]
       tags = options.fetch(:tags, {})
 
       opts = options.select do |k, _v|
@@ -230,7 +230,7 @@ def start_span(name, options = {})
       end
       tags.each { |k, v| span.set_tag(k, v) } unless tags.empty?
       @tags.each { |k, v| span.set_tag(k, v) } unless @tags.empty?
-      span.start_time = start_time
+      span.start start_time
 
       # this could at some point be optional (start_active_span vs start_manual_span)
       ctx.add_span(span) unless ctx.nil?

spec/ddtrace/contrib/active_support/notifications/subscription_spec.rb

@@ -30,7 +30,7 @@
 
         it do
           expect(tracer).to receive(:trace).with(span_name, options).and_return(span).ordered
-          expect(span).to receive(:start_time=).with(start).and_return(span).ordered
+          expect(span).to receive(:start).with(start).and_return(span).ordered
           expect(tracer).to receive(:active_span).and_return(span).ordered
           expect(spy).to receive(:call).with(span, name, id, payload).ordered
           expect(span).to receive(:finish).with(finish).and_return(span).ordered
@@ -48,7 +48,7 @@
 
           it 'finishes tracing anyways' do
             expect(tracer).to receive(:trace).with(span_name, options).and_return(span).ordered
-            expect(span).to receive(:start_time=).with(start).and_return(span).ordered
+            expect(span).to receive(:start).with(start).and_return(span).ordered
             expect(tracer).to receive(:active_span).and_return(span).ordered
             expect(span).to receive(:finish).with(finish).and_return(span).ordered
             is_expected.to be(span)