Skip to content

Commit 6a1dd53

Browse files
committed
sdk/trace: optimize recordingSpan endTime with atomics
Instead of using a mutex, use atomic compare-and-swap to set the endTime. Store unix nanoseconds as an int64 to enable atomics. This has few nice properties: - Span.End() no longer needs the mutex. The first call to Span.End() does an atomic compare-and-swap. Later calls will return early. - We remove the isRecording method and use the public IsRecording method since we don't need the mutex to access endTime. - We reduce the recordingSpan size by 32 bytes. time.Time takes 24 bytes compared to 8 bytes for int64 nanoseconds. We save 16 bytes each for startTime and endTime. Benchstat ``` benchstat private/base2.txt private/new2.txt goos: darwin goarch: arm64 pkg: go.opentelemetry.io/otel/sdk/trace cpu: Apple M2 Max │ private/base2.txt │ private/new2.txt │ │ sec/op │ sec/op vs base │ Truncate/Unlimited-12 0.2089n ± 2% 0.2090n ± 4% ~ (p=0.698 n=10) Truncate/Zero-12 0.3052n ± 1% 0.3087n ± 20% ~ (p=0.127 n=10) Truncate/Short-12 0.2081n ± 0% 0.2089n ± 1% ~ (p=0.362 n=10) Truncate/ASCII-12 0.7140n ± 2% 0.6855n ± 0% -4.00% (p=0.000 n=10) Truncate/ValidUTF-8-12 1.311n ± 2% 1.303n ± 1% -0.61% (p=0.015 n=10) Truncate/InvalidUTF-8-12 9.437n ± 1% 9.315n ± 3% ~ (p=0.143 n=10) Truncate/MixedUTF-8-12 17.32n ± 0% 17.16n ± 2% ~ (p=0.159 n=10) RecordingSpanSetAttributes/WithLimit/false-12 2.080µ ± 1% 2.010µ ± 1% -3.39% (p=0.000 n=10) RecordingSpanSetAttributes/WithLimit/true-12 4.358µ ± 0% 4.297µ ± 0% -1.40% (p=0.000 n=10) SpanEnd-12 107.90n ± 10% 94.44n ± 1% -12.47% (p=0.001 n=10) TraceStart/with_a_simple_span-12 319.5n ± 6% 293.7n ± 3% -8.08% (p=0.000 n=10) TraceStart/with_several_links-12 428.3n ± 2% 411.2n ± 1% -3.99% (p=0.000 n=10) TraceStart/with_attributes-12 469.6n ± 3% 430.4n ± 1% -8.35% (p=0.000 n=10) SpanLimits/AttributeValueLengthLimit-12 4.379µ ± 1% 4.144µ ± 1% -5.38% (p=0.000 n=10) SpanLimits/AttributeCountLimit-12 4.219µ ± 2% 3.909µ ± 1% -7.36% (p=0.000 n=10) SpanLimits/EventCountLimit-12 3.994µ ± 6% 3.663µ ± 1% -8.28% (p=0.000 n=10) SpanLimits/LinkCountLimit-12 3.835µ ± 2% 3.619µ ± 1% -5.63% (p=0.000 n=10) SpanLimits/AttributePerEventCountLimit-12 4.225µ ± 3% 3.961µ ± 1% -6.25% (p=0.000 n=10) SpanLimits/AttributePerLinkCountLimit-12 4.218µ ± 1% 3.951µ ± 1% -6.32% (p=0.000 n=10) SpanSetAttributesOverCapacity-12 1.676µ ± 2% 1.582µ ± 0% -5.58% (p=0.000 n=10) StartEndSpan/AlwaysSample-12 322.3n ± 0% 279.1n ± 0% -13.40% (p=0.000 n=10) StartEndSpan/NeverSample-12 153.5n ± 4% 148.1n ± 0% -3.55% (p=0.000 n=10) SpanWithAttributes_4/AlwaysSample-12 527.6n ± 1% 467.7n ± 0% -11.36% (p=0.000 n=10) SpanWithAttributes_4/NeverSample-12 245.1n ± 0% 227.6n ± 0% -7.14% (p=0.000 n=10) SpanWithAttributes_8/AlwaysSample-12 702.7n ± 2% 638.2n ± 1% -9.19% (p=0.000 n=10) SpanWithAttributes_8/NeverSample-12 336.4n ± 1% 305.0n ± 1% -9.32% (p=0.000 n=10) SpanWithAttributes_all/AlwaysSample-12 593.9n ± 3% 518.8n ± 1% -12.65% (p=0.000 n=10) SpanWithAttributes_all/NeverSample-12 267.0n ± 3% 251.6n ± 0% -5.73% (p=0.000 n=10) SpanWithAttributes_all_2x/AlwaysSample-12 850.2n ± 1% 749.9n ± 0% -11.80% (p=0.000 n=10) SpanWithAttributes_all_2x/NeverSample-12 398.4n ± 2% 350.8n ± 2% -11.95% (p=0.000 n=10) SpanWithEvents_4/AlwaysSample-12 736.3n ± 9% 640.9n ± 0% -12.96% (p=0.000 n=10) SpanWithEvents_4/NeverSample-12 158.1n ± 3% 149.8n ± 0% -5.25% (p=0.000 n=10) SpanWithEvents_8/AlwaysSample-12 1111.5n ± 1% 995.0n ± 0% -10.48% (p=0.000 n=10) SpanWithEvents_8/NeverSample-12 159.9n ± 2% 153.1n ± 0% -4.28% (p=0.000 n=10) SpanWithEvents_WithStackTrace/AlwaysSample-12 446.3n ± 1% 395.8n ± 0% -11.30% (p=0.000 n=10) SpanWithEvents_WithStackTrace/NeverSample-12 170.4n ± 1% 161.4n ± 0% -5.25% (p=0.000 n=10) SpanWithEvents_WithTimestamp/AlwaysSample-12 441.9n ± 1% 379.1n ± 0% -14.19% (p=0.000 n=10) SpanWithEvents_WithTimestamp/NeverSample-12 196.3n ± 5% 185.2n ± 1% -5.65% (p=0.000 n=10) TraceID_DotString-12 43.07n ± 1% 40.19n ± 0% -6.69% (p=0.000 n=10) SpanID_DotString-12 31.61n ± 1% 32.63n ± 0% +3.23% (p=0.001 n=10) SpanProcessorOnEnd/batch:_10,_spans:_10-12 163.3n ± 3% 162.3n ± 0% -0.64% (p=0.010 n=10) SpanProcessorOnEnd/batch:_10,_spans:_100-12 1.645µ ± 1% 1.624µ ± 0% -1.31% (p=0.000 n=10) SpanProcessorOnEnd/batch:_100,_spans:_10-12 162.2n ± 1% 162.5n ± 0% ~ (p=0.587 n=10) SpanProcessorOnEnd/batch:_100,_spans:_100-12 1.626µ ± 1% 1.623µ ± 0% ~ (p=0.361 n=10) SpanProcessorVerboseLogging-12 6.795µ ± 2% 5.789µ ± 3% -14.81% (p=0.000 n=10) geomean 225.5n 211.6n -6.19% │ private/base2.txt │ private/new2.txt │ │ B/op │ B/op vs base │ Truncate/Unlimited-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ Truncate/Zero-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ Truncate/Short-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ Truncate/ASCII-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ Truncate/ValidUTF-8-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ Truncate/InvalidUTF-8-12 16.00 ± 0% 16.00 ± 0% ~ (p=1.000 n=10) ¹ Truncate/MixedUTF-8-12 32.00 ± 0% 32.00 ± 0% ~ (p=1.000 n=10) ¹ RecordingSpanSetAttributes/WithLimit/false-12 6.891Ki ± 0% 6.859Ki ± 0% -0.45% (p=0.000 n=10) RecordingSpanSetAttributes/WithLimit/true-12 7.023Ki ± 0% 6.992Ki ± 0% -0.44% (p=0.000 n=10) SpanEnd-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ TraceStart/with_a_simple_span-12 528.0 ± 0% 496.0 ± 0% -6.06% (p=0.000 n=10) TraceStart/with_several_links-12 704.0 ± 0% 672.0 ± 0% -4.55% (p=0.000 n=10) TraceStart/with_attributes-12 784.0 ± 0% 752.0 ± 0% -4.08% (p=0.000 n=10) SpanLimits/AttributeValueLengthLimit-12 10.56Ki ± 0% 10.53Ki ± 0% -0.30% (p=0.000 n=10) SpanLimits/AttributeCountLimit-12 9.844Ki ± 0% 9.812Ki ± 0% -0.32% (p=0.000 n=10) SpanLimits/EventCountLimit-12 9.422Ki ± 0% 9.391Ki ± 0% -0.33% (p=0.000 n=10) SpanLimits/LinkCountLimit-12 9.031Ki ± 0% 9.000Ki ± 0% -0.35% (p=0.000 n=10) SpanLimits/AttributePerEventCountLimit-12 10.47Ki ± 0% 10.44Ki ± 0% -0.30% (p=0.000 n=10) SpanLimits/AttributePerLinkCountLimit-12 10.47Ki ± 0% 10.44Ki ± 0% -0.30% (p=0.000 n=10) SpanSetAttributesOverCapacity-12 592.0 ± 0% 560.0 ± 0% -5.41% (p=0.000 n=10) StartEndSpan/AlwaysSample-12 528.0 ± 0% 496.0 ± 0% -6.06% (p=0.000 n=10) StartEndSpan/NeverSample-12 144.0 ± 0% 144.0 ± 0% ~ (p=1.000 n=10) ¹ SpanWithAttributes_4/AlwaysSample-12 1040.0 ± 0% 1008.0 ± 0% -3.08% (p=0.000 n=10) SpanWithAttributes_4/NeverSample-12 400.0 ± 0% 400.0 ± 0% ~ (p=1.000 n=10) ¹ SpanWithAttributes_8/AlwaysSample-12 1.516Ki ± 0% 1.484Ki ± 0% -2.06% (p=0.000 n=10) SpanWithAttributes_8/NeverSample-12 656.0 ± 0% 656.0 ± 0% ~ (p=1.000 n=10) ¹ SpanWithAttributes_all/AlwaysSample-12 1.141Ki ± 0% 1.109Ki ± 0% -2.74% (p=0.000 n=10) SpanWithAttributes_all/NeverSample-12 464.0 ± 0% 464.0 ± 0% ~ (p=1.000 n=10) ¹ SpanWithAttributes_all_2x/AlwaysSample-12 1.891Ki ± 0% 1.859Ki ± 0% -1.65% (p=0.000 n=10) SpanWithAttributes_all_2x/NeverSample-12 848.0 ± 0% 848.0 ± 0% ~ (p=1.000 n=10) ¹ SpanWithEvents_4/AlwaysSample-12 1040.0 ± 0% 1008.0 ± 0% -3.08% (p=0.000 n=10) SpanWithEvents_4/NeverSample-12 144.0 ± 0% 144.0 ± 0% ~ (p=1.000 n=10) ¹ SpanWithEvents_8/AlwaysSample-12 1.641Ki ± 0% 1.609Ki ± 0% -1.90% (p=0.000 n=10) SpanWithEvents_8/NeverSample-12 144.0 ± 0% 144.0 ± 0% ~ (p=1.000 n=10) ¹ SpanWithEvents_WithStackTrace/AlwaysSample-12 624.0 ± 0% 592.0 ± 0% -5.13% (p=0.000 n=10) SpanWithEvents_WithStackTrace/NeverSample-12 160.0 ± 0% 160.0 ± 0% ~ (p=1.000 n=10) ¹ SpanWithEvents_WithTimestamp/AlwaysSample-12 648.0 ± 0% 616.0 ± 0% -4.94% (p=0.000 n=10) SpanWithEvents_WithTimestamp/NeverSample-12 184.0 ± 0% 184.0 ± 0% ~ (p=1.000 n=10) ¹ SpanProcessorOnEnd/batch:_10,_spans:_10-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ SpanProcessorOnEnd/batch:_10,_spans:_100-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ SpanProcessorOnEnd/batch:_100,_spans:_10-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ SpanProcessorOnEnd/batch:_100,_spans:_100-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ SpanProcessorVerboseLogging-12 9.547Ki ± 0% 9.234Ki ± 0% -3.27% (p=0.000 n=10) geomean ² -1.34% ² ¹ all samples are equal ² summaries must be >0 to compute geomean │ private/base2.txt │ private/new2.txt │ │ allocs/op │ allocs/op vs base │ Truncate/Unlimited-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ Truncate/Zero-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ Truncate/Short-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ Truncate/ASCII-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ Truncate/ValidUTF-8-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ Truncate/InvalidUTF-8-12 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ Truncate/MixedUTF-8-12 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ RecordingSpanSetAttributes/WithLimit/false-12 3.000 ± 0% 3.000 ± 0% ~ (p=1.000 n=10) ¹ RecordingSpanSetAttributes/WithLimit/true-12 10.00 ± 0% 10.00 ± 0% ~ (p=1.000 n=10) ¹ SpanEnd-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ TraceStart/with_a_simple_span-12 2.000 ± 0% 2.000 ± 0% ~ (p=1.000 n=10) ¹ TraceStart/with_several_links-12 3.000 ± 0% 3.000 ± 0% ~ (p=1.000 n=10) ¹ TraceStart/with_attributes-12 4.000 ± 0% 4.000 ± 0% ~ (p=1.000 n=10) ¹ SpanLimits/AttributeValueLengthLimit-12 41.00 ± 0% 41.00 ± 0% ~ (p=1.000 n=10) ¹ SpanLimits/AttributeCountLimit-12 38.00 ± 0% 38.00 ± 0% ~ (p=1.000 n=10) ¹ SpanLimits/EventCountLimit-12 35.00 ± 0% 35.00 ± 0% ~ (p=1.000 n=10) ¹ SpanLimits/LinkCountLimit-12 35.00 ± 0% 35.00 ± 0% ~ (p=1.000 n=10) ¹ SpanLimits/AttributePerEventCountLimit-12 38.00 ± 0% 38.00 ± 0% ~ (p=1.000 n=10) ¹ SpanLimits/AttributePerLinkCountLimit-12 38.00 ± 0% 38.00 ± 0% ~ (p=1.000 n=10) ¹ SpanSetAttributesOverCapacity-12 3.000 ± 0% 3.000 ± 0% ~ (p=1.000 n=10) ¹ StartEndSpan/AlwaysSample-12 2.000 ± 0% 2.000 ± 0% ~ (p=1.000 n=10) ¹ StartEndSpan/NeverSample-12 2.000 ± 0% 2.000 ± 0% ~ (p=1.000 n=10) ¹ SpanWithAttributes_4/AlwaysSample-12 4.000 ± 0% 4.000 ± 0% ~ (p=1.000 n=10) ¹ SpanWithAttributes_4/NeverSample-12 3.000 ± 0% 3.000 ± 0% ~ (p=1.000 n=10) ¹ SpanWithAttributes_8/AlwaysSample-12 4.000 ± 0% 4.000 ± 0% ~ (p=1.000 n=10) ¹ SpanWithAttributes_8/NeverSample-12 3.000 ± 0% 3.000 ± 0% ~ (p=1.000 n=10) ¹ SpanWithAttributes_all/AlwaysSample-12 4.000 ± 0% 4.000 ± 0% ~ (p=1.000 n=10) ¹ SpanWithAttributes_all/NeverSample-12 3.000 ± 0% 3.000 ± 0% ~ (p=1.000 n=10) ¹ SpanWithAttributes_all_2x/AlwaysSample-12 4.000 ± 0% 4.000 ± 0% ~ (p=1.000 n=10) ¹ SpanWithAttributes_all_2x/NeverSample-12 3.000 ± 0% 3.000 ± 0% ~ (p=1.000 n=10) ¹ SpanWithEvents_4/AlwaysSample-12 5.000 ± 0% 5.000 ± 0% ~ (p=1.000 n=10) ¹ SpanWithEvents_4/NeverSample-12 2.000 ± 0% 2.000 ± 0% ~ (p=1.000 n=10) ¹ SpanWithEvents_8/AlwaysSample-12 6.000 ± 0% 6.000 ± 0% ~ (p=1.000 n=10) ¹ SpanWithEvents_8/NeverSample-12 2.000 ± 0% 2.000 ± 0% ~ (p=1.000 n=10) ¹ SpanWithEvents_WithStackTrace/AlwaysSample-12 4.000 ± 0% 4.000 ± 0% ~ (p=1.000 n=10) ¹ SpanWithEvents_WithStackTrace/NeverSample-12 3.000 ± 0% 3.000 ± 0% ~ (p=1.000 n=10) ¹ SpanWithEvents_WithTimestamp/AlwaysSample-12 5.000 ± 0% 5.000 ± 0% ~ (p=1.000 n=10) ¹ SpanWithEvents_WithTimestamp/NeverSample-12 4.000 ± 0% 4.000 ± 0% ~ (p=1.000 n=10) ¹ SpanProcessorOnEnd/batch:_10,_spans:_10-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ SpanProcessorOnEnd/batch:_10,_spans:_100-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ SpanProcessorOnEnd/batch:_100,_spans:_10-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ SpanProcessorOnEnd/batch:_100,_spans:_100-12 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ SpanProcessorVerboseLogging-12 35.00 ± 0% 35.00 ± 0% ~ (p=1.000 n=10) ¹ geomean ² +0.00% ² ¹ all samples are equal ² summaries must be >0 to compute geomean See open-telemetry#6721.
1 parent 9579111 commit 6a1dd53

File tree

4 files changed

+74
-94
lines changed

4 files changed

+74
-94
lines changed

internal/epoch/nanos.go

Lines changed: 35 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,35 @@
1+
package epoch
2+
3+
import (
4+
"sync/atomic"
5+
"time"
6+
)
7+
8+
// Nanos is the nanoseconds since the Unix epoch.
9+
//
10+
//nolint:recvcheck
11+
type Nanos int64
12+
13+
// NewNanos converts a [time.Time] to Nanos.
14+
func NewNanos(t time.Time) Nanos {
15+
return Nanos(t.UnixNano())
16+
}
17+
18+
// NanosNow returns the current, monotonic time in nanoseconds since the epoch.
19+
func NanosNow() Nanos { return Nanos(time.Now().UnixNano()) }
20+
21+
// ToTime converts the Nanos to a [time.Time].
22+
func (u Nanos) ToTime() time.Time {
23+
return time.Unix(0, int64(u))
24+
}
25+
26+
// SwapIfZero atomically swaps the value of u with new if u is zero.
27+
// Returns true if the value was swapped.
28+
func (u *Nanos) SwapIfZero(ns Nanos) bool {
29+
p := (*int64)(u)
30+
return atomic.CompareAndSwapInt64(p, 0, int64(ns))
31+
}
32+
33+
func (u *Nanos) Load() Nanos {
34+
return Nanos(atomic.LoadInt64((*int64)(u)))
35+
}

sdk/trace/span.go

Lines changed: 26 additions & 87 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ package trace // import "go.opentelemetry.io/otel/sdk/trace"
66
import (
77
"context"
88
"fmt"
9+
"go.opentelemetry.io/otel/internal/epoch"
910
"reflect"
1011
"runtime"
1112
rt "runtime/trace"
@@ -114,11 +115,11 @@ type recordingSpan struct {
114115
name string
115116

116117
// startTime is the time at which this span was started.
117-
startTime time.Time
118+
startTime epoch.Nanos
118119

119-
// endTime is the time at which this span was ended. It contains the zero
120-
// value of time.Time until the span is ended.
121-
endTime time.Time
120+
// endTime is the time at which this span was ended. It contains zero until
121+
// the span is ended.
122+
endTime epoch.Nanos
122123

123124
// status is the status of this span.
124125
status Status
@@ -168,40 +169,19 @@ func (s *recordingSpan) SpanContext() trace.SpanContext {
168169
// IsRecording returns if this span is being recorded. If this span has ended
169170
// this will return false.
170171
func (s *recordingSpan) IsRecording() bool {
171-
if s == nil {
172-
return false
173-
}
174-
s.mu.Lock()
175-
defer s.mu.Unlock()
176-
177-
return s.isRecording()
178-
}
179-
180-
// isRecording returns if this span is being recorded. If this span has ended
181-
// this will return false.
182-
//
183-
// This method assumes s.mu.Lock is held by the caller.
184-
func (s *recordingSpan) isRecording() bool {
185-
if s == nil {
186-
return false
187-
}
188-
return s.endTime.IsZero()
172+
return s != nil && (&s.endTime).Load() == 0
189173
}
190174

191175
// SetStatus sets the status of the Span in the form of a code and a
192176
// description, overriding previous values set. The description is only
193177
// included in the set status when the code is for an error. If this span is
194178
// not being recorded than this method does nothing.
195179
func (s *recordingSpan) SetStatus(code codes.Code, description string) {
196-
if s == nil {
180+
if !s.IsRecording() {
197181
return
198182
}
199-
200183
s.mu.Lock()
201184
defer s.mu.Unlock()
202-
if !s.isRecording() {
203-
return
204-
}
205185
if s.status.Code > code {
206186
return
207187
}
@@ -225,15 +205,12 @@ func (s *recordingSpan) SetStatus(code codes.Code, description string) {
225205
// attributes the span is configured to have, the last added attributes will
226206
// be dropped.
227207
func (s *recordingSpan) SetAttributes(attributes ...attribute.KeyValue) {
228-
if s == nil || len(attributes) == 0 {
208+
if !s.IsRecording() || len(attributes) == 0 {
229209
return
230210
}
231211

232212
s.mu.Lock()
233213
defer s.mu.Unlock()
234-
if !s.isRecording() {
235-
return
236-
}
237214

238215
limit := s.tracer.provider.spanLimits.AttributeCountLimit
239216
if limit == 0 {
@@ -444,24 +421,23 @@ func truncate(limit int, s string) string {
444421
// If this method is called while panicking an error event is added to the
445422
// Span before ending it and the panic is continued.
446423
func (s *recordingSpan) End(options ...trace.SpanEndOption) {
447-
// Do not start by checking if the span is being recorded which requires
448-
// acquiring a lock. Make a minimal check that the span is not nil.
449424
if s == nil {
450425
return
451426
}
452427

453-
// Store the end time as soon as possible to avoid artificially increasing
454-
// the span's duration in case some operation below takes a while.
455-
et := monotonicEndTime(s.startTime)
428+
config := trace.NewSpanEndConfig(options...)
429+
var endTime epoch.Nanos
430+
if config.Timestamp().IsZero() {
431+
endTime = epoch.NanosNow()
432+
} else {
433+
endTime = epoch.NewNanos(config.Timestamp())
434+
}
456435

457-
// Lock the span now that we have an end time and see if we need to do any more processing.
458-
s.mu.Lock()
459-
if !s.isRecording() {
460-
s.mu.Unlock()
436+
// Only the first call to End sets the time using atomic compare-and-swap.
437+
if !(&s.endTime).SwapIfZero(endTime) {
461438
return
462439
}
463440

464-
config := trace.NewSpanEndConfig(options...)
465441
if recovered := recover(); recovered != nil {
466442
// Record but don't stop the panic.
467443
defer panic(recovered)
@@ -482,19 +458,9 @@ func (s *recordingSpan) End(options ...trace.SpanEndOption) {
482458
}
483459

484460
if s.executionTracerTaskEnd != nil {
485-
s.mu.Unlock()
486461
s.executionTracerTaskEnd()
487-
s.mu.Lock()
488462
}
489463

490-
// Setting endTime to non-zero marks the span as ended and not recording.
491-
if config.Timestamp().IsZero() {
492-
s.endTime = et
493-
} else {
494-
s.endTime = config.Timestamp()
495-
}
496-
s.mu.Unlock()
497-
498464
sps := s.tracer.provider.getSpanProcessors()
499465
if len(sps) == 0 {
500466
return
@@ -505,30 +471,17 @@ func (s *recordingSpan) End(options ...trace.SpanEndOption) {
505471
}
506472
}
507473

508-
// monotonicEndTime returns the end time at present but offset from start,
509-
// monotonically.
510-
//
511-
// The monotonic clock is used in subtractions hence the duration since start
512-
// added back to start gives end as a monotonic time. See
513-
// https://golang.org/pkg/time/#hdr-Monotonic_Clocks
514-
func monotonicEndTime(start time.Time) time.Time {
515-
return start.Add(time.Since(start))
516-
}
517-
518474
// RecordError will record err as a span event for this span. An additional call to
519475
// SetStatus is required if the Status of the Span should be set to Error, this method
520476
// does not change the Span status. If this span is not being recorded or err is nil
521477
// than this method does nothing.
522478
func (s *recordingSpan) RecordError(err error, opts ...trace.EventOption) {
523-
if s == nil || err == nil {
479+
if err == nil || !s.IsRecording() {
524480
return
525481
}
526482

527483
s.mu.Lock()
528484
defer s.mu.Unlock()
529-
if !s.isRecording() {
530-
return
531-
}
532485

533486
opts = append(opts, trace.WithAttributes(
534487
semconv.ExceptionType(typeStr(err)),
@@ -564,15 +517,12 @@ func recordStackTrace() string {
564517
// AddEvent adds an event with the provided name and options. If this span is
565518
// not being recorded then this method does nothing.
566519
func (s *recordingSpan) AddEvent(name string, o ...trace.EventOption) {
567-
if s == nil {
520+
if !s.IsRecording() {
568521
return
569522
}
570523

571524
s.mu.Lock()
572525
defer s.mu.Unlock()
573-
if !s.isRecording() {
574-
return
575-
}
576526
s.addEvent(name, o...)
577527
}
578528

@@ -601,15 +551,12 @@ func (s *recordingSpan) addEvent(name string, o ...trace.EventOption) {
601551
// SetName sets the name of this span. If this span is not being recorded than
602552
// this method does nothing.
603553
func (s *recordingSpan) SetName(name string) {
604-
if s == nil {
554+
if s == nil || !s.IsRecording() {
605555
return
606556
}
607557

608558
s.mu.Lock()
609559
defer s.mu.Unlock()
610-
if !s.isRecording() {
611-
return
612-
}
613560
s.name = name
614561
}
615562

@@ -638,15 +585,13 @@ func (s *recordingSpan) SpanKind() trace.SpanKind {
638585
func (s *recordingSpan) StartTime() time.Time {
639586
s.mu.Lock()
640587
defer s.mu.Unlock()
641-
return s.startTime
588+
return s.startTime.ToTime()
642589
}
643590

644591
// EndTime returns the time this span ended. For spans that have not yet
645592
// ended, the returned value will be the zero value of time.Time.
646593
func (s *recordingSpan) EndTime() time.Time {
647-
s.mu.Lock()
648-
defer s.mu.Unlock()
649-
return s.endTime
594+
return (&s.endTime).Load().ToTime()
650595
}
651596

652597
// Attributes returns the attributes of this span.
@@ -740,7 +685,7 @@ func (s *recordingSpan) Resource() *resource.Resource {
740685
}
741686

742687
func (s *recordingSpan) AddLink(link trace.Link) {
743-
if s == nil {
688+
if !s.IsRecording() {
744689
return
745690
}
746691
if !link.SpanContext.IsValid() && len(link.Attributes) == 0 &&
@@ -750,9 +695,6 @@ func (s *recordingSpan) AddLink(link trace.Link) {
750695

751696
s.mu.Lock()
752697
defer s.mu.Unlock()
753-
if !s.isRecording() {
754-
return
755-
}
756698

757699
l := Link{SpanContext: link.SpanContext, Attributes: link.Attributes}
758700

@@ -814,14 +756,14 @@ func (s *recordingSpan) snapshot() ReadOnlySpan {
814756
s.mu.Lock()
815757
defer s.mu.Unlock()
816758

817-
sd.endTime = s.endTime
759+
sd.endTime = s.endTime.ToTime()
818760
sd.instrumentationScope = s.tracer.instrumentationScope
819761
sd.name = s.name
820762
sd.parent = s.parent
821763
sd.resource = s.tracer.provider.resource
822764
sd.spanContext = s.spanContext
823765
sd.spanKind = s.spanKind
824-
sd.startTime = s.startTime
766+
sd.startTime = s.startTime.ToTime()
825767
sd.status = s.status
826768
sd.childSpanCount = s.childSpanCount
827769

@@ -842,15 +784,12 @@ func (s *recordingSpan) snapshot() ReadOnlySpan {
842784
}
843785

844786
func (s *recordingSpan) addChild() {
845-
if s == nil {
787+
if !s.IsRecording() {
846788
return
847789
}
848790

849791
s.mu.Lock()
850792
defer s.mu.Unlock()
851-
if !s.isRecording() {
852-
return
853-
}
854793
s.childSpanCount++
855794
}
856795

sdk/trace/trace_test.go

Lines changed: 7 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1045,7 +1045,7 @@ func TestEndSpanTwice(t *testing.T) {
10451045
}
10461046

10471047
ro := span.(ReadOnlySpan)
1048-
if ro.EndTime() != et1 {
1048+
if !ro.EndTime().Equal(et1) {
10491049
t.Fatalf("2nd call to End() should not modify end time")
10501050
}
10511051
}
@@ -1638,7 +1638,9 @@ func TestReadOnlySpan(t *testing.T) {
16381638
assert.Equal(t, trace.SpanContextFromContext(ctx), ro.SpanContext())
16391639
assert.Equal(t, parent, ro.Parent())
16401640
assert.Equal(t, trace.SpanKindInternal, ro.SpanKind())
1641-
assert.Equal(t, st, ro.StartTime())
1641+
if !st.Equal(ro.StartTime()) {
1642+
t.Errorf("StartTime should be set from timestamp")
1643+
}
16421644
assert.True(t, ro.EndTime().IsZero())
16431645
assert.Equal(t, kv.Key, ro.Attributes()[0].Key)
16441646
assert.Equal(t, kv.Value, ro.Attributes()[0].Value)
@@ -1680,7 +1682,9 @@ func TestReadOnlySpan(t *testing.T) {
16801682

16811683
et := st.Add(time.Millisecond)
16821684
s.End(trace.WithTimestamp(et))
1683-
assert.Equal(t, et, ro.EndTime())
1685+
if !et.Equal(ro.EndTime()) {
1686+
t.Errorf("EndTime should be set from timestamp")
1687+
}
16841688
}
16851689

16861690
func TestReadWriteSpan(t *testing.T) {

sdk/trace/tracer.go

Lines changed: 6 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -5,8 +5,8 @@ package trace // import "go.opentelemetry.io/otel/sdk/trace"
55

66
import (
77
"context"
8-
"time"
98

9+
"go.opentelemetry.io/otel/internal/epoch"
1010
"go.opentelemetry.io/otel/sdk/instrumentation"
1111
"go.opentelemetry.io/otel/trace"
1212
"go.opentelemetry.io/otel/trace/embedded"
@@ -122,9 +122,11 @@ func (tr *tracer) newRecordingSpan(
122122
sr SamplingResult,
123123
config *trace.SpanConfig,
124124
) *recordingSpan {
125-
startTime := config.Timestamp()
126-
if startTime.IsZero() {
127-
startTime = time.Now()
125+
var startTime epoch.Nanos
126+
if config.Timestamp().IsZero() {
127+
startTime = epoch.NanosNow()
128+
} else {
129+
startTime = epoch.NewNanos(config.Timestamp())
128130
}
129131

130132
s := &recordingSpan{

0 commit comments

Comments
 (0)