From 53ef6067e3fbc12dfd646bc7b3fbec86e8d57418 Mon Sep 17 00:00:00 2001 From: Yahor Yuzefovich Date: Fri, 4 Nov 2022 16:10:40 +0000 Subject: [PATCH] tracing: use timeutil for Now() and Since() MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Previously, for performance reasons (as well as a few others) we used `time.Now()` and `time.Since` in the tracing library. But the work in f782e45fd0da015396bc758e855535a951f2e21a alleviated those concerns, so we can now switch to using `timeutil` library in two places. ``` Tracer_StartSpanCtx/opts=none-24 508ns ± 0% 512ns ± 0% +0.80% (p=0.000 n=10+10) Tracer_StartSpanCtx/opts=real-24 510ns ± 1% 515ns ± 1% +0.96% (p=0.000 n=10+10) Tracer_StartSpanCtx/opts=real,logtag-24 539ns ± 1% 544ns ± 1% +0.90% (p=0.000 n=10+10) Tracer_StartSpanCtx/opts=real,autoparent-24 480ns ± 0% 486ns ± 1% +1.26% (p=0.000 n=10+10) Tracer_StartSpanCtx/opts=real,manualparent-24 523ns ± 1% 527ns ± 1% +0.91% (p=0.004 n=10+10) Tracer_StartSpanCtx/opts=real,autoparent,withEventListener-24 755ns ± 0% 765ns ± 0% +1.40% (p=0.000 n=10+10) Tracer_StartSpanCtx/opts=real,manualparent,withEventListener-24 547ns ± 1% 552ns ± 1% +0.89% (p=0.000 n=10+10) Span_GetRecording/root-only-24 7.36ns ± 0% 6.75ns ± 0% -8.26% (p=0.000 n=10+10) Span_GetRecording/child-only-24 7.36ns ± 0% 6.75ns ± 0% -8.30% (p=0.000 n=10+10) Span_GetRecording/root-child-24 7.36ns ± 0% 6.74ns ± 0% -8.32% (p=0.000 n=10+10) RecordingWithStructuredEvent/with-event-listener-24 3.47µs ± 1% 3.47µs ± 1% ~ (p=0.541 n=10+10) RecordingWithStructuredEvent/without-event-listener-24 3.31µs ± 0% 3.32µs ± 1% ~ (p=0.271 n=10+10) SpanCreation/detached-child=false-24 1.07µs ± 1% 1.07µs ± 1% ~ (p=0.955 n=10+10) SpanCreation/detached-child=true-24 1.84µs ± 1% 1.82µs ± 1% -1.30% (p=0.000 n=10+10) ``` And no changes in allocations. Epic: None Release note: None --- pkg/testutils/lint/lint_test.go | 3 --- pkg/util/tracing/crdbspan.go | 2 +- pkg/util/tracing/tracer.go | 2 +- 3 files changed, 2 insertions(+), 5 deletions(-) diff --git a/pkg/testutils/lint/lint_test.go b/pkg/testutils/lint/lint_test.go index 641016ddd5fd..39feee411d13 100644 --- a/pkg/testutils/lint/lint_test.go +++ b/pkg/testutils/lint/lint_test.go @@ -731,9 +731,6 @@ func TestLint(t *testing.T) { ":!**/embedded.go", ":!util/timeutil/time.go", ":!util/timeutil/zoneinfo.go", - ":!util/tracing/span.go", - ":!util/tracing/crdbspan.go", - ":!util/tracing/tracer.go", ":!cmd/roachtest/tests/gorm_helpers.go", ) if err != nil { diff --git a/pkg/util/tracing/crdbspan.go b/pkg/util/tracing/crdbspan.go index d5a4533dca82..f21d0cecc405 100644 --- a/pkg/util/tracing/crdbspan.go +++ b/pkg/util/tracing/crdbspan.go @@ -854,7 +854,7 @@ func (s *crdbSpan) getRecordingNoChildrenLocked( // -1 indicates an unfinished Span. For a recording it's better to put some // duration in it, otherwise tools get confused. For example, we export // recordings to Jaeger, and spans with a zero duration don't look nice. - rs.Duration = time.Since(rs.StartTime) + rs.Duration = timeutil.Since(rs.StartTime) rs.Finished = false } else { rs.Finished = true diff --git a/pkg/util/tracing/tracer.go b/pkg/util/tracing/tracer.go index cdb0562704ad..0ae5f02b58d2 100644 --- a/pkg/util/tracing/tracer.go +++ b/pkg/util/tracing/tracer.go @@ -1130,7 +1130,7 @@ child operation: %s, tracer created at: opts.LogTags = opts.Parent.i.crdb.logTags } - startTime := time.Now() + startTime := timeutil.Now() // First, create any external spans that we may need (OpenTelemetry, net/trace). // We do this early so that they are available when we construct the main Span,