Add ParallelStep method to Trace to support logging concurrent work with an explicit duration

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

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 = &currentTime // 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