Avoid unnecessary time.Since() when ending spans if the endTime is already specified

[rueian]

Hi,

When ending a span, I noticed that there might be an unnecessary and expensive time.Since invocation (inside the internal.MonotonicEndTime) that we can avoid:

Saying that I want to instrument the trace and the latency metric at the same time, I would like to make sure I use only two expensive time.Now invocations:

ts1 := time.Now()
ctx, span := tracer.Start(ctx, "myFunc", trace.WithTimestamp(ts1)) 

myFunc(ctx, ...)

ts2 := time.Now()
span.End(trace.WithTimestamp(ts2))
latency.Record(ctx, ts2.Sub(ts1).Milliseconds())

So, if there is a trace.WithTimestamp(ts) passed in while ending the span, we don't need the internal.MonotonicEndTime invocation.

To do that, this PR moves config := trace.NewSpanEndConfig(options...) forward and check if there is a trace.WithTimestamp(ts) passed in and call internal.MonotonicEndTime only when necessary.

[linux-foundation-easycla]

The committers listed above are authorized under a signed CLA.

• ✅ login: rueian / name: Rueian (c6b2456)

[codecov]

Codecov Report

Merging #3143 (b477a5c) into main (ec13377) will decrease coverage by 0.1%.
The diff coverage is 100.0%.

Additional details and impacted files

@@           Coverage Diff           @@
##            main   #3143     +/-   ##
=======================================
- Coverage   79.7%   79.7%   -0.1%     
=======================================
  Files        171     171             
  Lines      12673   12674      +1     
=======================================
- Hits       10105   10104      -1     
- Misses      2355    2357      +2     
  Partials     213     213             

Impacted Files	Coverage Δ
sdk/trace/span.go	87.9% <100.0%> (+<0.1%)	⬆️
sdk/trace/batch_span_processor.go	81.1% <0.0%> (-0.9%)	⬇️

[Aneurysm9]

What other impact can moving the processing of config options before the IsRecording() short-circuit have?

[rueian]

Hi @Aneurysm9, we only have two kinds of SpanEndOption, which are trace.WithStackTrace and trace.WithTimestamp. And the config := trace.NewSpanEndConfig(options...) is allocating on the stack, no GC impact. Therefore the impact will be looping at most two iterations on the options.

[jmacd]

Does anyone understand the comment below this, "now that we have an end time and see if we need to do any more processing."

I can't see why we'd compute the timestamp before the short-circuit.

[MrAlias]

Does anyone understand the comment below this, "now that we have an end time and see if we need to do any more processing."

I can't see why we'd compute the timestamp before the short-circuit.

Because if we didn't the end time would be less accurate.

[griggsca91]

I'm not sure if this is still an issue that is wanting to be done, but I did a small benchmark and got these results with this change (with a much more recent branch)

awesomeProject benchstat old.txt new.txt
goos: darwin
goarch: arm64
pkg: awesomeProject
                                            │   old.txt   │              new.txt               │
                                            │   sec/op    │   sec/op     vs base               │
SpanEnd/span_end_with_timestamp_config-8      726.9n ± 1%   684.0n ± 2%  -5.90% (p=0.000 n=20)
SpanEnd/span_end_without_timestamp_config-8   662.6n ± 4%   672.1n ± 2%       ~ (p=0.147 n=20)
geomean                                       694.0n        678.0n       -2.30%

This is the benchmark I used

https://go.dev/play/p/--mM4hpzckk

Is this something we want to try to proceed with for some small savings?