From 5e9b0b1fb7ff458c744c66211ba8cf11b901c100 Mon Sep 17 00:00:00 2001 From: Nick Ripley Date: Mon, 23 Oct 2023 09:15:34 -0400 Subject: [PATCH] ddtrace/tracer: encode span IDs in execution traces efficiently (#2268) We were previously encoding span IDs into execution traces as base-10 strings. This is wasteful, in terms of CPU time to encode the ID and more importantly in terms of how much of the limited execution trace data the profiler collects will be taken up by span IDs. They can be encoded directly as 8-byte unsigned integers. --- ddtrace/tracer/exec_tracer_test.go | 95 ++++++++++++++++++++++++++++++ ddtrace/tracer/tracer.go | 8 ++- 2 files changed, 102 insertions(+), 1 deletion(-) create mode 100644 ddtrace/tracer/exec_tracer_test.go diff --git a/ddtrace/tracer/exec_tracer_test.go b/ddtrace/tracer/exec_tracer_test.go new file mode 100644 index 0000000000..0ff8e239f9 --- /dev/null +++ b/ddtrace/tracer/exec_tracer_test.go @@ -0,0 +1,95 @@ +// Unless explicitly stated otherwise all files in this repository are licensed +// under the Apache License Version 2.0. +// This product includes software developed at Datadog (https://www.datadoghq.com/). +// Copyright 2016 Datadog, Inc. + +// Tests in this file rely on parsing execution tracer data, which can change +// formats across Go releases. This guard should be updated as the Go trace +// parser library is upgraded to support new versions. +//go:build !go1.21 + +package tracer + +import ( + "bytes" + "context" + "encoding/binary" + rt "runtime/trace" + "testing" + + "github.com/stretchr/testify/assert" + gotraceui "honnef.co/go/gotraceui/trace" +) + +func TestExecutionTraceSpans(t *testing.T) { + if rt.IsEnabled() { + t.Skip("runtime execution tracing is already enabled") + } + + buf := new(bytes.Buffer) + if err := rt.Start(buf); err != nil { + t.Fatal(err) + } + // Ensure we unconditionally stop tracing. It's safe to call this + // multiple times. + defer rt.Stop() + + _, _, _, stop := startTestTracer(t) + defer stop() + + root, ctx := StartSpanFromContext(context.Background(), "root") + child, _ := StartSpanFromContext(ctx, "child") + root.Finish() + child.Finish() + + rt.Stop() + + execTrace, err := gotraceui.Parse(buf, nil) + if err != nil { + t.Fatalf("parsing trace: %s", err) + } + + type traceSpan struct { + name string + parent string + spanID uint64 + } + + spans := make(map[int]*traceSpan) + for _, ev := range execTrace.Events { + switch ev.Type { + case gotraceui.EvUserTaskCreate: + id := int(ev.Args[0]) + name := execTrace.Strings[ev.Args[2]] + var parent string + if p, ok := spans[int(ev.Args[1])]; ok { + parent = p.name + } + spans[id] = &traceSpan{ + name: name, + parent: parent, + } + case gotraceui.EvUserLog: + id := int(ev.Args[0]) + span, ok := spans[id] + if !ok { + continue + } + key := execTrace.Strings[ev.Args[1]] + if key == "datadog.uint64_span_id" { + span.spanID = binary.LittleEndian.Uint64([]byte(execTrace.Strings[ev.Args[3]])) + } + } + } + + want := []traceSpan{ + {name: "root", spanID: root.Context().SpanID()}, + {name: "child", parent: "root", spanID: child.Context().SpanID()}, + } + var got []traceSpan + for _, v := range spans { + got = append(got, *v) + } + + assert.ElementsMatch(t, want, got) +} diff --git a/ddtrace/tracer/tracer.go b/ddtrace/tracer/tracer.go index 0c333d2d5c..97a948d45d 100644 --- a/ddtrace/tracer/tracer.go +++ b/ddtrace/tracer/tracer.go @@ -7,6 +7,7 @@ package tracer import ( gocontext "context" + "encoding/binary" "os" "runtime/pprof" rt "runtime/trace" @@ -702,7 +703,12 @@ func startExecutionTracerTask(ctx gocontext.Context, span *span) (gocontext.Cont // skipped. ctx = globalinternal.WithExecutionNotTraced(ctx) } - rt.Log(ctx, "span id", strconv.FormatUint(span.SpanID, 10)) + var b [8]byte + binary.LittleEndian.PutUint64(b[:], span.SpanID) + // TODO: can we make string(b[:]) not allocate? e.g. with unsafe + // shenanigans? rt.Log won't retain the message string, though perhaps + // we can't assume that will always be the case. + rt.Log(ctx, "datadog.uint64_span_id", string(b[:])) return ctx, end }