Add performance instrumentation framework for CLI operations

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
 }
 

cmd/entire/cli/hook_registry_test.go

@@ -131,47 +131,41 @@ 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 {
 			t.Errorf("failed to parse log line as JSON: %v", err)
 			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")
 			}
 		}
 	}
 
 	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")
 	}
 }
 

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
 		},

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,19 +375,25 @@ 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
 	}
 	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)