diff --git a/cmd/entire/cli/hook_registry.go b/cmd/entire/cli/hook_registry.go index 8ffe488ce..0ca44bdae 100644 --- a/cmd/entire/cli/hook_registry.go +++ b/cmd/entire/cli/hook_registry.go @@ -7,7 +7,6 @@ import ( "errors" "fmt" "log/slog" - "time" "github.com/entireio/cli/cmd/entire/cli/agent" "github.com/entireio/cli/cmd/entire/cli/agent/claudecode" @@ -16,6 +15,7 @@ import ( "github.com/entireio/cli/cmd/entire/cli/logging" "github.com/entireio/cli/cmd/entire/cli/paths" "github.com/entireio/cli/cmd/entire/cli/strategy" + "github.com/entireio/cli/perf" "github.com/spf13/cobra" ) @@ -109,8 +109,6 @@ func executeAgentHook(cmd *cobra.Command, agentName types.AgentName, hookName st defer cleanup() } - start := time.Now() - // Initialize logging context with agent name ctx := logging.WithAgent(logging.WithComponent(cmd.Context(), "hooks"), agentName) @@ -119,6 +117,12 @@ func executeAgentHook(cmd *cobra.Command, agentName types.AgentName, hookName st hookType := getHookType(hookName) + // Start root perf span — child spans in lifecycle handlers and strategy + // methods will automatically nest under this span. + ctx, span := perf.Start(ctx, hookName, + slog.String("hook_type", hookType)) + defer span.End() + logging.Debug(ctx, "hook invoked", slog.String("hook", hookName), slog.String("hook_type", hookType), @@ -156,13 +160,7 @@ func executeAgentHook(cmd *cobra.Command, agentName types.AgentName, hookName st } // Other pass-through hooks (nil event, no special handling) are no-ops - logging.LogDuration(ctx, slog.LevelDebug, "hook completed", start, - slog.String("hook", hookName), - slog.String("hook_type", hookType), - slog.String("strategy", strategyName), - slog.Bool("success", hookErr == nil), - ) - + span.RecordError(hookErr) return hookErr } diff --git a/cmd/entire/cli/hook_registry_test.go b/cmd/entire/cli/hook_registry_test.go index f258baf76..7420e0a90 100644 --- a/cmd/entire/cli/hook_registry_test.go +++ b/cmd/entire/cli/hook_registry_test.go @@ -131,9 +131,9 @@ func TestNewAgentHookVerbCmd_LogsInvocation(t *testing.T) { t.Fatal("expected at least one log line") } - // Check for hook invocation log + // Check for hook invocation log and perf span log foundInvocation := false - foundCompletion := false + foundPerfSpan := false for _, line := range lines { var entry map[string]interface{} if err := json.Unmarshal([]byte(line), &entry); err != nil { @@ -141,28 +141,22 @@ func TestNewAgentHookVerbCmd_LogsInvocation(t *testing.T) { continue } - if entry["hook"] == claudecode.HookNameSessionStart { - msg, msgOK := entry["msg"].(string) - if !msgOK { - continue - } - if strings.Contains(msg, "invoked") { - foundInvocation = true - // Verify component is set - if entry["component"] != "hooks" { - t.Errorf("expected component='hooks', got %v", entry["component"]) - } + msg, msgOK := entry["msg"].(string) + + // Hook invocation log: msg="hook invoked", hook="session-start" + if msgOK && entry["hook"] == claudecode.HookNameSessionStart && strings.Contains(msg, "invoked") { + foundInvocation = true + // Verify component is set + if entry["component"] != "hooks" { + t.Errorf("expected component='hooks', got %v", entry["component"]) } - if strings.Contains(msg, "completed") { - foundCompletion = true - // Verify duration_ms is present - if _, ok := entry["duration_ms"]; !ok { - t.Error("expected duration_ms in completion log") - } - // Verify success status - if entry["success"] != true { - t.Errorf("expected success=true, got %v", entry["success"]) - } + } + + // Perf span log: msg="perf", op="session-start", duration_ms present + if msgOK && msg == "perf" && entry["op"] == claudecode.HookNameSessionStart { + foundPerfSpan = true + if _, ok := entry["duration_ms"]; !ok { + t.Error("expected duration_ms in perf span log") } } } @@ -170,8 +164,8 @@ func TestNewAgentHookVerbCmd_LogsInvocation(t *testing.T) { if !foundInvocation { t.Error("expected to find hook invocation log") } - if !foundCompletion { - t.Error("expected to find hook completion log") + if !foundPerfSpan { + t.Error("expected to find perf span log") } } diff --git a/cmd/entire/cli/hooks_git_cmd.go b/cmd/entire/cli/hooks_git_cmd.go index 3d7026865..5cfe1b19b 100644 --- a/cmd/entire/cli/hooks_git_cmd.go +++ b/cmd/entire/cli/hooks_git_cmd.go @@ -3,11 +3,11 @@ package cli import ( "context" "log/slog" - "time" "github.com/entireio/cli/cmd/entire/cli/logging" "github.com/entireio/cli/cmd/entire/cli/settings" "github.com/entireio/cli/cmd/entire/cli/strategy" + "github.com/entireio/cli/perf" "github.com/spf13/cobra" ) @@ -20,16 +20,22 @@ var gitHooksDisabled bool type gitHookContext struct { hookName string ctx context.Context - start time.Time + span *perf.Span strategy *strategy.ManualCommitStrategy } -// newGitHookContext creates a new git hook context with logging initialized. +// newGitHookContext creates a new git hook context with logging and a root perf span. +// The perf span ensures all perf.Start calls in strategy methods become child spans, +// producing a single perf log line per hook with a full timing breakdown. +// Callers must defer g.span.End() to emit the perf log. func newGitHookContext(ctx context.Context, hookName string) *gitHookContext { + ctx = logging.WithComponent(ctx, "hooks") + ctx, span := perf.Start(ctx, hookName, + slog.String("hook_type", "git")) g := &gitHookContext{ hookName: hookName, - start: time.Now(), - ctx: logging.WithComponent(ctx, "hooks"), + ctx: ctx, + span: span, } g.strategy = GetStrategy(ctx) return g @@ -45,16 +51,9 @@ func (g *gitHookContext) logInvoked(extraAttrs ...any) { logging.Debug(g.ctx, g.hookName+" hook invoked", append(attrs, extraAttrs...)...) } -// logCompleted logs hook completion with duration at DEBUG level. -// The actual work logging (checkpoint operations) happens at INFO level in the handlers. -func (g *gitHookContext) logCompleted(err error, extraAttrs ...any) { - attrs := []any{ - slog.String("hook", g.hookName), - slog.String("hook_type", "git"), - slog.String("strategy", strategy.StrategyNameManualCommit), - slog.Bool("success", err == nil), - } - logging.LogDuration(g.ctx, slog.LevelDebug, g.hookName+" hook completed", g.start, append(attrs, extraAttrs...)...) +// logCompleted records the error on the perf span. +func (g *gitHookContext) logCompleted(err error) { + g.span.RecordError(err) } // initHookLogging initializes logging for hooks by finding the most recent session. @@ -134,10 +133,11 @@ func newHooksGitPrepareCommitMsgCmd() *cobra.Command { } g := newGitHookContext(cmd.Context(), "prepare-commit-msg") + defer g.span.End() g.logInvoked(slog.String("source", source)) hookErr := g.strategy.PrepareCommitMsg(g.ctx, commitMsgFile, source) - g.logCompleted(hookErr, slog.String("source", source)) + g.logCompleted(hookErr) return nil }, @@ -157,6 +157,7 @@ func newHooksGitCommitMsgCmd() *cobra.Command { commitMsgFile := args[0] g := newGitHookContext(cmd.Context(), "commit-msg") + defer g.span.End() g.logInvoked() hookErr := g.strategy.CommitMsg(g.ctx, commitMsgFile) @@ -177,6 +178,7 @@ func newHooksGitPostCommitCmd() *cobra.Command { } g := newGitHookContext(cmd.Context(), "post-commit") + defer g.span.End() g.logInvoked() hookErr := g.strategy.PostCommit(g.ctx) @@ -200,10 +202,11 @@ func newHooksGitPrePushCmd() *cobra.Command { remote := args[0] g := newGitHookContext(cmd.Context(), "pre-push") + defer g.span.End() g.logInvoked(slog.String("remote", remote)) hookErr := g.strategy.PrePush(g.ctx, remote) - g.logCompleted(hookErr, slog.String("remote", remote)) + g.logCompleted(hookErr) return nil }, diff --git a/cmd/entire/cli/lifecycle.go b/cmd/entire/cli/lifecycle.go index ca6a92f9a..6c6e0fed9 100644 --- a/cmd/entire/cli/lifecycle.go +++ b/cmd/entire/cli/lifecycle.go @@ -23,6 +23,7 @@ import ( "github.com/entireio/cli/cmd/entire/cli/strategy" "github.com/entireio/cli/cmd/entire/cli/transcript" "github.com/entireio/cli/cmd/entire/cli/validation" + "github.com/entireio/cli/perf" ) // DispatchLifecycleEvent routes a normalized lifecycle event to the appropriate handler. @@ -79,22 +80,28 @@ func handleLifecycleSessionStart(ctx context.Context, ag agent.Agent, event *age message := "\n\nPowered by Entire:\n This conversation will be linked to your next commit." // Check for concurrent sessions and append count if any + _, countSessionsSpan := perf.Start(ctx, "count_active_sessions") strat := GetStrategy(ctx) if count, err := strat.CountOtherActiveSessionsWithCheckpoints(ctx, event.SessionID); err == nil && count > 0 { message += fmt.Sprintf("\n %d other active conversation(s) in this workspace will also be included.\n Use 'entire status' for more information.", count) } + countSessionsSpan.End() // Output informational message if the agent supports hook responses. // Claude Code reads JSON from stdout; agents that don't implement // HookResponseWriter silently skip (avoids raw JSON in their terminal). + _, hookResponseSpan := perf.Start(ctx, "write_hook_response") if event.ResponseMessage != "" { message = event.ResponseMessage } if writer, ok := agent.AsHookResponseWriter(ag); ok { if err := writer.WriteHookResponse(message); err != nil { + hookResponseSpan.RecordError(err) + hookResponseSpan.End() return fmt.Errorf("failed to write hook response: %w", err) } } + hookResponseSpan.End() // Store model hint if the agent provided model info on SessionStart if event.Model != "" { @@ -193,9 +200,13 @@ func handleLifecycleTurnStart(ctx context.Context, ag agent.Agent, event *agent. } // Capture pre-prompt state (including transcript position via TranscriptAnalyzer) + _, captureSpan := perf.Start(ctx, "capture_pre_prompt_state") if err := CapturePrePromptState(ctx, ag, sessionID, event.SessionRef); err != nil { + captureSpan.RecordError(err) + captureSpan.End() return err } + captureSpan.End() // Append prompt to prompt.txt on filesystem so it's available for // mid-turn commits (before SaveStep writes it to the shadow branch). @@ -221,6 +232,7 @@ func handleLifecycleTurnStart(ctx context.Context, ag agent.Agent, event *agent. } // Ensure strategy setup and initialize session + _, initSpan := perf.Start(ctx, "init_session") if err := strategy.EnsureSetup(ctx); err != nil { logging.Warn(logCtx, "failed to ensure strategy setup", slog.String("error", err.Error())) @@ -231,6 +243,7 @@ func handleLifecycleTurnStart(ctx context.Context, ag agent.Agent, event *agent. logging.Warn(logCtx, "failed to initialize session state", slog.String("error", err.Error())) } + initSpan.End() return nil } @@ -272,6 +285,7 @@ func handleLifecycleTurnEnd(ctx context.Context, ag agent.Agent, event *agent.Ev // via `opencode export`, so the file doesn't exist until PrepareTranscript creates it. // Claude Code's PrepareTranscript just flushes (always succeeds). Agents without // TranscriptPreparer (Gemini, Droid) are unaffected. + _, prepareSpan := perf.Start(ctx, "prepare_and_validate_transcript") if preparer, ok := agent.AsTranscriptPreparer(ag); ok { if err := preparer.PrepareTranscript(ctx, transcriptRef); err != nil { logging.Warn(logCtx, "failed to prepare transcript", @@ -280,38 +294,52 @@ func handleLifecycleTurnEnd(ctx context.Context, ag agent.Agent, event *agent.Ev } if !fileExists(transcriptRef) { + prepareSpan.RecordError(fmt.Errorf("transcript file not found: %s", transcriptRef)) + prepareSpan.End() return fmt.Errorf("transcript file not found: %s", transcriptRef) } // Early check: bail out quickly if the repo has no commits yet. if repo, err := strategy.OpenRepository(ctx); err == nil && strategy.IsEmptyRepository(repo) { + prepareSpan.RecordError(strategy.ErrEmptyRepository) + prepareSpan.End() logging.Info(logCtx, "skipping checkpoint - will activate after first commit") return NewSilentError(strategy.ErrEmptyRepository) } + prepareSpan.End() // Create session metadata directory + _, copySpan := perf.Start(ctx, "copy_transcript") sessionDir := paths.SessionMetadataDirFromSessionID(sessionID) sessionDirAbs, err := paths.AbsPath(ctx, sessionDir) if err != nil { sessionDirAbs = sessionDir } if err := os.MkdirAll(sessionDirAbs, 0o750); err != nil { + copySpan.RecordError(err) + copySpan.End() return fmt.Errorf("failed to create session directory: %w", err) } // Copy transcript to session directory transcriptData, err := ag.ReadTranscript(transcriptRef) if err != nil { + copySpan.RecordError(err) + copySpan.End() return fmt.Errorf("failed to read transcript: %w", err) } logFile := filepath.Join(sessionDirAbs, paths.TranscriptFileName) if err := os.WriteFile(logFile, transcriptData, 0o600); err != nil { + copySpan.RecordError(err) + copySpan.End() return fmt.Errorf("failed to write transcript: %w", err) } logging.Debug(logCtx, "copied transcript", slog.String("path", sessionDir+"/"+paths.TranscriptFileName)) + copySpan.End() // Load pre-prompt state (captured on TurnStart) + _, extractSpan := perf.Start(ctx, "extract_metadata") preState, err := LoadPrePromptState(ctx, sessionID) if err != nil { logging.Warn(logCtx, "failed to load pre-prompt state", @@ -347,8 +375,10 @@ func handleLifecycleTurnEnd(ctx context.Context, ag agent.Agent, event *agent.Ev } } } + extractSpan.End() // Generate commit message from last prompt (read from session state, set at TurnStart) + _, commitMsgSpan := perf.Start(ctx, "generate_commit_message") lastPrompt := "" if sessionState, stateErr := strategy.LoadSessionState(ctx, sessionID); stateErr == nil && sessionState != nil { lastPrompt = sessionState.LastPrompt @@ -356,10 +386,14 @@ func handleLifecycleTurnEnd(ctx context.Context, ag agent.Agent, event *agent.Ev commitMessage := generateCommitMessage(lastPrompt, ag.Type()) logging.Debug(logCtx, "using commit message", slog.Int("message_length", len(commitMessage))) + commitMsgSpan.End() // Get worktree root for path normalization + _, detectSpan := perf.Start(ctx, "detect_file_changes") repoRoot, err := paths.WorktreeRoot(ctx) if err != nil { + detectSpan.RecordError(err) + detectSpan.End() return fmt.Errorf("failed to get worktree root: %w", err) } @@ -376,8 +410,10 @@ func handleLifecycleTurnEnd(ctx context.Context, ag agent.Agent, event *agent.Ev logging.Warn(logCtx, "failed to compute file changes", slog.String("error", err.Error())) } + detectSpan.End() // Filter and normalize all paths + _, normalizeSpan := perf.Start(ctx, "filter_and_normalize_paths") relModifiedFiles := FilterAndNormalizePaths(modifiedFiles, repoRoot) var relNewFiles, relDeletedFiles []string if changes != nil { @@ -396,6 +432,7 @@ func handleLifecycleTurnEnd(ctx context.Context, ag agent.Agent, event *agent.Ev // and should not be re-added to FilesTouched by SaveStep. A file is "committed" // if it exists in HEAD with the same content as the working tree. relModifiedFiles = filterToUncommittedFiles(ctx, relModifiedFiles, repoRoot) + normalizeSpan.End() // Check if there are any changes totalChanges := len(relModifiedFiles) + len(relNewFiles) + len(relDeletedFiles) diff --git a/cmd/entire/cli/strategy/manual_commit_git.go b/cmd/entire/cli/strategy/manual_commit_git.go index 99cc4ba97..0f62cfba7 100644 --- a/cmd/entire/cli/strategy/manual_commit_git.go +++ b/cmd/entire/cli/strategy/manual_commit_git.go @@ -14,6 +14,7 @@ import ( "github.com/entireio/cli/cmd/entire/cli/logging" "github.com/entireio/cli/cmd/entire/cli/paths" "github.com/entireio/cli/cmd/entire/cli/trailers" + "github.com/entireio/cli/perf" "github.com/go-git/go-git/v5" ) @@ -21,17 +22,24 @@ import ( // SaveStep saves a checkpoint to the shadow branch. // Uses checkpoint.GitStore.WriteTemporary for git operations. func (s *ManualCommitStrategy) SaveStep(ctx context.Context, step StepContext) error { + _, openRepoSpan := perf.Start(ctx, "open_repository") repo, err := OpenRepository(ctx) if err != nil { + openRepoSpan.RecordError(err) + openRepoSpan.End() return fmt.Errorf("failed to open git repository: %w", err) } + openRepoSpan.End() // Extract session ID from metadata dir sessionID := filepath.Base(step.MetadataDir) // Load or initialize session state + _, loadStateSpan := perf.Start(ctx, "load_session_state") state, err := s.loadSessionState(ctx, sessionID) if err != nil { + loadStateSpan.RecordError(err) + loadStateSpan.End() return fmt.Errorf("failed to load session state: %w", err) } // Initialize if state is nil OR BaseCommit is empty (can happen with partial state from warnings) @@ -39,14 +47,21 @@ func (s *ManualCommitStrategy) SaveStep(ctx context.Context, step StepContext) e agentType := resolveAgentType(step.AgentType, state) state, err = s.initializeSession(ctx, repo, sessionID, agentType, "", "", "") // No transcript/prompt/model in fallback if err != nil { + loadStateSpan.RecordError(err) + loadStateSpan.End() return fmt.Errorf("failed to initialize session: %w", err) } } + loadStateSpan.End() // Check if HEAD has changed (e.g., Claude did a rebase via tool call) and migrate if needed + _, migrateSpan := perf.Start(ctx, "migrate_shadow_branch") if err := s.migrateAndPersistIfNeeded(ctx, repo, state); err != nil { + migrateSpan.RecordError(err) + migrateSpan.End() return err } + migrateSpan.End() // Get checkpoint store store, err := s.getCheckpointStore() @@ -80,6 +95,7 @@ func (s *ManualCommitStrategy) SaveStep(ctx context.Context, step StepContext) e slog.String("session_id", sessionID)) // Use WriteTemporary to create the checkpoint + _, writeCheckpointSpan := perf.Start(ctx, "write_temporary_checkpoint") isFirstCheckpointOfSession := state.StepCount == 0 result, err := store.WriteTemporary(ctx, checkpoint.WriteTemporaryOptions{ SessionID: sessionID, @@ -95,6 +111,8 @@ func (s *ManualCommitStrategy) SaveStep(ctx context.Context, step StepContext) e AuthorEmail: step.AuthorEmail, IsFirstCheckpoint: isFirstCheckpointOfSession, }) + writeCheckpointSpan.RecordError(err) + writeCheckpointSpan.End() if err != nil { return fmt.Errorf("failed to write temporary checkpoint: %w", err) } @@ -112,6 +130,7 @@ func (s *ManualCommitStrategy) SaveStep(ctx context.Context, step StepContext) e } // Update session state + _, updateStateSpan := perf.Start(ctx, "update_session_state") state.StepCount++ // Note: LastCheckpointID is intentionally NOT cleared here. @@ -136,8 +155,11 @@ func (s *ManualCommitStrategy) SaveStep(ctx context.Context, step StepContext) e // Save updated state if err := s.saveSessionState(ctx, state); err != nil { + updateStateSpan.RecordError(err) + updateStateSpan.End() return fmt.Errorf("failed to save session state: %w", err) } + updateStateSpan.End() if !branchExisted { logging.Info(logging.WithComponent(ctx, "checkpoint"), "created shadow branch and committed changes", diff --git a/cmd/entire/cli/strategy/manual_commit_hooks.go b/cmd/entire/cli/strategy/manual_commit_hooks.go index 26284607d..30fec41b0 100644 --- a/cmd/entire/cli/strategy/manual_commit_hooks.go +++ b/cmd/entire/cli/strategy/manual_commit_hooks.go @@ -27,6 +27,7 @@ import ( "github.com/entireio/cli/cmd/entire/cli/stringutil" "github.com/entireio/cli/cmd/entire/cli/trail" "github.com/entireio/cli/cmd/entire/cli/trailers" + "github.com/entireio/cli/perf" "github.com/entireio/cli/redact" "github.com/go-git/go-git/v5" @@ -327,14 +328,21 @@ func (s *ManualCommitStrategy) PrepareCommitMsg(ctx context.Context, commitMsgFi return s.handleAmendCommitMsg(ctx, commitMsgFile) } + _, openRepoSpan := perf.Start(ctx, "open_repository") repo, err := OpenRepository(ctx) if err != nil { - return nil //nolint:nilerr // Hook must be silent on failure + openRepoSpan.RecordError(err) + openRepoSpan.End() + return nil } + openRepoSpan.End() + _, findSessionsSpan := perf.Start(ctx, "find_sessions_for_worktree") worktreePath, err := paths.WorktreeRoot(ctx) if err != nil { - return nil //nolint:nilerr // Hook must be silent on failure + findSessionsSpan.RecordError(err) + findSessionsSpan.End() + return nil } // Find all active sessions for this worktree @@ -342,13 +350,16 @@ func (s *ManualCommitStrategy) PrepareCommitMsg(ctx context.Context, commitMsgFi // intermediate commits without entering new prompts, causing HEAD to diverge sessions, err := s.findSessionsForWorktree(ctx, worktreePath) if err != nil || len(sessions) == 0 { + findSessionsSpan.RecordError(err) + findSessionsSpan.End() // No active sessions or error listing - silently skip (hooks must be resilient) logging.Debug(logCtx, "prepare-commit-msg: no active sessions", slog.String("strategy", "manual-commit"), slog.String("source", source), ) - return nil //nolint:nilerr // Intentional: hooks must be silent on failure + return nil } + findSessionsSpan.End() // Fast path: when an agent is committing (ACTIVE session + no TTY), skip // content detection and interactive prompts. The agent can't respond to TTY @@ -364,7 +375,9 @@ func (s *ManualCommitStrategy) PrepareCommitMsg(ctx context.Context, commitMsgFi } // Check if any session has new content to condense + _, filterSessionsSpan := perf.Start(ctx, "filter_sessions_with_content") sessionsWithContent := s.filterSessionsWithNewContent(ctx, repo, sessions) + filterSessionsSpan.End() if len(sessionsWithContent) == 0 { // No new content — no trailer needed @@ -377,15 +390,19 @@ func (s *ManualCommitStrategy) PrepareCommitMsg(ctx context.Context, commitMsgFi } // Read current commit message + _, readCommitMessageSpan := perf.Start(ctx, "read_commit_message") content, err := os.ReadFile(commitMsgFile) //nolint:gosec // commitMsgFile is provided by git hook if err != nil { - return nil //nolint:nilerr // Hook must be silent on failure + readCommitMessageSpan.RecordError(err) + readCommitMessageSpan.End() + return nil } message := string(content) // Check if trailer already exists (ParseCheckpoint validates format, so found==true means valid) if existingCpID, found := trailers.ParseCheckpoint(message); found { + readCommitMessageSpan.End() // Trailer already exists (e.g., amend) - keep it logging.Debug(logCtx, "prepare-commit-msg: trailer already exists", slog.String("strategy", "manual-commit"), @@ -394,10 +411,14 @@ func (s *ManualCommitStrategy) PrepareCommitMsg(ctx context.Context, commitMsgFi ) return nil } + readCommitMessageSpan.End() - // Generate a fresh checkpoint ID + // Generate a fresh checkpoint ID and resolve session metadata + _, resolveMetadataSpan := perf.Start(ctx, "resolve_session_metadata") checkpointID, err := id.Generate() if err != nil { + resolveMetadataSpan.RecordError(err) + resolveMetadataSpan.End() return fmt.Errorf("failed to generate checkpoint ID: %w", err) } @@ -420,8 +441,11 @@ func (s *ManualCommitStrategy) PrepareCommitMsg(ctx context.Context, commitMsgFi if stngs, loadErr := settings.Load(ctx); loadErr == nil { commitLinking = stngs.GetCommitLinking() } + resolveMetadataSpan.End() // Add trailer differently based on commit source + // NOTE: TTY confirmation (askConfirmTTY) is intentionally NOT wrapped in a span + // because it blocks on user input and would skew timing. switch source { case "message": // Using -m or -F: behavior depends on TTY availability and commit_linking setting @@ -470,9 +494,13 @@ func (s *ManualCommitStrategy) PrepareCommitMsg(ctx context.Context, commitMsgFi ) // Write updated message back + _, writeCommitMessageSpan := perf.Start(ctx, "write_commit_message") if err := os.WriteFile(commitMsgFile, []byte(message), 0o600); err != nil { - return nil //nolint:nilerr // Hook must be silent on failure + writeCommitMessageSpan.RecordError(err) + writeCommitMessageSpan.End() + return nil } + writeCommitMessageSpan.End() return nil } @@ -727,24 +755,33 @@ func (h *postCommitActionHandler) HandleWarnStaleSession(_ *session.State) error func (s *ManualCommitStrategy) PostCommit(ctx context.Context) error { //nolint:unparam // error return is part of the hook contract; callers check it logCtx := logging.WithComponent(ctx, "checkpoint") + _, 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 } // Get HEAD commit to check for trailer head, err := repo.Head() if err != nil { - return nil //nolint:nilerr // Hook must be silent on failure + openRepoSpan.RecordError(err) + openRepoSpan.End() + return nil } 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 } // Check if commit has checkpoint trailer (ParseCheckpoint validates format) checkpointID, found := trailers.ParseCheckpoint(commit.Message) + openRepoSpan.End() + if !found { // No trailer — user removed it or it was never added (mid-turn commit). // Still update BaseCommit for active sessions so future commits can match. @@ -752,13 +789,19 @@ func (s *ManualCommitStrategy) PostCommit(ctx context.Context) error { //nolint: return nil } + _, findSessionsSpan := perf.Start(ctx, "find_sessions_for_worktree") worktreePath, err := paths.WorktreeRoot(ctx) if err != nil { - return nil //nolint:nilerr // Hook must be silent on failure + findSessionsSpan.RecordError(err) + findSessionsSpan.End() + return nil } // Find all active sessions for this worktree sessions, err := s.findSessionsForWorktree(ctx, worktreePath) + findSessionsSpan.RecordError(err) + findSessionsSpan.End() + if err != nil || len(sessions) == 0 { logging.Warn(logCtx, "post-commit: no active sessions despite trailer", slog.String("strategy", "manual-commit"), @@ -790,6 +833,7 @@ func (s *ManualCommitStrategy) PostCommit(ctx context.Context) error { //nolint: // These are immutable within this hook invocation and used by multiple // per-session functions (filesOverlapWithContent, filesWithRemainingAgentChanges, // calculateSessionAttributions). + _, resolveTreesSpan := perf.Start(ctx, "resolve_commit_trees") var headTree *object.Tree if t, err := commit.Tree(); err == nil { headTree = t @@ -804,6 +848,7 @@ func (s *ManualCommitStrategy) PostCommit(ctx context.Context) error { //nolint: } committedFileSet := filesChangedInCommit(ctx, worktreePath, commit, headTree, parentTree) + resolveTreesSpan.End() for _, state := range sessions { // Skip fully-condensed ended sessions — no work remains. @@ -818,6 +863,7 @@ func (s *ManualCommitStrategy) PostCommit(ctx context.Context) error { //nolint: // Clean up shadow branches — only delete when ALL sessions on the branch are non-active // or were condensed during this PostCommit. + _, cleanupBranchesSpan := perf.Start(ctx, "cleanup_shadow_branches") for shadowBranchName := range shadowBranchesToDelete { if uncondensedActiveOnBranch[shadowBranchName] { logging.Debug(logCtx, "post-commit: preserving shadow branch (active session exists)", @@ -836,6 +882,7 @@ func (s *ManualCommitStrategy) PostCommit(ctx context.Context) error { //nolint: ) } } + cleanupBranchesSpan.End() return nil } @@ -864,6 +911,7 @@ func (s *ManualCommitStrategy) postCommitProcessSession( // Pre-resolve shadow branch ref and tree for this session. // These are read 4+ times across sessionHasNewContent, filesOverlapWithContent, // CondenseSession, filesWithRemainingAgentChanges, and calculateSessionAttributions. + _, resolveShadowBranchSpan := perf.Start(ctx, "resolve_shadow_branch") var shadowRef *plumbing.Reference var shadowTree *object.Tree if ref, refErr := repo.Reference(plumbing.NewBranchReferenceName(shadowBranchName), true); refErr == nil { @@ -874,6 +922,7 @@ func (s *ManualCommitStrategy) postCommitProcessSession( } } } + resolveShadowBranchSpan.End() // Check for new content (needed for TransitionContext and condensation). // Fail-open: if content check errors, assume new content exists so we @@ -887,6 +936,7 @@ func (s *ManualCommitStrategy) postCommitProcessSession( // In both cases, PrepareCommitMsg already validated this commit. We trust // that decision here. Transcript-based re-validation is unreliable because // subagent transcripts may not be available yet (subagent still running). + _, checkContentSpan := perf.Start(ctx, "check_session_content") var hasNew bool if state.Phase.IsActive() { hasNew = true @@ -914,6 +964,7 @@ func (s *ManualCommitStrategy) postCommitProcessSession( filesTouchedBefore = make([]string, len(state.FilesTouched)) copy(filesTouchedBefore, state.FilesTouched) } + checkContentSpan.End() logging.Debug(logCtx, "post-commit: carry-forward prep", slog.String("session_id", state.SessionID), @@ -924,6 +975,7 @@ func (s *ManualCommitStrategy) postCommitProcessSession( ) // Run the state machine transition with handler for strategy-specific actions. + _, transitionAndCondenseSpan := perf.Start(ctx, "transition_and_condense") handler := &postCommitActionHandler{ s: s, ctx: ctx, @@ -948,6 +1000,7 @@ func (s *ManualCommitStrategy) postCommitProcessSession( logging.Warn(logCtx, "post-commit action handler error", slog.String("error", err.Error())) } + transitionAndCondenseSpan.End() // Record checkpoint ID for ACTIVE sessions so HandleTurnEnd can finalize // with full transcript. IDLE/ENDED sessions already have complete transcripts. @@ -963,6 +1016,7 @@ func (s *ManualCommitStrategy) postCommitProcessSession( // commit across two `git commit` invocations, each gets a 1:1 checkpoint. // Uses content-aware comparison: if user did `git add -p` and committed // partial changes, the file still has remaining agent changes to carry forward. + _, carryForwardSpan := perf.Start(ctx, "carry_forward_files") if handler.condensed { remainingFiles := filesWithRemainingAgentChanges(ctx, repo, shadowBranchName, commit, filesTouchedBefore, committedFileSet, overlapOpts{ headTree: headTree, @@ -988,6 +1042,7 @@ func (s *ManualCommitStrategy) postCommitProcessSession( clearFilesystemPrompt(ctx, state.SessionID) } } + carryForwardSpan.End() // Mark ENDED sessions as fully condensed when no carry-forward remains. // PostCommit will skip these sessions entirely on future commits. @@ -997,11 +1052,13 @@ func (s *ManualCommitStrategy) postCommitProcessSession( } // Save the updated state + _, saveSessionStateSpan := perf.Start(ctx, "save_session_state") if err := s.saveSessionState(ctx, state); err != nil { logging.Warn(logCtx, "failed to update session state", slog.String("session_id", state.SessionID), slog.String("error", err.Error())) } + saveSessionStateSpan.End() // Only preserve shadow branch for active sessions that were NOT condensed. // Condensed sessions already have their data on entire/checkpoints/v1. diff --git a/cmd/entire/cli/strategy/manual_commit_push.go b/cmd/entire/cli/strategy/manual_commit_push.go index 9bf6c8bf7..a8f5be40c 100644 --- a/cmd/entire/cli/strategy/manual_commit_push.go +++ b/cmd/entire/cli/strategy/manual_commit_push.go @@ -4,6 +4,7 @@ import ( "context" "github.com/entireio/cli/cmd/entire/cli/paths" + "github.com/entireio/cli/perf" ) // PrePush is called by the git pre-push hook before pushing to a remote. @@ -13,8 +14,17 @@ import ( // - "prompt" (default): ask user with option to enable auto // - "false"/"off"/"no": never push func (s *ManualCommitStrategy) PrePush(ctx context.Context, remote string) error { + _, pushCheckpointsSpan := perf.Start(ctx, "push_checkpoints_branch") if err := pushSessionsBranchCommon(ctx, remote, paths.MetadataBranchName); err != nil { + pushCheckpointsSpan.RecordError(err) + pushCheckpointsSpan.End() return err } - return PushTrailsBranch(ctx, remote) + pushCheckpointsSpan.End() + + _, pushTrailsSpan := perf.Start(ctx, "push_trails_branch") + err := PushTrailsBranch(ctx, remote) + pushTrailsSpan.RecordError(err) + pushTrailsSpan.End() + return err } diff --git a/perf/context.go b/perf/context.go new file mode 100644 index 000000000..ceeed2010 --- /dev/null +++ b/perf/context.go @@ -0,0 +1,20 @@ +package perf + +import "context" + +type contextKey struct{} + +// spanFromContext retrieves the current span from context, or nil if none. +func spanFromContext(ctx context.Context) *Span { + if v := ctx.Value(contextKey{}); v != nil { + if s, ok := v.(*Span); ok { + return s + } + } + return nil +} + +// contextWithSpan returns a new context with the span stored. +func contextWithSpan(ctx context.Context, s *Span) context.Context { + return context.WithValue(ctx, contextKey{}, s) +} diff --git a/perf/span.go b/perf/span.go new file mode 100644 index 000000000..6d547596e --- /dev/null +++ b/perf/span.go @@ -0,0 +1,97 @@ +package perf + +import ( + "context" + "fmt" + "log/slog" + "time" + + "github.com/entireio/cli/cmd/entire/cli/logging" +) + +// 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 +} + +// Start begins a new span. If ctx already has a span, the new one becomes a child. +// Returns the updated context and the span. Call span.End() when the operation completes. +func Start(ctx context.Context, name string, attrs ...slog.Attr) (context.Context, *Span) { + parent := spanFromContext(ctx) + s := &Span{ + name: name, + start: time.Now(), + parent: parent, + attrs: attrs, + ctx: ctx, + } + if parent != nil { + parent.children = append(parent.children, s) + } + return contextWithSpan(ctx, s), s +} + +// RecordError marks the span as errored. Only the first non-nil error is stored; +// subsequent calls are no-ops. Call this before End() on error paths. +func (s *Span) RecordError(err error) { + if err == nil || s.err != nil { + return + } + s.err = err +} + +// End completes the span. For root spans, emits a single DEBUG log line +// with the full timing tree. For child spans, records the duration only. +// Safe to call multiple times -- subsequent calls are no-ops. +func (s *Span) End() { + if s.ended { + return + } + s.ended = true + s.duration = time.Since(s.start) + + // Only root spans emit log output + if s.parent != nil { + 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") + attrs := make([]any, 0, 3+2*len(s.children)+len(s.attrs)) + 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 + for _, child := range s.children { + // Auto-end children that were not explicitly ended + if !child.ended { + child.End() + } + 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)) + } + } + + // Add any extra attributes from Start() + for _, a := range s.attrs { + attrs = append(attrs, a) + } + + logging.Debug(logCtx, "perf", attrs...) +} diff --git a/perf/span_test.go b/perf/span_test.go new file mode 100644 index 000000000..64ec9c422 --- /dev/null +++ b/perf/span_test.go @@ -0,0 +1,224 @@ +package perf + +import ( + "context" + "errors" + "testing" + "time" +) + +func TestStart_CreatesRootSpan(t *testing.T) { + t.Parallel() + ctx := context.Background() + + ctx, span := Start(ctx, "test_op") + if span == nil { + t.Fatal("Start() returned nil span") + } + if span.name != "test_op" { + t.Errorf("span.name = %q, want %q", span.name, "test_op") + } + if span.parent != nil { + t.Error("root span should have nil parent") + } + + got := spanFromContext(ctx) + if got != span { + t.Error("spanFromContext should return the span set by Start") + } + + span.End() +} + +func TestStart_NestsChildSpan(t *testing.T) { + t.Parallel() + ctx := context.Background() + + ctx, parent := Start(ctx, "parent") + _, child := Start(ctx, "child") + + if child.parent != parent { + t.Error("child span should reference parent") + } + if len(parent.children) != 1 { + t.Fatalf("parent should have 1 child, got %d", len(parent.children)) + } + if parent.children[0] != child { + t.Error("parent.children[0] should be the child span") + } + + child.End() + parent.End() +} + +func TestEnd_RecordsDuration(t *testing.T) { + t.Parallel() + ctx := context.Background() + + _, span := Start(ctx, "timed_op") + time.Sleep(10 * time.Millisecond) + span.End() + + if span.duration < 10*time.Millisecond { + t.Errorf("span.duration = %v, want >= 10ms", span.duration) + } +} + +func TestEnd_Idempotent(t *testing.T) { + t.Parallel() + ctx := context.Background() + + _, span := Start(ctx, "double_end") + time.Sleep(10 * time.Millisecond) + span.End() + + firstDuration := span.duration + + time.Sleep(10 * time.Millisecond) + span.End() + + if span.duration != firstDuration { + t.Errorf("second End() changed duration from %v to %v", firstDuration, span.duration) + } +} + +func TestEnd_AutoEndsChildren(t *testing.T) { + t.Parallel() + ctx := context.Background() + + ctx, parent := Start(ctx, "parent") + _, child := Start(ctx, "child") + + time.Sleep(10 * time.Millisecond) + parent.End() + + if !child.ended { + t.Error("child should be auto-ended when parent ends") + } + if child.duration == 0 { + t.Error("child should have non-zero duration after auto-end") + } +} + +func TestSpanFromContext_ReturnsNilWhenEmpty(t *testing.T) { + t.Parallel() + ctx := context.Background() + + if got := spanFromContext(ctx); got != nil { + t.Errorf("spanFromContext on empty context = %v, want nil", got) + } +} + +func TestStart_MultipleChildren(t *testing.T) { + t.Parallel() + ctx := context.Background() + + ctx, parent := Start(ctx, "parent") + + ctx2, child1 := Start(ctx, "child1") + _ = ctx2 + child1.End() + + ctx3, child2 := Start(ctx, "child2") + _ = ctx3 + child2.End() + + parent.End() + + if len(parent.children) != 2 { + t.Fatalf("expected 2 children, got %d", len(parent.children)) + } + if parent.children[0].name != "child1" { + t.Errorf("first child name = %q, want %q", parent.children[0].name, "child1") + } + if parent.children[1].name != "child2" { + t.Errorf("second child name = %q, want %q", parent.children[1].name, "child2") + } +} + +func TestRecordError_MarksSpanAsErrored(t *testing.T) { + t.Parallel() + ctx := context.Background() + + _, span := Start(ctx, "op") + testErr := errors.New("something failed") + span.RecordError(testErr) + + if !errors.Is(span.err, testErr) { + t.Errorf("span.err = %v, want %v", span.err, testErr) + } + + span.End() +} + +func TestRecordError_NilIsNoOp(t *testing.T) { + t.Parallel() + ctx := context.Background() + + _, span := Start(ctx, "op") + span.RecordError(nil) + + if span.err != nil { + t.Errorf("span.err = %v, want nil", span.err) + } + + span.End() +} + +func TestRecordError_FirstErrorWins(t *testing.T) { + t.Parallel() + ctx := context.Background() + + _, span := Start(ctx, "op") + firstErr := errors.New("first") + secondErr := errors.New("second") + + span.RecordError(firstErr) + span.RecordError(secondErr) + + if !errors.Is(span.err, firstErr) { + t.Errorf("span.err = %v, want %v (first error)", span.err, firstErr) + } + + span.End() +} + +func TestRecordError_ChildErrorFlagInOutput(t *testing.T) { + t.Parallel() + ctx := context.Background() + + ctx, parent := Start(ctx, "parent") + _, child := Start(ctx, "failing_step") + + child.RecordError(errors.New("step failed")) + child.End() + parent.End() + + // Verify the child has the error recorded + if child.err == nil { + t.Error("child span should have error recorded") + } + // The error flag will appear as "steps.failing_step_err: true" in log output. + // We verify the span state directly since log output goes to slog. + if parent.children[0].err == nil { + t.Error("parent's child should have error recorded") + } +} + +func TestEnd_NoErrorFlagByDefault(t *testing.T) { + t.Parallel() + ctx := context.Background() + + ctx, parent := Start(ctx, "parent") + _, child := Start(ctx, "ok_step") + + child.End() + parent.End() + + if child.err != nil { + t.Errorf("child span should have nil error, got %v", child.err) + } + if parent.err != nil { + t.Errorf("parent span should have nil error, got %v", parent.err) + } +}