Skip to content

Add entire trace command to find slow performance hooks etc.#652

Merged
Soph merged 23 commits intomainfrom
feat/entire-perf-command
Mar 19, 2026
Merged

Add entire trace command to find slow performance hooks etc.#652
Soph merged 23 commits intomainfrom
feat/entire-perf-command

Conversation

@pfleidi
Copy link
Copy Markdown
Contributor

@pfleidi pfleidi commented Mar 7, 2026

entire trace command

Adds a new entire trace CLI command that displays hook performance traces, and extends the perf/span package with loop iteration tracking.

New command: entire trace

Parses structured perf log entries from .entire/logs/entire.log and renders them as formatted timing tables with hierarchical sub-step breakdowns.

  • entire trace — show the most recent hook trace
  • entire trace --last 5 — show the last 5 traces
  • entire trace --hook post-commit — filter by hook type

Traces require ENTIRE_LOG_LEVEL=DEBUG to be enabled.

Implementation (cmd/entire/cli/trace.go, trace_cmd.go):

  • JSONL log parser that extracts steps.*_ms and steps.*_err keys into a hierarchical step tree
  • Sub-step detection: keys like foo.0, foo.1 are nested under their parent foo when the parent exists
  • ASCII tree rendering (├─/└─) with manual padding to avoid UTF-8 multi-byte alignment issues
  • Input validation on --last flag (must be >= 1)

Example output:

❯ entire trace --hook post-commit --last 2
post-commit  123ms  2026-03-06T16:35:48-08:00

  STEP                        DURATION
  cleanup_shadow_branches         12ms
  find_sessions_for_worktree       0ms
  open_repository_and_head         0ms
  process_sessions               100ms
    ├─ process_sessions.0          3ms
    ├─ process_sessions.1          0ms
    ├─ process_sessions.2         95ms
    └─ process_sessions.3          0ms
  resolve_commit_trees             5ms

perf/span: LoopSpan and child deduplication

Extends the span package to support tracking loop iterations as grouped sub-spans.

  • LoopSpan — wraps a grouping span; Iteration() creates child spans, End() auto-ends unfinished iterations
  • childStepKey() — deduplicates child span names (.1, .2 suffixes) so repeated loop iterations don't overwrite each other in log output
  • Grandchild emission — group spans emit their children as steps.<name>.<index>_ms entries with 0-based indexing

Hook integration

PostCommit in manual_commit_hooks.go now wraps the session processing loop with StartLoop/Iteration/End to emit per-session timing in traces.

pfleidi and others added 8 commits March 6, 2026 13:49
Entire-Checkpoint: 22415ab59f02
Add collectPerfEntries() to read JSONL log files and return the last N
perf entries in newest-first order, with optional hook type filtering.

Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
Entire-Checkpoint: eaf01bcc91eb
Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
Entire-Checkpoint: c3b7ec761aa8
Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
Entire-Checkpoint: e5bf775d5e75
Entire-Checkpoint: c75be2c5408c
Entire-Checkpoint: 2bc23d89214f
Entire-Checkpoint: 7d7c4e94c454
Copilot AI review requested due to automatic review settings March 7, 2026 00:40
@cursor
Copy link
Copy Markdown

cursor bot commented Mar 7, 2026

PR Summary

Medium Risk
Changes perf trace serialization and adds new loop-based spans; incorrect keying or span lifecycles could make perf logs misleading or noisy, and the post-commit hook now does extra tracing work (though only emitted at DEBUG).

Overview
Adds a new entire perf subcommand that reads .entire/logs/entire.log, extracts msg="perf" JSONL entries (including steps.*_ms/*_err), and renders them as a readable timing table with optional --last and --hook filtering plus hierarchical sub-step display.

Extends perf/span logging to preserve duplicate child step names (suffixing .1, .2, …) and to emit grouped loop iteration timings as steps.<name>.<index>_*, then instruments the post-commit session-processing loop to record per-session iteration spans. Includes comprehensive unit tests for parsing/rendering, key de-duplication, and loop span behavior (plus minor test formatting cleanup).

Written by Cursor Bugbot for commit c1c901d. Configure here.

Copy link
Copy Markdown
Contributor

Copilot AI left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

This PR adds a new entire perf CLI command for viewing hook performance traces, extends the perf/span package with loop iteration tracking (LoopSpan), and integrates the new loop span into the PostCommit hook to emit per-session timing data.

Changes:

  • New entire perf command (perf.go, perf_cmd.go) that parses JSONL log entries and renders hierarchical timing tables with sub-step breakdowns
  • New LoopSpan type in perf/span.go with StartLoop/Iteration/End pattern, plus childStepKey deduplication for repeated child span names
  • Integration of LoopSpan in PostCommit hook to track per-session processing times

Reviewed changes

Copilot reviewed 7 out of 8 changed files in this pull request and generated 4 comments.

Show a summary per file
File Description
cmd/entire/cli/perf.go New file: JSONL log parser, sub-step detection, and ASCII table renderer
cmd/entire/cli/perf_cmd.go New file: Cobra command definition for entire perf
cmd/entire/cli/perf_test.go New file: Tests for parsing, collecting, rendering, and flag validation
perf/span.go Adds childStepKey dedup, grandchild emission, LoopSpan type
perf/span_test.go Tests for deduplication, loop span creation, auto-end, and errors
cmd/entire/cli/strategy/manual_commit_hooks.go Wraps session loop with StartLoop/Iteration/End
cmd/entire/cli/root.go Registers newPerfCmd()
cmd/entire/cli/strategy/common_test.go Whitespace formatting cleanup

pfleidi and others added 6 commits March 6, 2026 16:58
Entire-Checkpoint: e6ea5a3d3580
Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com>
Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com>
@pfleidi
Copy link
Copy Markdown
Contributor Author

pfleidi commented Mar 7, 2026

Bugbot run

@pfleidi pfleidi marked this pull request as ready for review March 7, 2026 01:27
@pfleidi pfleidi requested a review from a team as a code owner March 7, 2026 01:27
Copy link
Copy Markdown

@cursor cursor bot left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

✅ Bugbot reviewed your changes and found no new issues!

Comment @cursor review or bugbot run to trigger another review on this PR

Copy link
Copy Markdown
Contributor

Copilot AI left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 7 out of 8 changed files in this pull request and generated no new comments.

Copy link
Copy Markdown
Contributor

@khaong khaong left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

From Claude:

Review

Consolidated review covering 1 must-fix and 3 should-fix items. See inline comments.

Overall the PR is clean — follows project conventions, good test coverage, nice separation of concerns. These are the items worth addressing before merge.

@pfleidi pfleidi changed the title Add entire perf command to find slow performance hooks etc. Add entire trace command to find slow performance hooks etc. Mar 18, 2026
pfleidi added 5 commits March 17, 2026 17:23
Entire-Checkpoint: 667a3f4cd3a2
Increase bufio.Scanner max line size to 1MB in collectTraceEntries
since the shared log file may contain large entries from other
components. Also fix the attrs slice capacity in Span.End() to
account for grandchild attributes, avoiding unnecessary reallocation.

Entire-Checkpoint: e39fa6f2bd3e
- Use ~ separator in childStepKey dedup to avoid collision with
  grandchild . indexing (e.g. steps.foo~1_ms vs steps.foo.1_ms)
- Auto-end iteration children in LoopSpan.End() so durations are
  captured at loop-end time, not deferred to root span
- Use best-effort field extraction in parseTraceEntry: mistyped op,
  duration_ms, or error fields keep zero values instead of discarding
  the entire entry
- Fix test comment: iterations are auto-ended by loop.End(), not
  root.End()

Entire-Checkpoint: 405fd6ef50b1
- Use slices.Sort/SortFunc/Reverse instead of sort package (matches
  codebase conventions)
- Add cheap string pre-filter before full JSON parse to skip
  non-perf log lines without marshalling cost
- Add nolint:errcheck directives for intentional best-effort
  json.Unmarshal calls
- Fix stale comment in span.go (says .1 but code uses ~1)

Entire-Checkpoint: 8efdc71f54f1
Copy link
Copy Markdown
Contributor

Copilot AI left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 7 out of 7 changed files in this pull request and generated 2 comments.


You can also share your feedback on Copilot code review. Take the survey.

pfleidi and others added 2 commits March 18, 2026 11:33
Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com>
@pfleidi pfleidi requested review from khaong and pjbgf March 18, 2026 21:47
@Soph Soph merged commit 8f135d0 into main Mar 19, 2026
3 checks passed
@Soph Soph deleted the feat/entire-perf-command branch March 19, 2026 16:42
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Development

Successfully merging this pull request may close these issues.

5 participants