Add performance instrumentation framework for CLI operations#614
Add performance instrumentation framework for CLI operations#614
Conversation
Introduce the perf package at repo root level for measuring operation latencies. Provides Start/End/Measure API with automatic parent-child span nesting via context propagation. Root spans emit a single DEBUG log line through the existing logging package with the full timing tree flattened as slog attributes. Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com> Entire-Checkpoint: 7995b4435733
Replace the manual time.Now()/LogDuration timing pattern in newAgentHookVerbCmdWithLogging with a perf.Start/span.End root span. This root span will serve as the parent for all child spans added in subsequent instrumentation of lifecycle handlers and strategy methods. Update the corresponding test to check for the perf span log line (msg="perf", op=hookName, duration_ms present) instead of the removed "hook completed" LogDuration entry. Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com> Entire-Checkpoint: 665747ffa1ac
Add perf spans to SessionStart, TurnStart, and TurnEnd handlers. Span variable names reflect what they measure (e.g., detectSpan, extractSpan) and span operation names are derived from the actual code being measured rather than comments. Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com> Entire-Checkpoint: 09854502885a
Add perf spans to measure substeps of the prepare-commit-msg hook: open_repository, find_sessions_for_worktree, filter_sessions_with_content, read_commit_message, resolve_session_metadata, and write_commit_message. TTY confirmation prompts are intentionally excluded from spans since they block on user input and would skew timing measurements. Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com> Entire-Checkpoint: fe39488c5e4b
Add perf spans to measure substeps of SaveStep: open_repository, load_session_state, migrate_shadow_branch, write_temporary_checkpoint, and update_session_state. These nest as grandchildren of the root hook span via the build_and_save_step parent span. Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com> Entire-Checkpoint: 9b052733f137
Instrument the PostCommit hook and its per-session helper with descriptive perf spans to measure substep timing. PostCommit gets spans for open_repository_and_head, find_sessions_for_worktree, resolve_commit_trees, process_sessions, and cleanup_shadow_branches. postCommitProcessSession gets spans for resolve_shadow_branch, check_session_content, transition_and_condense, carry_forward_files, and save_session_state. Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com> Entire-Checkpoint: 4b92e096b173
Add child spans for the two push operations in PrePush: - push_checkpoints_branch wrapping pushSessionsBranchCommon() - push_trails_branch wrapping PushTrailsBranch() These appear as substeps under the root hook span from hook_registry. Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com> Entire-Checkpoint: 5814d9978c73
Entire-Checkpoint: f76dd0cc9ae4
PR SummaryMedium Risk Overview Replaces ad-hoc duration logging in agent hook execution with a root span per hook invocation, and instruments key lifecycle/strategy paths (session start/turn start/turn end, Written by Cursor Bugbot for commit 64dd5d9. Configure here. |
There was a problem hiding this comment.
Cursor Bugbot has reviewed your changes and found 2 potential issues.
Bugbot Autofix prepared fixes for both issues found in the latest run.
- ✅ Fixed: Span ended before error check loses error recording
- In
SaveStep, thewrite_temporary_checkpointspan now recordsWriteTemporaryerrors before ending the span and returning.
- In
- ✅ Fixed: Span ended before error check in PostCommit
- In
PostCommit, thefind_sessions_for_worktreespan now records and handles lookup errors before ending, withEnd()left on the success path.
- In
Or push these changes by commenting:
@cursor push abf8b32088
Preview (abf8b32088)
diff --git a/cmd/entire/cli/strategy/manual_commit_git.go b/cmd/entire/cli/strategy/manual_commit_git.go
--- a/cmd/entire/cli/strategy/manual_commit_git.go
+++ b/cmd/entire/cli/strategy/manual_commit_git.go
@@ -111,10 +111,12 @@
AuthorEmail: step.AuthorEmail,
IsFirstCheckpoint: isFirstCheckpointOfSession,
})
- writeCheckpointSpan.End()
if err != nil {
+ writeCheckpointSpan.RecordError(err)
+ writeCheckpointSpan.End()
return fmt.Errorf("failed to write temporary checkpoint: %w", err)
}
+ writeCheckpointSpan.End()
// If checkpoint was skipped due to deduplication (no changes), return early
if result.Skipped {
diff --git a/cmd/entire/cli/strategy/manual_commit_hooks.go b/cmd/entire/cli/strategy/manual_commit_hooks.go
--- a/cmd/entire/cli/strategy/manual_commit_hooks.go
+++ b/cmd/entire/cli/strategy/manual_commit_hooks.go
@@ -793,14 +793,23 @@
// Find all active sessions for this worktree
sessions, err := s.findSessionsForWorktree(ctx, worktreePath)
+ if err != nil {
+ findSessionsSpan.RecordError(err)
+ findSessionsSpan.End()
+ logging.Warn(logCtx, "post-commit: no active sessions despite trailer",
+ slog.String("strategy", "manual-commit"),
+ slog.String("checkpoint_id", checkpointID.String()),
+ )
+ return nil
+ }
findSessionsSpan.End()
- if err != nil || len(sessions) == 0 {
+ if len(sessions) == 0 {
logging.Warn(logCtx, "post-commit: no active sessions despite trailer",
slog.String("strategy", "manual-commit"),
slog.String("checkpoint_id", checkpointID.String()),
)
- return nil //nolint:nilerr // Intentional: hooks must be silent on failure
+ return nil
}
// Build transition contextComment @cursor review or bugbot run to trigger another review on this PR
| AuthorEmail: step.AuthorEmail, | ||
| IsFirstCheckpoint: isFirstCheckpointOfSession, | ||
| }) | ||
| writeCheckpointSpan.End() |
There was a problem hiding this comment.
Span ended before error check loses error recording
Medium Severity
writeCheckpointSpan.End() is called unconditionally on line 114, before the error from store.WriteTemporary is checked on line 115. If WriteTemporary returns an error, RecordError is never called, so the span's error flag won't appear in the perf log output. Every other span in this PR follows the pattern of calling RecordError(err) then End() on error paths before the happy-path End().
| // Find all active sessions for this worktree | ||
| sessions, err := s.findSessionsForWorktree(ctx, worktreePath) | ||
| findSessionsSpan.End() | ||
|
|
There was a problem hiding this comment.
Span ended before error check in PostCommit
Medium Severity
In PostCommit, findSessionsSpan.End() is called on line 796 immediately after findSessionsForWorktree, before the error is checked on line 798. If findSessionsForWorktree returns an error, RecordError is never called. Contrast this with the same span pattern in PrepareCommitMsg (lines 351–361), which correctly calls RecordError(err) then End() inside the error branch.
There was a problem hiding this comment.
Pull request overview
Adds a new perf span-based instrumentation package and wires it into the CLI hook pipeline to produce structured, per-step timing logs for diagnosing slow git hook operations.
Changes:
- Introduces
perfpackage (context-attached spans, root span emits a single aggregated DEBUG log line). - Replaces ad-hoc hook duration logging with a root perf span in the hook registry.
- Adds span instrumentation and
RecordErrorcalls across lifecycle + manual-commit strategy hook paths.
Reviewed changes
Copilot reviewed 9 out of 9 changed files in this pull request and generated 12 comments.
Show a summary per file
| File | Description |
|---|---|
| perf/context.go | Stores/retrieves the active perf span in context.Context. |
| perf/span.go | Implements spans, step aggregation, and perf log emission. |
| perf/span_test.go | Unit tests for span lifecycle, nesting, durations, and error recording. |
| cmd/entire/cli/hook_registry.go | Starts a root perf span per hook invocation (replacing LogDuration). |
| cmd/entire/cli/hook_registry_test.go | Updates log assertions to expect the perf span log line. |
| cmd/entire/cli/lifecycle.go | Adds perf spans around lifecycle substeps + error recording on return paths. |
| cmd/entire/cli/strategy/manual_commit_hooks.go | Instruments prepare-commit-msg/post-commit flows with per-step spans. |
| cmd/entire/cli/strategy/manual_commit_git.go | Instruments SaveStep with spans for major sub-operations. |
| cmd/entire/cli/strategy/manual_commit_push.go | Instruments pre-push branch push steps with spans. |
Comments suppressed due to low confidence (1)
cmd/entire/cli/strategy/manual_commit_hooks.go:804
findSessionsSpanis ended before checkingerr, and ifs.findSessionsForWorktreefails the span never callsRecordError(err). This means perf logs will show the step as successful even when it errored. Consider movingEnd()after theif err != nilcheck and recording the error before returning.
// Find all active sessions for this worktree
sessions, err := s.findSessionsForWorktree(ctx, worktreePath)
findSessionsSpan.End()
if err != nil || len(sessions) == 0 {
logging.Warn(logCtx, "post-commit: no active sessions despite trailer",
slog.String("strategy", "manual-commit"),
slog.String("checkpoint_id", checkpointID.String()),
)
return nil //nolint:nilerr // Intentional: hooks must be silent on failure
}
| @@ -153,13 +157,6 @@ func newAgentHookVerbCmdWithLogging(agentName types.AgentName, hookName string) | |||
| } | |||
| // Other pass-through hooks (nil event, no special handling) are no-ops | |||
|
|
|||
There was a problem hiding this comment.
The root perf span in newAgentHookVerbCmdWithLogging is always ended via defer span.End(), but it never records hookErr. If DispatchLifecycleEvent/handleClaudeCodePostTodo returns an error, the root perf log won’t show error=true unless errors are also propagated from children. Consider calling span.RecordError(hookErr) before returning when hookErr != nil.
| if hookErr != nil { | |
| span.RecordError(hookErr) | |
| } |
| return nil //nolint:nilerr // Hook must be silent on failure | ||
| openRepoSpan.RecordError(err) | ||
| openRepoSpan.End() | ||
| return nil |
There was a problem hiding this comment.
These hook code paths intentionally swallow errors (return nil) but the nilerr linter is enabled in this repo; without //nolint:nilerr (or another linter-friendly pattern), CI will fail. Please restore the nolint:nilerr annotation (as previously used) for this return nil on error.
| return nil | |
| return nil //nolint:nilerr // intentional: do not block commit if repository cannot be opened |
| return nil //nolint:nilerr // Hook must be silent on failure | ||
| writeCommitMessageSpan.RecordError(err) | ||
| writeCommitMessageSpan.End() | ||
| return nil |
There was a problem hiding this comment.
Same nilerr issue: os.WriteFile failure returns nil without //nolint:nilerr, which will be flagged by the nilerr linter. Add back the nolint (or refactor) to keep the hook silent while passing lint.
| return nil | |
| return fmt.Errorf("failed to write commit message: %w", err) |
| commit, err := repo.CommitObject(head.Hash()) | ||
| if err != nil { | ||
| return nil //nolint:nilerr // Hook must be silent on failure | ||
| openRepoSpan.RecordError(err) | ||
| openRepoSpan.End() | ||
| return nil | ||
| } |
There was a problem hiding this comment.
Same nilerr issue: repo.CommitObject error path returns nil without //nolint:nilerr. Add back the linter suppression or adjust the pattern.
| return nil //nolint:nilerr // Hook must be silent on failure | ||
| findSessionsSpan.RecordError(err) | ||
| findSessionsSpan.End() | ||
| return nil |
There was a problem hiding this comment.
Same nilerr issue: paths.WorktreeRoot failure returns nil inside an error check but lacks //nolint:nilerr. This is expected to be flagged by the nilerr linter.
| return nil | |
| return nil //nolint:nilerr // Intentional: hooks must be silent on failure |
| _, openRepoSpan := perf.Start(ctx, "open_repository_and_head") | ||
| repo, err := OpenRepository(ctx) | ||
| if err != nil { | ||
| return nil //nolint:nilerr // Hook must be silent on failure | ||
| openRepoSpan.RecordError(err) | ||
| openRepoSpan.End() | ||
| return nil | ||
| } |
There was a problem hiding this comment.
Same nilerr issue in PostCommit: returning nil on an OpenRepository error inside if err != nil will be flagged by nilerr. Add //nolint:nilerr (or refactor) so CI passes while keeping hooks fail-open.
| head, err := repo.Head() | ||
| if err != nil { | ||
| return nil //nolint:nilerr // Hook must be silent on failure | ||
| openRepoSpan.RecordError(err) | ||
| openRepoSpan.End() | ||
| return nil | ||
| } |
There was a problem hiding this comment.
Same nilerr issue: repo.Head() error path returns nil without a //nolint:nilerr annotation. This will likely fail golangci-lint.
| writeCheckpointSpan.End() | ||
| if err != nil { | ||
| return fmt.Errorf("failed to write temporary checkpoint: %w", err) | ||
| } |
There was a problem hiding this comment.
writeCheckpointSpan.End() is called before checking err from store.WriteTemporary, so failures won't be captured via RecordError and the span ends even when the operation errors. Record the error (if any) and end the span after the call (or defer End and record before returning).
| writeCheckpointSpan.End() | |
| if err != nil { | |
| return fmt.Errorf("failed to write temporary checkpoint: %w", err) | |
| } | |
| if err != nil { | |
| writeCheckpointSpan.RecordError(err) | |
| writeCheckpointSpan.End() | |
| return fmt.Errorf("failed to write temporary checkpoint: %w", err) | |
| } | |
| writeCheckpointSpan.End() |
| if s.err != nil { | ||
| attrs = append(attrs, slog.Bool("error", true)) | ||
| } | ||
|
|
||
| // Add child step durations (and error flags) as flat keys | ||
| for _, child := range s.children { | ||
| // Auto-end children that were not explicitly ended | ||
| if !child.ended { | ||
| child.ended = true | ||
| child.duration = time.Since(child.start) | ||
| } | ||
| key := fmt.Sprintf("steps.%s_ms", child.name) | ||
| attrs = append(attrs, slog.Int64(key, child.duration.Milliseconds())) | ||
| if child.err != nil { | ||
| errKey := fmt.Sprintf("steps.%s_err", child.name) | ||
| attrs = append(attrs, slog.Bool(errKey, true)) | ||
| } | ||
| } |
There was a problem hiding this comment.
Root span logging only sets error=true when s.err is non-nil, but child spans can record errors without propagating to the root. This can make failed operations look successful at the root level (no error=true) even though steps.*_err flags exist. Consider setting the root error flag when any child span has an error (or propagating the first child error up).
There was a problem hiding this comment.
I think that would make things quite confusing to handle: There might be child-steps that can fail and report errors but doing so isn't going to automatically fail the step that called them. I personally think these things should stay disconnected for the time being and assume that we'd manually report errors on the root level when we need to.
| fn() | ||
| child.End() |
There was a problem hiding this comment.
Span.Measure doesn’t defer child.End(), so if fn() panics the child span may never be ended (and won’t have a meaningful duration/error state). Using defer child.End() (and optionally re-panicking) would make the helper robust.
| fn() | |
| child.End() | |
| defer child.End() | |
| fn() |
…nvestigation # Conflicts: # cmd/entire/cli/lifecycle.go # cmd/entire/cli/strategy/manual_commit_hooks.go
Summary
Add a
perfpackage with span-based performance instrumentation for the Entire CLI's git hook pipeline. This replaces the ad-hocLogDurationapproach with structured, hierarchical timing that captures the full cost breakdown of each hook invocation in a single log line.Why
Hook latency directly impacts developer experience — every
git commitblocks on ourprepare-commit-msgandpost-commithooks. When users report slowness, we need to know which step inside a hook is slow. The previousLogDurationcall only captured total wall time with no per-step breakdown, making it impossible to diagnose bottlenecks from logs alone.More on this can be found here: https://github.com/entirehq/company-knowledge/pull/59
What changed
New
perfpackage (perf/span.go,perf/context.go)perf.Start(ctx, name)returns a child span that nests under the current context's spanEnd()withduration_msand flatsteps.<name>_mskeys for each childRecordError(err)marks a span as errored (first-error-wins semantics); root span output includeserror: trueandsteps.<name>_err: trueflags for failed stepsMeasure(name, fn)convenience for timing a closure as a child spanHook registry (
hook_registry.go)LogDurationwith a rootperf.Start(ctx, hookName)span — all child spans in lifecycle handlers and strategy methods automatically nest under itLifecycle handlers (
lifecycle.go)handleLifecycleTurnStartandhandleLifecycleTurnEnd: transcript preparation, copy, metadata extraction, file change detection, path normalization, step save, etc.RecordErroron all error-return paths (13 call sites)Strategy hooks (
manual_commit_hooks.go)PrepareCommitMsg,PostCommit, andpostCommitProcessSession: repository open, session lookup, content filtering, tree resolution, session processing, shadow branch cleanup, carry-forward, state saveRecordErroron error paths (10 call sites)Strategy git operations (
manual_commit_git.go)SaveStep: repository open, state load, shadow branch migration, checkpoint write, state updateRecordErroron error paths (5 call sites)Strategy push (
manual_commit_push.go)PrePush: checkpoints branch push, trails branch pushRecordErroron error paths (2 call sites)Example log output
With an error:
Test plan
perfpackage: span creation, nesting, duration recording, idempotent End, auto-end children,RecordError(nil no-op, first-error-wins, child error flag in output, no flag by default)mise run fmt && mise run lint && mise run test:cipasses (unit + integration tests with race detector)