diff --git a/cmd/entire/cli/trace.go b/cmd/entire/cli/trace.go index bf2ca7d91a..483c7154a3 100644 --- a/cmd/entire/cli/trace.go +++ b/cmd/entire/cli/trace.go @@ -12,10 +12,13 @@ import ( "strconv" "strings" "time" + + "charm.land/lipgloss/v2" ) // traceStep represents a single timed step within a trace span. -// Group steps (from nested spans) have SubSteps with 0-based iteration numbering. +// Nested spans are represented as SubSteps. Loop iterations keep their numeric +// suffixes in the step name, e.g. "process_sessions.0". type traceStep struct { Name string DurationMs int64 @@ -103,90 +106,99 @@ func parseTraceEntry(line string) *traceEntry { } } - // Separate parent steps from sub-steps. - // A key like "foo.0" is a sub-step of "foo" if "foo" also exists as a parent - // and the last segment is a non-negative integer. - subStepDurations := make(map[string]map[int]int64) // parent -> index -> ms - subStepErrors := make(map[string]map[int]bool) // parent -> index -> err - parentStepDurations := make(map[string]int64) - parentStepErrors := make(map[string]bool) + entry.Steps = buildTraceSteps(stepDurations, stepErrors) + + return entry +} + +type traceStepNode struct { + step traceStep + children []*traceStepNode +} +func buildTraceSteps(stepDurations map[string]int64, stepErrors map[string]bool) []traceStep { + nodes := make(map[string]*traceStepNode, len(stepDurations)) for name, ms := range stepDurations { - if parent, idx, ok := parseSubStepKey(name, stepDurations); ok { - if subStepDurations[parent] == nil { - subStepDurations[parent] = make(map[int]int64) - } - subStepDurations[parent][idx] = ms - if stepErrors[name] { - if subStepErrors[parent] == nil { - subStepErrors[parent] = make(map[int]bool) - } - subStepErrors[parent][idx] = true - } - } else { - parentStepDurations[name] = ms - parentStepErrors[name] = stepErrors[name] + nodes[name] = &traceStepNode{ + step: traceStep{ + Name: name, + DurationMs: ms, + Error: stepErrors[name], + }, } } - // Build steps slice sorted alphabetically by name - steps := make([]traceStep, 0, len(parentStepDurations)) - for name, ms := range parentStepDurations { - step := traceStep{ - Name: name, - DurationMs: ms, - Error: parentStepErrors[name], + roots := make([]*traceStepNode, 0, len(nodes)) + for name, node := range nodes { + parentName, ok := traceStepParent(name, stepDurations) + if !ok { + roots = append(roots, node) + continue } + nodes[parentName].children = append(nodes[parentName].children, node) + } - // Attach sub-steps if any, sorted by numeric index - if subs, ok := subStepDurations[name]; ok { - indices := make([]int, 0, len(subs)) - for idx := range subs { - indices = append(indices, idx) - } - slices.Sort(indices) - - subList := make([]traceStep, 0, len(subs)) - for _, idx := range indices { - subList = append(subList, traceStep{ - Name: fmt.Sprintf("%s.%d", name, idx), - DurationMs: subs[idx], - Error: subStepErrors[name][idx], - }) - } - step.SubSteps = subList + return traceStepNodesToSteps(roots, "") +} + +func traceStepParent(name string, allSteps map[string]int64) (string, bool) { + candidate := name + for { + idx := strings.LastIndex(candidate, ".") + if idx < 0 { + return "", false } + candidate = candidate[:idx] + if _, ok := allSteps[candidate]; ok { + return candidate, true + } + } +} +func traceStepNodesToSteps(nodes []*traceStepNode, parentName string) []traceStep { + sortTraceStepNodes(nodes, parentName) + + steps := make([]traceStep, 0, len(nodes)) + for _, node := range nodes { + step := node.step + step.SubSteps = traceStepNodesToSteps(node.children, step.Name) steps = append(steps, step) } - slices.SortFunc(steps, func(a, b traceStep) int { - return cmp.Compare(a.Name, b.Name) - }) + return steps +} - entry.Steps = steps +func sortTraceStepNodes(nodes []*traceStepNode, parentName string) { + slices.SortFunc(nodes, func(a, b *traceStepNode) int { + if parentName == "" { + return cmp.Compare(a.step.Name, b.step.Name) + } - return entry + aIdx, aNumeric := traceStepChildIndex(parentName, a.step.Name) + bIdx, bNumeric := traceStepChildIndex(parentName, b.step.Name) + if aNumeric && bNumeric { + return cmp.Compare(aIdx, bIdx) + } + if aNumeric { + return -1 + } + if bNumeric { + return 1 + } + return cmp.Compare(a.step.Name, b.step.Name) + }) } -// parseSubStepKey checks if a step name like "foo.0" is a sub-step of "foo". -// Returns the parent name, index, and true if it is a sub-step. -// A name is a sub-step if: the last segment after the final "." is a non-negative -// integer AND the parent name exists in allSteps. -func parseSubStepKey(name string, allSteps map[string]int64) (string, int, bool) { - lastDot := strings.LastIndex(name, ".") - if lastDot < 0 { - return "", 0, false +func traceStepChildIndex(parentName, childName string) (int, bool) { + prefix := parentName + "." + if !strings.HasPrefix(childName, prefix) { + return 0, false } - parent := name[:lastDot] - suffix := name[lastDot+1:] + suffix := strings.TrimPrefix(childName, prefix) idx, err := strconv.Atoi(suffix) if err != nil || idx < 0 { - return "", 0, false - } - if _, exists := allSteps[parent]; !exists { - return "", 0, false + return 0, false } - return parent, idx, true + return idx, true } // collectTraceEntries reads a JSONL log file and returns the last N trace entries, @@ -247,7 +259,6 @@ func renderTraceEntries(w io.Writer, entries []traceEntry) { fmt.Fprintln(w) } - // Header line: op duration [timestamp] header := fmt.Sprintf("%s %dms", entry.Op, entry.DurationMs) if !entry.Time.IsZero() { header += " " + entry.Time.Format(time.RFC3339) @@ -259,53 +270,57 @@ func renderTraceEntries(w io.Writer, entries []traceEntry) { continue } - // Compute max name display width (at least len("STEP")). - // Sub-steps are indented 5 extra display columns relative to parent rows - // (" " + "├─ " = 7 display cols vs " " = 2 display cols). - const subExtraIndent = 5 - nameWidth := len("STEP") - for _, s := range entry.Steps { - if len(s.Name) > nameWidth { - nameWidth = len(s.Name) - } - for _, sub := range s.SubSteps { - if needed := len(sub.Name) + subExtraIndent; needed > nameWidth { - nameWidth = needed - } - } + rows := flattenTraceSteps(entry.Steps) + nameWidth := lipgloss.Width("STEP") + for _, r := range rows { + nameWidth = max(nameWidth, lipgloss.Width(r.label)) } - // Column header - fmt.Fprintf(w, " %-*s %8s\n", nameWidth, "STEP", "DURATION") + renderTraceTableRow(w, nameWidth, "STEP", "DURATION", false) + for _, r := range rows { + renderTraceTableRow(w, nameWidth, r.label, fmt.Sprintf("%dms", r.durationMs), r.err) + } + } +} - // Step rows - for _, s := range entry.Steps { - dur := fmt.Sprintf("%dms", s.DurationMs) - line := fmt.Sprintf(" %-*s %8s", nameWidth, s.Name, dur) - if s.Error { - line += " x" - } - fmt.Fprintln(w, line) - - // Sub-step rows with ASCII tree connectors. - // Pad manually to avoid multi-byte UTF-8 box-drawing chars - // (├─, └─) breaking Go's byte-based %-*s alignment. - for i, sub := range s.SubSteps { - connector := "├─" - if i == len(s.SubSteps)-1 { - connector = "└─" - } - subDur := fmt.Sprintf("%dms", sub.DurationMs) - pad := nameWidth - subExtraIndent - len(sub.Name) - if pad < 0 { - pad = 0 - } - subLine := fmt.Sprintf(" %s %s%s %8s", connector, sub.Name, strings.Repeat(" ", pad), subDur) - if sub.Error { - subLine += " x" - } - fmt.Fprintln(w, subLine) - } +type traceRenderRow struct { + label string + durationMs int64 + err bool +} + +func flattenTraceSteps(steps []traceStep) []traceRenderRow { + var rows []traceRenderRow + for _, s := range steps { + rows = append(rows, traceRenderRow{label: s.Name, durationMs: s.DurationMs, err: s.Error}) + appendChildRows(&rows, s.SubSteps, " ") + } + return rows +} + +func appendChildRows(rows *[]traceRenderRow, steps []traceStep, prefix string) { + for i, step := range steps { + connector, childPrefix := "├─", prefix+"│ " + if i == len(steps)-1 { + connector, childPrefix = "└─", prefix+" " } + *rows = append(*rows, traceRenderRow{ + label: prefix + connector + " " + step.Name, + durationMs: step.DurationMs, + err: step.Error, + }) + appendChildRows(rows, step.SubSteps, childPrefix) + } +} + +func renderTraceTableRow(w io.Writer, nameWidth int, label, duration string, hasError bool) { + pad := nameWidth - lipgloss.Width(label) + if pad < 0 { + pad = 0 + } + line := fmt.Sprintf(" %s%s %8s", label, strings.Repeat(" ", pad), duration) + if hasError { + line += " x" } + fmt.Fprintln(w, line) } diff --git a/cmd/entire/cli/trace_test.go b/cmd/entire/cli/trace_test.go index 424d6b4490..c009070cea 100644 --- a/cmd/entire/cli/trace_test.go +++ b/cmd/entire/cli/trace_test.go @@ -297,6 +297,62 @@ func TestParseTraceEntry_WithSubSteps(t *testing.T) { } } +func TestParseTraceEntry_WithNestedNamedSpans(t *testing.T) { + t.Parallel() + + line := `{"time":"2026-01-15T10:30:00Z","level":"DEBUG","msg":"perf","op":"why","duration_ms":500,"steps.enrich_commits_ms":300,"steps.enrich_commits.why_checkpoint_info_ms":200,"steps.enrich_commits.why_checkpoint_info.why_checkpoint_read_session_ms":120,"steps.enrich_commits.why_checkpoint_info.why_checkpoint_read_session_err":true,"steps.render_ms":50}` + + entry := parseTraceEntry(line) + if entry == nil { + t.Fatal("parseTraceEntry returned nil") + return + } + + if len(entry.Steps) != 2 { + t.Fatalf("len(Steps) = %d, want 2", len(entry.Steps)) + } + + if entry.Steps[0].Name != "enrich_commits" { + t.Errorf("Steps[0].Name = %q, want %q", entry.Steps[0].Name, "enrich_commits") + } + if entry.Steps[1].Name != "render" { + t.Errorf("Steps[1].Name = %q, want %q", entry.Steps[1].Name, "render") + } + + enrich := entry.Steps[0] + if enrich.DurationMs != 300 { + t.Errorf("enrich.DurationMs = %d, want %d", enrich.DurationMs, 300) + } + if len(enrich.SubSteps) != 1 { + t.Fatalf("enrich should have 1 sub-step, got %d", len(enrich.SubSteps)) + } + + checkpointInfo := enrich.SubSteps[0] + if checkpointInfo.Name != "enrich_commits.why_checkpoint_info" { + t.Errorf("checkpointInfo.Name = %q, want %q", checkpointInfo.Name, "enrich_commits.why_checkpoint_info") + } + if checkpointInfo.DurationMs != 200 { + t.Errorf("checkpointInfo.DurationMs = %d, want %d", checkpointInfo.DurationMs, 200) + } + if checkpointInfo.Error { + t.Error("checkpointInfo.Error = true, want false") + } + if len(checkpointInfo.SubSteps) != 1 { + t.Fatalf("checkpointInfo should have 1 sub-step, got %d", len(checkpointInfo.SubSteps)) + } + + readSession := checkpointInfo.SubSteps[0] + if readSession.Name != "enrich_commits.why_checkpoint_info.why_checkpoint_read_session" { + t.Errorf("readSession.Name = %q, want %q", readSession.Name, "enrich_commits.why_checkpoint_info.why_checkpoint_read_session") + } + if readSession.DurationMs != 120 { + t.Errorf("readSession.DurationMs = %d, want %d", readSession.DurationMs, 120) + } + if !readSession.Error { + t.Error("readSession.Error = false, want true") + } +} + func TestParseTraceEntry_SubStepNumericOrdering(t *testing.T) { t.Parallel() @@ -387,6 +443,55 @@ func TestRenderTraceEntries_WithSubSteps(t *testing.T) { } } +func TestRenderTraceEntries_WithNestedNamedSubSteps(t *testing.T) { + t.Parallel() + + entries := []traceEntry{ + { + Op: "why", + DurationMs: 500, + Steps: []traceStep{ + {Name: "enrich_commits", DurationMs: 300, SubSteps: []traceStep{ + {Name: "enrich_commits.why_checkpoint_info", DurationMs: 200, SubSteps: []traceStep{ + {Name: "enrich_commits.why_checkpoint_info.why_checkpoint_read_session", DurationMs: 120, Error: true}, + }}, + }}, + {Name: "render", DurationMs: 50}, + }, + }, + } + + var buf bytes.Buffer + renderTraceEntries(&buf, entries) + out := buf.String() + + if !strings.Contains(out, "enrich_commits") { + t.Errorf("output missing parent step 'enrich_commits':\n%s", out) + } + if !strings.Contains(out, "├─ enrich_commits.why_checkpoint_info") && + !strings.Contains(out, "└─ enrich_commits.why_checkpoint_info") { + t.Errorf("output missing named nested sub-step with tree connector:\n%s", out) + } + + lines := strings.Split(out, "\n") + foundReadSession := false + foundReadSessionError := false + for _, line := range lines { + if strings.Contains(line, "enrich_commits.why_checkpoint_info.why_checkpoint_read_session") { + foundReadSession = true + if strings.Contains(line, "x") { + foundReadSessionError = true + } + } + } + if !foundReadSession { + t.Errorf("output missing deeper named sub-step:\n%s", out) + } + if !foundReadSessionError { + t.Errorf("output missing error marker on deeper named sub-step:\n%s", out) + } +} + func TestTraceCmd_InvalidLastFlag(t *testing.T) { t.Parallel() diff --git a/perf/span.go b/perf/span.go index ee887979e1..09aeb9f438 100644 --- a/perf/span.go +++ b/perf/span.go @@ -12,15 +12,16 @@ import ( // Span tracks timing for an operation and its substeps. // A Span is not safe for concurrent use from multiple goroutines. type Span struct { - name string - start time.Time - parent *Span - children []*Span - duration time.Duration - attrs []slog.Attr - ctx context.Context - ended bool - err error + name string + start time.Time + parent *Span + children []*Span + duration time.Duration + attrs []slog.Attr + ctx context.Context + ended bool + err error + isLoopIter bool } // Start begins a new span. If ctx already has a span, the new one becomes a child. @@ -64,61 +65,67 @@ func (s *Span) End() { return } - // Build log attributes: op, duration_ms, error flag, then child step durations. - // Component is set via context so it appears exactly once in the log line. logCtx := logging.WithComponent(s.ctx, "perf") - grandchildren := 0 - for _, c := range s.children { - grandchildren += len(c.children) - } - attrs := make([]any, 0, 3+2*len(s.children)+2*grandchildren+len(s.attrs)) + attrs := make([]any, 0, 3+len(s.attrs)+countChildStepAttrs(s)) attrs = append(attrs, slog.String("op", s.name)) attrs = append(attrs, slog.Int64("duration_ms", s.duration.Milliseconds())) if s.err != nil { attrs = append(attrs, slog.Bool("error", true)) } - // Add child step durations (and error flags) as flat keys. - // Disambiguate duplicate child names (from loops) with ~1, ~2, etc. suffixes - // to prevent later values from overwriting earlier ones in JSON output. - // - // Group spans (children that have their own children) also emit grandchildren - // with 0-based indexing: steps..0_ms, steps..1_ms, etc. The ~N - // suffix avoids collisions with this .0, .1, ... iteration indexing. - seen := make(map[string]int, len(s.children)) - for _, child := range s.children { - // Auto-end children that were not explicitly ended + attrs = appendChildStepAttrs(attrs, s, "") + + for _, a := range s.attrs { + attrs = append(attrs, a) + } + + logging.Debug(logCtx, "perf", attrs...) +} + +// appendChildStepAttrs emits the full child timing tree under parent. +// +// Normal children use their span names, with ~N suffixes for duplicate sibling +// names. Loop iterations (from LoopSpan.Iteration) keep the historical numeric +// keys: steps..0_ms, steps..1_ms, etc. +func appendChildStepAttrs(attrs []any, parent *Span, parentKey string) []any { + seen := make(map[string]int, len(parent.children)) + loopIndex := 0 + for _, child := range parent.children { if !child.ended { child.End() } - stepKey := childStepKey(child.name, seen) - key := fmt.Sprintf("steps.%s_ms", stepKey) - attrs = append(attrs, slog.Int64(key, child.duration.Milliseconds())) - if child.err != nil { - errKey := fmt.Sprintf("steps.%s_err", stepKey) - attrs = append(attrs, slog.Bool(errKey, true)) - } - // Emit grandchildren (group iterations) with 0-based indexing - for i, gc := range child.children { - if !gc.ended { - gc.End() - } - gcKey := fmt.Sprintf("steps.%s.%d_ms", stepKey, i) - attrs = append(attrs, slog.Int64(gcKey, gc.duration.Milliseconds())) - if gc.err != nil { - gcErrKey := fmt.Sprintf("steps.%s.%d_err", stepKey, i) - attrs = append(attrs, slog.Bool(gcErrKey, true)) + var stepKey string + if child.isLoopIter && parentKey != "" { + stepKey = fmt.Sprintf("%s.%d", parentKey, loopIndex) + loopIndex++ + } else { + stepKey = childStepKey(child.name, seen) + if parentKey != "" { + stepKey = parentKey + "." + stepKey } } - } - // Add any extra attributes from Start() - for _, a := range s.attrs { - attrs = append(attrs, a) + attrs = append(attrs, slog.Int64("steps."+stepKey+"_ms", child.duration.Milliseconds())) + if child.err != nil { + attrs = append(attrs, slog.Bool("steps."+stepKey+"_err", true)) + } + + attrs = appendChildStepAttrs(attrs, child, stepKey) } + return attrs +} - logging.Debug(logCtx, "perf", attrs...) +func countChildStepAttrs(parent *Span) int { + count := 0 + for _, child := range parent.children { + count++ + if child.err != nil { + count++ + } + count += countChildStepAttrs(child) + } + return count } // childStepKey returns a unique key for a child span name. @@ -161,7 +168,9 @@ func StartLoop(ctx context.Context, name string, attrs ...slog.Attr) (context.Co // Iteration creates a child span for a single loop iteration. The caller must // call End() on the returned span when the iteration completes. func (l *LoopSpan) Iteration(ctx context.Context) (context.Context, *Span) { - return Start(ctx, l.span.name) + ctx, s := Start(ctx, l.span.name) + s.isLoopIter = true + return ctx, s } // End completes the loop span, auto-ending any unended iteration children first diff --git a/perf/span_test.go b/perf/span_test.go index b728f019f8..a1ecb290c9 100644 --- a/perf/span_test.go +++ b/perf/span_test.go @@ -3,6 +3,7 @@ package perf import ( "context" "errors" + "log/slog" "testing" "time" @@ -288,6 +289,96 @@ func TestEnd_DuplicateChildNames_AllPreserved(t *testing.T) { } } +func TestEnd_SerializesLoopIterationsWithNumericKeys(t *testing.T) { + t.Parallel() + + iter0 := testEndedSpan("process_sessions", 100*time.Millisecond) + iter0.isLoopIter = true + iter1 := testEndedSpan("process_sessions", 200*time.Millisecond) + iter1.isLoopIter = true + processSessions := testEndedSpan("process_sessions", 300*time.Millisecond, iter0, iter1) + root := testEndedSpan("post-commit", 350*time.Millisecond, processSessions) + + attrs := testAttrMap(t, appendChildStepAttrs(nil, root, "")) + + require.Equal(t, int64(300), attrs["steps.process_sessions_ms"]) + require.Equal(t, int64(100), attrs["steps.process_sessions.0_ms"]) + require.Equal(t, int64(200), attrs["steps.process_sessions.1_ms"]) +} + +func TestEnd_SerializesNestedNamedSpansWithNames(t *testing.T) { + t.Parallel() + + readSession := testEndedSpan("why_checkpoint_read_session", 120*time.Millisecond) + checkpointInfo := testEndedSpan("why_checkpoint_info", 200*time.Millisecond, readSession) + enrichCommits := testEndedSpan("enrich_commits", 300*time.Millisecond, checkpointInfo) + root := testEndedSpan("why", 500*time.Millisecond, enrichCommits) + + attrs := testAttrMap(t, appendChildStepAttrs(nil, root, "")) + + require.Equal(t, int64(300), attrs["steps.enrich_commits_ms"]) + require.Equal(t, int64(200), attrs["steps.enrich_commits.why_checkpoint_info_ms"]) + require.Equal(t, int64(120), attrs["steps.enrich_commits.why_checkpoint_info.why_checkpoint_read_session_ms"]) + require.NotContains(t, attrs, "steps.enrich_commits.0_ms") +} + +func TestEnd_SerializesDuplicateNestedSiblingNames(t *testing.T) { + t.Parallel() + + firstInfo := testEndedSpan("why_checkpoint_info", 100*time.Millisecond) + secondInfo := testEndedSpan("why_checkpoint_info", 150*time.Millisecond) + enrichCommits := testEndedSpan("enrich_commits", 300*time.Millisecond, firstInfo, secondInfo) + root := testEndedSpan("why", 500*time.Millisecond, enrichCommits) + + attrs := testAttrMap(t, appendChildStepAttrs(nil, root, "")) + + require.Equal(t, int64(100), attrs["steps.enrich_commits.why_checkpoint_info_ms"]) + require.Equal(t, int64(150), attrs["steps.enrich_commits.why_checkpoint_info~1_ms"]) +} + +func TestEnd_SerializesNestedErrorFlags(t *testing.T) { + t.Parallel() + + readSession := testEndedSpan("why_checkpoint_read_session", 120*time.Millisecond) + readSession.err = errors.New("read session failed") + checkpointInfo := testEndedSpan("why_checkpoint_info", 200*time.Millisecond, readSession) + checkpointInfo.err = errors.New("checkpoint info failed") + enrichCommits := testEndedSpan("enrich_commits", 300*time.Millisecond, checkpointInfo) + root := testEndedSpan("why", 500*time.Millisecond, enrichCommits) + + attrs := testAttrMap(t, appendChildStepAttrs(nil, root, "")) + + require.Equal(t, true, attrs["steps.enrich_commits.why_checkpoint_info_err"]) + require.Equal(t, true, attrs["steps.enrich_commits.why_checkpoint_info.why_checkpoint_read_session_err"]) +} + +func testEndedSpan(name string, duration time.Duration, children ...*Span) *Span { + span := &Span{ + name: name, + duration: duration, + ended: true, + children: children, + } + for _, child := range children { + child.parent = span + } + return span +} + +func testAttrMap(t *testing.T, attrs []any) map[string]any { + t.Helper() + + out := make(map[string]any, len(attrs)) + for _, raw := range attrs { + attr, ok := raw.(slog.Attr) + if !ok { + t.Fatalf("attr has type %T, want slog.Attr", raw) + } + out[attr.Key] = attr.Value.Any() + } + return out +} + func TestStartLoop_CreatesGroupSpan(t *testing.T) { t.Parallel() ctx := context.Background()