Spans carry a parent span id and share their parent's trace id. A Trace holds one thread of work's open spans (one UI program, one import), so what starts through it nests under the innermost; work on another goroutine takes a Parent. OTLP spans get parentSpanId and the JSON log gets trace_id, span_id and parent_id. Off, every call is still one atomic load and no allocation.
- commit
- 801c083827a1b477e7e3c620aecd55456857c87e
- parent
- b3b18788dd38b27dbe98c5036df21e7fd845ba30
- author
- Dami <dami.etoile@gmail.com>
| M | internal/ | 2 | +- |
| M | internal/ | 28 | +-- |
| M | internal/ | 24 | +++ |
| M | internal/ | 1 | + |
| M | internal/ | 9 | +- |
| M | internal/ | 80 | +------- |
| A | internal/ | 281 | ++++++++++++++++++++++++++++++ |
| A | internal/ | 181 | +++++++++++++++++++ |
@@ -94,7 +94,7 @@ func summarize(since, now time.Time, render, keys []time.Duration, gauges map[st
9494 for _, k := range slices.Sorted(maps.Keys(gauges)) {9595 attrs = append(attrs, slog.Int64(k, gauges[k]))9696 }97- emit(slog.LevelInfo, "frames", window, attrs, false)97+ emit(slog.LevelInfo, "frames", window, attrs, spanIDs{})9898 if _, e := current(); e != nil && e.urls.metrics != "" {9999 e.window(frameWindow{start: since, end: now, render: r, key: k, heap: heap, gauges: gauges})100100 }@@ -127,24 +127,10 @@ func randomBytes(b []byte) {
127127 }128128 }129129 130-func newIDs() (traceID, spanID) {131- var t traceID132- var s spanID133- for t.IsZero() {134- randomBytes(t[:])135- }136- for s.IsZero() {137- randomBytes(s[:])138- }139- return t, s140-}141-142-// span records a finished operation: a span when traces are on, and its143-// duration in the operation histogram when metrics are. It returns the144-// span's ids for the log record that goes with it. attrs is not kept.145-func (e *exporter) span(name string, start, end time.Time, failed bool, attrs []slog.Attr) (traceID, spanID) {146- var t traceID147- var s spanID130+// span records a finished operation: a span with ids when traces are on,131+// and its duration in the operation histogram when metrics are. attrs is132+// not kept.133+func (e *exporter) span(name string, start, end time.Time, failed bool, attrs []slog.Attr, ids spanIDs) {148134 if e.urls.metrics != "" {149135 e.mu.Lock()150136 h := e.ops[name]@@ -157,11 +143,10 @@ func (e *exporter) span(name string, start, end time.Time, failed bool, attrs []
157143 e.mu.Unlock()158144 }159145 if e.urls.traces == "" {160- return t, s146+ return161147 }162- t, s = newIDs()163148 sp := spanData{164- TraceID: t, SpanID: s, Name: name, Kind: spanKindInternal,149+ TraceID: ids.trace, SpanID: ids.span, ParentSpanID: ids.parent, Name: name, Kind: spanKindInternal,165150 StartTimeUnixNano: nanos(start), EndTimeUnixNano: nanos(end),166151 Attributes: attrsOf(attrs),167152 Status: status{Code: statusOK},@@ -184,7 +169,6 @@ func (e *exporter) span(name string, start, end time.Time, failed bool, attrs []
184169 n := len(e.spans)185170 e.mu.Unlock()186171 e.nudge(n)187- return t, s188172 }189173 190174 func (e *exporter) log(r logRecord) {@@ -466,3 +466,27 @@ func BenchmarkSpanOTLP(b *testing.B) {
466466 s.End(slog.Int("cells", 2))467467 }468468 }469+470+// Nested spans go out with their parent's span id and trace id; roots471+// without a parentSpanId.472+func TestOTLPNestedSpans(t *testing.T) {473+ c := newCollector(t)474+ otlpSetup(t, OTLPConfig{Endpoint: c.srv.URL})475+ tr := &Trace{}476+ cmd := tr.Start("command")477+ tr.Begin("recalc")478+ tr.End()479+ cmd.End()480+ Close()481+ spans, _ := c.items("/v1/traces")482+ if len(spans) != 2 {483+ t.Fatalf("%d spans: %v", len(spans), spans)484+ }485+ recalc, command := spans[0], spans[1]486+ if recalc["parentSpanId"] != command["spanId"] || recalc["traceId"] != command["traceId"] || !hexSpan.MatchString(recalc["parentSpanId"].(string)) {487+ t.Errorf("recalc %v is not under command %v", recalc, command)488+ }489+ if _, ok := command["parentSpanId"]; ok {490+ t.Errorf("root span with a parent: %v", command)491+ }492+}@@ -183,6 +183,7 @@ const (
183183 type spanData struct {184184 TraceID traceID `json:"traceId"`185185 SpanID spanID `json:"spanId"`186+ ParentSpanID spanID `json:"parentSpanId,omitzero"`186187 Name string `json:"name"`187188 Kind int `json:"kind"`188189 StartTimeUnixNano u64 `json:"startTimeUnixNano"`@@ -7,15 +7,10 @@ import (
77 "time"88 )99 10-// spanKey carries a span's ids from log to the OTLP log handler, so the11-// log record of an operation links to its span.10+// spanKey carries a span's ids (spanIDs) from emit to the log handlers,11+// so the log record of an operation links to its span.1212 type spanKey struct{}1313 14-type spanIDs struct {15- trace traceID16- span spanID17-}18-1914 // otlpHandler is a slog.Handler that queues OTLP log records.2015 type otlpHandler struct {2116 e *exporter@@ -91,8 +91,8 @@ func start(w io.Writer, e *exporter, c Config) {
9191 var hs []slog.Handler9292 if w != nil {9393 // OTLP carries the service in its resource instead.94- hs = append(hs, slog.NewJSONHandler(w, &slog.HandlerOptions{Level: c.Level}).95- WithAttrs([]slog.Attr{slog.String("service", "012")}))94+ hs = append(hs, idsHandler{slog.NewJSONHandler(w, &slog.HandlerOptions{Level: c.Level}).95+ WithAttrs([]slog.Attr{slog.String("service", "012")})})9696 }9797 if e != nil && e.urls.logs != "" {9898 hs = append(hs, &otlpHandler{e: e, level: c.Level})@@ -157,68 +157,13 @@ func Logger() *slog.Logger {
157157 return logger158158 }159159 160-// Span times one operation. The zero Span, returned while off, does161-// nothing. With OTLP on, each span is sent as a root span of its own162-// trace (spans don't nest: call sites pass no context), and the log163-// record of the same event carries its trace and span ids.164-type Span struct {165- name string166- start time.Time167- // attrs holds up to four attributes given to Start, in the Span168- // itself: keeping the variadic slice would move it to the heap at169- // every call site, telemetry on or off.170- attrs [4]slog.Attr171- n int172-}173-174-// Start begins timing an operation named like "recalc" or "import", with175-// up to four attributes known at the start.176-func Start(name string, attrs ...slog.Attr) Span {177- if !on.Load() {178- return Span{}179- }180- s := Span{name: name, start: time.Now()}181- s.n = copy(s.attrs[:], attrs)182- return s183-}184-185-// End logs the operation with its duration in milliseconds and any186-// attributes learned along the way, such as rows read.187-func (s Span) End(attrs ...slog.Attr) {188- if s.name == "" || !on.Load() {189- return190- }191- emit(slog.LevelInfo, s.name, time.Since(s.start), append(s.attrs[:s.n:s.n], attrs...), true)192-}193-194-// Fail ends the span with an error, logged at Warn with its message.195-func (s Span) Fail(err error, attrs ...slog.Attr) {196- if err == nil {197- s.End(attrs...)198- return199- }200- if s.name == "" || !on.Load() {201- return202- }203- attrs = append(append(s.attrs[:s.n:s.n], attrs...), slog.String("error", err.Error()))204- emit(slog.LevelWarn, s.name, time.Since(s.start), attrs, true)205-}206-207-// Event logs a finished operation that took d (a span, for OTLP).208-func Event(name string, d time.Duration, attrs ...slog.Attr) {209- if !on.Load() {210- return211- }212- emit(slog.LevelInfo, name, d, attrs, true)213-}214-215160 // Debug logs a finished operation at Debug level, for events too216161 // frequent to keep by default (and to send as spans).217162 func Debug(name string, d time.Duration, attrs ...slog.Attr) {218163 if !on.Load() {219164 return220165 }221- emit(slog.LevelDebug, name, d, attrs, false)166+ emit(slog.LevelDebug, name, d, attrs, spanIDs{})222167 }223168 224169 // current is the logger and the OTLP exporter (nil unless OTLP is on).@@ -228,22 +173,23 @@ func current() (*slog.Logger, *exporter) {
228173 return logger, exp229174 }230175 231-// emit logs an event that took d and ended now. With span set and OTLP232-// on, it is also a span and a sample of the operation histogram, and its233-// log record carries the span's ids. attrs is not kept.234-func emit(level slog.Level, name string, d time.Duration, attrs []slog.Attr, span bool) {176+// emit logs an event that took d and ended now. With ids set it is a177+// span: its log record carries the ids, and with OTLP on it is also sent178+// as a span and a sample of the operation histogram. attrs is not kept.179+func emit(level slog.Level, name string, d time.Duration, attrs []slog.Attr, ids spanIDs) {235180 l, e := current()236- ctx := context.Background()181+ span := !ids.span.IsZero()237182 if span && e != nil {238183 end := time.Now()239- t, s := e.span(name, end.Add(-d), end, level >= slog.LevelWarn, attrs)240- if !t.IsZero() {241- ctx = context.WithValue(ctx, spanKey{}, spanIDs{t, s})242- }184+ e.span(name, end.Add(-d), end, level >= slog.LevelWarn, attrs, ids)243185 }186+ ctx := context.Background()244187 if !l.Enabled(ctx, level) {245188 return246189 }190+ if span {191+ ctx = context.WithValue(ctx, spanKey{}, ids)192+ }247193 all := make([]slog.Attr, 0, len(attrs)+2)248194 all = append(all, slog.String("event", name), slog.Float64("dur_ms", ms(d)))249195 l.LogAttrs(ctx, level, name, append(all, attrs...)...)@@ -0,0 +1,281 @@
1+package telemetry2+3+import (4+ "context"5+ "encoding/hex"6+ "log/slog"7+ "time"8+)9+10+// Spans nest. Every span has a trace id, a span id and, unless it is a11+// root, its parent's span id; a child shares its parent's trace id. No12+// context.Context goes through the engine for it: whoever owns a thread13+// of work (one UI program, one import) keeps a Trace, the spans it has14+// open, and what starts through the Trace nests under the innermost.15+// Work handed to another goroutine (a background tea.Cmd) takes a Parent16+// instead, an explicit handle on the span to nest under. There is no17+// goroutine-global "current span": 012 serve runs many programs in one18+// process, and their commands run on other goroutines.19+20+// Parent identifies a span that others can nest under, from any21+// goroutine. The zero Parent is none: spans under it are roots, each in22+// a trace of its own.23+type Parent struct {24+ trace traceID25+ span spanID26+}27+28+// spanIDs are a span's trace and span ids, and its parent's span id29+// (zero for a root).30+type spanIDs struct {31+ trace traceID32+ span spanID33+ parent spanID34+}35+36+// child makes the ids of a new span under p.37+func (p Parent) child() spanIDs {38+ ids := spanIDs{trace: p.trace, parent: p.span}39+ for ids.trace.IsZero() {40+ randomBytes(ids.trace[:])41+ }42+ for ids.span.IsZero() {43+ randomBytes(ids.span[:])44+ }45+ return ids46+}47+48+// Span times one operation. The zero Span, returned while off, does49+// nothing. With OTLP on it is sent as a span, and the log record of the50+// same event carries its trace, span and parent ids.51+type Span struct {52+ name string53+ start time.Time54+ // attrs holds up to four attributes given to Start, in the Span55+ // itself: keeping the variadic slice would move it to the heap at56+ // every call site, telemetry on or off.57+ attrs [4]slog.Attr58+ n int59+ ids spanIDs60+ tr *Trace // the Trace it is open in, if it was started through one61+}62+63+// Start begins timing an operation named like "recalc" or "import", with64+// up to four attributes known at the start, as a root span.65+func Start(name string, attrs ...slog.Attr) Span {66+ if !on.Load() {67+ return Span{}68+ }69+ return newSpan(Parent{}, name, attrs)70+}71+72+// Start begins a span under p, like the package's Start.73+func (p Parent) Start(name string, attrs ...slog.Attr) Span {74+ if !on.Load() {75+ return Span{}76+ }77+ return newSpan(p, name, attrs)78+}79+80+func newSpan(p Parent, name string, attrs []slog.Attr) Span {81+ s := Span{name: name, start: time.Now(), ids: p.child()}82+ s.n = copy(s.attrs[:], attrs)83+ return s84+}85+86+// Parent is the handle for nesting spans under s; zero for the zero Span.87+func (s Span) Parent() Parent { return Parent{s.ids.trace, s.ids.span} }88+89+// End logs the operation with its duration in milliseconds and any90+// attributes learned along the way, such as rows read. A span started91+// through a Trace is no longer open in it.92+func (s Span) End(attrs ...slog.Attr) {93+ if s.name == "" {94+ return95+ }96+ s.tr.close(s.ids.span)97+ if !on.Load() {98+ return99+ }100+ emit(slog.LevelInfo, s.name, time.Since(s.start), append(s.attrs[:s.n:s.n], attrs...), s.ids)101+}102+103+// Fail ends the span with an error, logged at Warn with its message.104+func (s Span) Fail(err error, attrs ...slog.Attr) {105+ if err == nil {106+ s.End(attrs...)107+ return108+ }109+ if s.name == "" {110+ return111+ }112+ s.tr.close(s.ids.span)113+ if !on.Load() {114+ return115+ }116+ attrs = append(append(s.attrs[:s.n:s.n], attrs...), slog.String("error", err.Error()))117+ emit(slog.LevelWarn, s.name, time.Since(s.start), attrs, s.ids)118+}119+120+// Event logs a finished operation that took d, as a root span.121+func Event(name string, d time.Duration, attrs ...slog.Attr) {122+ if !on.Load() {123+ return124+ }125+ emit(slog.LevelInfo, name, d, attrs, Parent{}.child())126+}127+128+// Event logs a finished operation that took d, as a span under p.129+func (p Parent) Event(name string, d time.Duration, attrs ...slog.Attr) {130+ if !on.Load() {131+ return132+ }133+ emit(slog.LevelInfo, name, d, attrs, p.child())134+}135+136+// Trace is the spans open in one thread of work, innermost last: one UI137+// program's, or one import's. Spans started through it nest under the138+// innermost open span, and stay open in it until they end. It belongs139+// to one goroutine at a time, like the Model or workbook that keeps it.140+// A nil *Trace works too, with nothing open.141+type Trace struct {142+ open []Parent143+ begun []Span // spans started by Begin, for End144+}145+146+// NewTrace returns a Trace with base open, if it isn't zero, beneath147+// everything started through it.148+func NewTrace(base Parent) *Trace {149+ t := &Trace{}150+ if base != (Parent{}) {151+ t.open = append(t.open, base)152+ }153+ return t154+}155+156+// Parent is the innermost span open, zero if none is: the handle to give157+// work done on another goroutine.158+func (t *Trace) Parent() Parent {159+ if t == nil || len(t.open) == 0 {160+ return Parent{}161+ }162+ return t.open[len(t.open)-1]163+}164+165+// Start begins a span under the innermost open one; it is the innermost166+// itself until it ends.167+func (t *Trace) Start(name string, attrs ...slog.Attr) Span {168+ if !on.Load() {169+ return Span{}170+ }171+ s := newSpan(t.Parent(), name, attrs)172+ if t != nil {173+ s.tr = t174+ t.open = append(t.open, s.Parent())175+ }176+ return s177+}178+179+// Event logs a finished operation that took d, under the innermost open180+// span.181+func (t *Trace) Event(name string, d time.Duration, attrs ...slog.Attr) {182+ if !on.Load() {183+ return184+ }185+ emit(slog.LevelInfo, name, d, attrs, t.Parent().child())186+}187+188+// Begin starts a span like Start and keeps it for End, for code that189+// has nowhere to keep a Span, such as the engine's hooks (see cmd/012).190+// On a nil Trace it does nothing.191+func (t *Trace) Begin(name string) {192+ if t == nil || !on.Load() {193+ return194+ }195+ t.begun = append(t.begun, t.Start(name))196+}197+198+// End ends the span last begun by Begin, reporting whether there was one.199+func (t *Trace) End(attrs ...slog.Attr) bool {200+ if t == nil || len(t.begun) == 0 {201+ return false202+ }203+ s := t.begun[len(t.begun)-1]204+ t.begun = t.begun[:len(t.begun)-1]205+ s.End(attrs...)206+ return true207+}208+209+// Enter makes p the innermost open span, until Leave with the depth it210+// returns: for a span that lives across several updates (a macro run, a211+// session) to hold what each of them starts.212+func (t *Trace) Enter(p Parent) int {213+ if t == nil {214+ return 0215+ }216+ n := len(t.open)217+ if p != (Parent{}) {218+ t.open = append(t.open, p)219+ }220+ return n221+}222+223+// Leave closes what was opened since the Enter that returned depth.224+func (t *Trace) Leave(depth int) {225+ if t != nil && depth < len(t.open) {226+ t.open = t.open[:depth]227+ }228+}229+230+// close closes span and anything opened after it that is still open (a231+// span ended out of order, or not at all).232+func (t *Trace) close(span spanID) {233+ if t == nil {234+ return235+ }236+ for i := len(t.open) - 1; i >= 0; i-- {237+ if t.open[i].span == span {238+ t.open = t.open[:i]239+ return240+ }241+ }242+}243+244+// parentKey carries a Parent in a context.Context, where one already245+// goes by, as into an import.246+type parentKey struct{}247+248+// WithParent returns ctx carrying p, for ParentFrom.249+func WithParent(ctx context.Context, p Parent) context.Context {250+ if p == (Parent{}) {251+ return ctx252+ }253+ return context.WithValue(ctx, parentKey{}, p)254+}255+256+// ParentFrom is the Parent ctx carries, zero if none.257+func ParentFrom(ctx context.Context) Parent {258+ p, _ := ctx.Value(parentKey{}).(Parent)259+ return p260+}261+262+// idsHandler adds a span's ids to its record in the JSON log, as263+// trace_id, span_id and, below a root, parent_id, so the file log holds264+// the same tree as the traces.265+type idsHandler struct{ slog.Handler }266+267+func (h idsHandler) Handle(ctx context.Context, r slog.Record) error {268+ if ids, ok := ctx.Value(spanKey{}).(spanIDs); ok {269+ r = r.Clone()270+ r.AddAttrs(slog.String("trace_id", hex.EncodeToString(ids.trace[:])), slog.String("span_id", hex.EncodeToString(ids.span[:])))271+ if !ids.parent.IsZero() {272+ r.AddAttrs(slog.String("parent_id", hex.EncodeToString(ids.parent[:])))273+ }274+ }275+ return h.Handler.Handle(ctx, r)276+}277+278+func (h idsHandler) WithAttrs(as []slog.Attr) slog.Handler {279+ return idsHandler{h.Handler.WithAttrs(as)}280+}281+func (h idsHandler) WithGroup(name string) slog.Handler { return idsHandler{h.Handler.WithGroup(name)} }@@ -0,0 +1,181 @@
1+package telemetry2+3+import (4+ "context"5+ "errors"6+ "io"7+ "log/slog"8+ "testing"9+ "time"10+)11+12+// byEvent indexes the logged events by name; names are unique in these13+// tests.14+func byEvent(t *testing.T, evs []map[string]any) map[string]map[string]any {15+ t.Helper()16+ m := map[string]map[string]any{}17+ for _, ev := range evs {18+ m[ev["event"].(string)] = ev19+ }20+ return m21+}22+23+// childOf checks that child is logged as a span under parent.24+func childOf(t *testing.T, child, parent map[string]any) {25+ t.Helper()26+ if child["parent_id"] == nil || child["parent_id"] != parent["span_id"] || child["trace_id"] != parent["trace_id"] {27+ t.Errorf("%v (parent %v, trace %v) is not under %v (span %v, trace %v)", child["event"], child["parent_id"], child["trace_id"],28+ parent["event"], parent["span_id"], parent["trace_id"])29+ }30+}31+32+func TestTraceNests(t *testing.T) {33+ buf := record(t, slog.LevelInfo)34+ tr := NewTrace(Parent{})35+ cmd := tr.Start("command", slog.String("id", "format.bold"))36+ tr.Begin("recalc")37+ tr.Begin("pivot")38+ tr.Event("jev.cached", time.Millisecond)39+ tr.End(slog.Int("cells", 1))40+ tr.End(slog.Int("cells", 2))41+ p := tr.Parent()42+ done := make(chan struct{})43+ go func() { // work handed to another goroutine44+ p.Start("jev").End()45+ close(done)46+ }()47+ <-done48+ cmd.End()49+ Start("root").End()50+ Event("event", time.Millisecond)51+ if tr.Parent() != (Parent{}) || len(tr.begun) != 0 {52+ t.Errorf("left open: %+v", tr)53+ }54+55+ evs := byEvent(t, events(t, buf))56+ childOf(t, evs["recalc"], evs["command"])57+ childOf(t, evs["pivot"], evs["recalc"])58+ childOf(t, evs["jev.cached"], evs["pivot"])59+ childOf(t, evs["jev"], evs["command"])60+ for _, root := range []string{"command", "root", "event"} {61+ ev := evs[root]62+ if _, ok := ev["parent_id"]; ok || len(ev["trace_id"].(string)) != 32 || len(ev["span_id"].(string)) != 16 {63+ t.Errorf("root %v", ev)64+ }65+ }66+ if evs["root"]["trace_id"] == evs["command"]["trace_id"] || evs["event"]["trace_id"] == evs["root"]["trace_id"] {67+ t.Error("roots share a trace")68+ }69+ if evs["recalc"]["cells"] != 2.0 || evs["pivot"]["cells"] != 1.0 {70+ t.Errorf("End's attributes went to the wrong span: %v %v", evs["recalc"], evs["pivot"])71+ }72+}73+74+// A session's span stays under everything its program starts; a macro's75+// is entered only while its calls are served.76+func TestTraceEnterLeave(t *testing.T) {77+ buf := record(t, slog.LevelInfo)78+ session := Start("serve.session")79+ tr := NewTrace(session.Parent())80+ macro := tr.Start("command", slog.String("id", "macro.run"))81+ run := tr.Parent().Start("macro") // outlives the command82+ macro.End()83+ n := tr.Enter(run.Parent())84+ tr.Start("command", slog.String("id", "set")).End()85+ tr.Leave(n)86+ run.End()87+ tr.Start("after").End()88+ session.End()89+90+ evs := events(t, buf)91+ got := map[string]map[string]any{}92+ for _, ev := range evs {93+ name := ev["event"].(string)94+ if id, ok := ev["id"].(string); ok {95+ name += " " + id96+ }97+ got[name] = ev98+ }99+ childOf(t, got["command macro.run"], got["serve.session"])100+ childOf(t, got["macro"], got["command macro.run"])101+ childOf(t, got["command set"], got["macro"])102+ childOf(t, got["after"], got["serve.session"])103+}104+105+// A span ended out of order closes what was opened after it, so a lost106+// End doesn't leave everything after it nested under a finished span.107+func TestTraceOutOfOrder(t *testing.T) {108+ record(t, slog.LevelInfo)109+ tr := &Trace{}110+ outer := tr.Start("outer")111+ tr.Start("lost") // never ended112+ outer.Fail(errors.New("failed"))113+ if tr.Parent() != (Parent{}) {114+ t.Errorf("still open: %+v", tr.open)115+ }116+ if tr.End() {117+ t.Error("End with nothing begun")118+ }119+ var nilTrace *Trace120+ nilTrace.Begin("recalc")121+ nilTrace.Start("x").End()122+ if nilTrace.End() || nilTrace.Enter(outer.Parent()) != 0 || nilTrace.Parent() != (Parent{}) {123+ t.Error("nil Trace")124+ }125+}126+127+func TestParentInContext(t *testing.T) {128+ record(t, slog.LevelInfo)129+ ctx := context.Background()130+ if WithParent(ctx, Parent{}) != ctx || ParentFrom(ctx) != (Parent{}) {131+ t.Error("zero Parent in a context")132+ }133+ s := Start("import")134+ if ParentFrom(WithParent(ctx, s.Parent())) != s.Parent() {135+ t.Error("Parent lost in a context")136+ }137+}138+139+// Nested spans while off: one atomic load each, nothing kept open.140+func TestTraceOff(t *testing.T) {141+ tr := NewTrace(Parent{})142+ s := tr.Start("command")143+ tr.Begin("recalc")144+ if s.name != "" || s.ids != (spanIDs{}) || len(tr.open) != 0 || len(tr.begun) != 0 {145+ t.Errorf("span while off = %+v, trace %+v", s, tr)146+ }147+ n := testing.AllocsPerRun(100, func() {148+ s := tr.Start("command", slog.String("id", "x"))149+ tr.Begin("recalc")150+ tr.Event("pivot", time.Millisecond, slog.Int("cells", 2))151+ tr.End(slog.Int("cells", 2))152+ tr.Parent().Start("jev").End()153+ d := tr.Enter(s.Parent())154+ tr.Leave(d)155+ s.End()156+ })157+ if n != 0 {158+ t.Errorf("%v allocations per call while off", n)159+ }160+}161+162+// The cost of a span nested under an open one, while off and on.163+func BenchmarkTraceOff(b *testing.B) {164+ tr := &Trace{}165+ for b.Loop() {166+ s := tr.Start("recalc", slog.Int("n", 1))167+ s.End(slog.Int("cells", 2))168+ }169+}170+171+func BenchmarkTraceOn(b *testing.B) {172+ start(io.Discard, nil, Config{})173+ defer Close()174+ tr := &Trace{}175+ cmd := tr.Start("command")176+ defer cmd.End()177+ for b.Loop() {178+ s := tr.Start("recalc", slog.Int("n", 1))179+ s.End(slog.Int("cells", 2))180+ }181+}