diff --git a/trace/trace.go b/trace/trace.go index 559aebb5..41709779 100644 --- a/trace/trace.go +++ b/trace/trace.go @@ -82,6 +82,10 @@ type traceStep struct { stepTime time.Time msg string fields []Field + // explicit duration override; nil means infer from timestamps + duration *time.Duration + // if true, renders with ||| prefix to indicate concurrent work. + parallel bool } // rLock doesn't need to do anything because traceStep instances are immutable. @@ -94,8 +98,15 @@ func (s traceStep) time() time.Time { func (s traceStep) writeItem(b *bytes.Buffer, formatter string, startTime time.Time, stepThreshold *time.Duration) { stepDuration := s.stepTime.Sub(startTime) + if s.duration != nil { + stepDuration = *s.duration + } + prefix := "---" + if s.parallel { + prefix = "|||" + } if stepThreshold == nil || *stepThreshold == 0 || stepDuration >= *stepThreshold || klogV(4) { - b.WriteString(fmt.Sprintf("%s---", formatter)) + b.WriteString(fmt.Sprintf("%s%s", formatter, prefix)) writeTraceItemSummary(b, s.msg, stepDuration, s.stepTime, s.fields) } } @@ -168,6 +179,18 @@ func (t *Trace) Step(msg string, fields ...Field) { t.traceItems = append(t.traceItems, traceStep{stepTime: time.Now(), msg: msg, fields: fields}) } +// ParallelStep records a step representing concurrent work with an explicit duration. +// The step is rendered with a "|||" prefix to indicate concurrent work. +func (t *Trace) ParallelStep(msg string, d time.Duration, fields ...Field) { + t.lock.Lock() + defer t.lock.Unlock() + if t.traceItems == nil { + // traces almost always have less than 6 steps, do this to avoid more than a single allocation + t.traceItems = make([]traceItem, 0, 6) + } + t.traceItems = append(t.traceItems, traceStep{stepTime: time.Now(), msg: msg, fields: fields, duration: &d, parallel: true}) +} + // Nest adds a nested trace with the given message and fields and returns it. // As a convenience, if the receiver is nil, returns a top level trace. This allows // one to call FromContext(ctx).Nest without having to check if the trace diff --git a/trace/trace_test.go b/trace/trace_test.go index 88fc2d7a..f47188bb 100644 --- a/trace/trace_test.go +++ b/trace/trace_test.go @@ -71,6 +71,72 @@ func TestStep(t *testing.T) { } } +func TestParallelStep(t *testing.T) { + d := 50 * time.Millisecond + + t.Run("State", func(t *testing.T) { + sampleTrace := &Trace{} + sampleTrace.ParallelStep("parallel1", d) + + if len(sampleTrace.traceItems) != 1 { + t.Fatalf("Expected 1 trace item, got %d", len(sampleTrace.traceItems)) + } + + step, ok := sampleTrace.traceItems[0].(traceStep) + if !ok { + t.Fatalf("Expected traceItem to be traceStep") + } + + if step.msg != "parallel1" { + t.Errorf("Expected msg 'parallel1', got %q", step.msg) + } + + if step.duration == nil || *step.duration != d { + t.Errorf("Expected duration %v, got %v", d, step.duration) + } + + if !step.parallel { + t.Errorf("Expected parallel to be true") + } + }) + + t.Run("TimelineAndRendering", func(t *testing.T) { + currentTime := time.Now() + sampleTrace := &Trace{ + name: "TestTrace", + startTime: currentTime, + } + + sampleTrace.traceItems = []traceItem{ + traceStep{stepTime: currentTime.Add(10 * time.Millisecond), msg: "step1"}, + traceStep{stepTime: currentTime.Add(20 * time.Millisecond), msg: "parallel1", duration: &d, parallel: true}, + traceStep{stepTime: currentTime.Add(30 * time.Millisecond), msg: "step2"}, + } + + var buf bytes.Buffer + klog.SetOutput(&buf) + + orig := klogV + klogV = func(_ klog.Level) bool { return true } // Force logging + defer func() { klogV = orig }() + + sampleTrace.endTime = ¤tTime // simulate completion + sampleTrace.logTrace() + + output := buf.String() + + if !strings.Contains(output, `---"step1" 10ms`) { + t.Errorf("Expected output to contain '---\"step1\" 10ms', got:\n%s", output) + } + if !strings.Contains(output, `|||"parallel1" 50ms`) { + t.Errorf("Expected output to contain '|||\"parallel1\" 50ms', got:\n%s", output) + } + if !strings.Contains(output, `---"step2" 10ms`) { + t.Errorf("Expected output to contain '---\"step2\" 10ms', got:\n%s", output) + } + }) +} + func TestNestedTrace(t *testing.T) { tests := []struct { name string