Refactor span.End()

- Improve accuracy of span duration. Record span end time ASAP. We
  want to measure a user operation as accurately as possible, which
  means we want to mark the end time of a span as soon as possible
  after span.End() is called. Any operations we do inside span.End()
  before storing the end time affect the total duration of the span,
  and although these operations are rather fast at the moment they
  still seem to affect the duration of the span by "artificially"
  adding time between the start and end timestamps. This is relevant
  only in cases where the end time isn't explicitly specified.
- Remove redundant idempotence check. Now that IsRecording() is based
  on the value of span.endTime, IsRecording() will always return
  false after span.End() had been called because span.endTime won't
  be zero. This means we no longer need span.endOnce.
- Improve TestEndSpanTwice so that it also ensures subsequent calls
  to span.End() don't modify the span's end time.

sdk/trace/span.go

@@ -130,9 +130,6 @@ type span struct {
 	// links are stored in FIFO queue capped by configured limit.
 	links *evictedQueue
 
-	// endOnce ensures End is only called once.
-	endOnce sync.Once
-
 	// executionTracerTaskEnd ends the execution tracer span.
 	executionTracerTaskEnd func()
 
@@ -190,6 +187,10 @@ func (s *span) End(options ...trace.SpanOption) {
 		return
 	}
 
+	// Store the end time as soon as possible to avoid artificially increasing
+	// the span's duration in case some operation below takes a while.
+	et := internal.MonotonicEndTime(s.startTime)
+
 	if recovered := recover(); recovered != nil {
 		// Record but don't stop the panic.
 		defer panic(recovered)
@@ -205,27 +206,28 @@ func (s *span) End(options ...trace.SpanOption) {
 	if s.executionTracerTaskEnd != nil {
 		s.executionTracerTaskEnd()
 	}
+
 	if !s.IsRecording() {
 		return
 	}
+
 	config := trace.NewSpanConfig(options...)
-	s.endOnce.Do(func() {
-		s.mu.Lock()
-		if config.Timestamp.IsZero() {
-			s.endTime = internal.MonotonicEndTime(s.startTime)
-		} else {
-			s.endTime = config.Timestamp
-		}
-		s.mu.Unlock()
-
-		sps, ok := s.tracer.provider.spanProcessors.Load().(spanProcessorStates)
-		mustExportOrProcess := ok && len(sps) > 0
-		if mustExportOrProcess {
-			for _, sp := range sps {
-				sp.sp.OnEnd(s)
-			}
+
+	s.mu.Lock()
+	if config.Timestamp.IsZero() {
+		s.endTime = et
+	} else {
+		s.endTime = config.Timestamp
+	}
+	s.mu.Unlock()
+
+	sps, ok := s.tracer.provider.spanProcessors.Load().(spanProcessorStates)
+	mustExportOrProcess := ok && len(sps) > 0
+	if mustExportOrProcess {
+		for _, sp := range sps {
+			sp.sp.OnEnd(s)
 		}
-	})
+	}
 }
 
 func (s *span) RecordError(err error, opts ...trace.EventOption) {

sdk/trace/trace_test.go

@@ -858,12 +858,22 @@ func TestEndSpanTwice(t *testing.T) {
 	te := NewTestExporter()
 	tp := NewTracerProvider(WithSyncer(te))
 
-	span := startSpan(tp, "EndSpanTwice")
-	span.End()
-	span.End()
+	st := time.Now()
+	et1 := st.Add(100 * time.Millisecond)
+	et2 := st.Add(200 * time.Millisecond)
+
+	span := startSpan(tp, "EndSpanTwice", trace.WithTimestamp(st))
+	span.End(trace.WithTimestamp(et1))
+	span.End(trace.WithTimestamp(et2))
+
 	if te.Len() != 1 {
 		t.Fatalf("expected only a single span, got %#v", te.Spans())
 	}
+
+	ro := span.(ReadOnlySpan)
+	if ro.EndTime() != et1 {
+		t.Fatalf("2nd call to End() should not modify end time")
+	}
 }
 
 func TestStartSpanAfterEnd(t *testing.T) {