DIAGNOSTIC: Windows hook spawn timing (do not merge)

.github/workflows/ci.yml

@@ -49,7 +49,26 @@ jobs:
         with:
           go-version: ${{ env.GO_VERSION }}
       - run: go mod verify
+      - name: Runner facts
+        if: runner.os == 'Windows'
+        run: |
+          echo "cpus=$env:NUMBER_OF_PROCESSORS"
+          (Get-CimInstance Win32_Processor).Name
+          (Get-CimInstance Win32_ComputerSystem).TotalPhysicalMemory
       - run: go test -count=1 ${{ matrix.test_flags }} ./...
+        env:
+          PACKETCODE_DIAG_FILE: ${{ runner.temp }}/hook-diag.txt
+      # DIAGNOSTIC (temporary): timings recorded from inside the real suite run,
+      # written to a file because go test discards a passing package's stderr.
+      - name: DIAG in-suite hook timings
+        if: always() && runner.os == 'Windows'
+        run: Get-Content "${{ runner.temp }}/hook-diag.txt"
+      # DIAGNOSTIC (temporary): tiered measurement of Windows hook spawn cost.
+      - name: DIAG hook spawn timing
+        if: always() && runner.os == 'Windows'
+        env:
+          PACKETCODE_HOOK_TIMING: '1'
+        run: go test -count=1 -v -run TestHookTimingDiagnostics ./internal/hooks/
 
   tui-golden:
     name: TUI golden and protocol safety

internal/hooks/diagrec_test.go

@@ -0,0 +1,27 @@
+package hooks
+
+import (
+	"fmt"
+	"os"
+	"sync"
+)
+
+// DIAGNOSTIC: go test discards a passing package's stderr, so timings written
+// there are invisible on exactly the runs that matter. Appending to a file the
+// workflow cats afterwards survives both a pass and a fail.
+var diagMu sync.Mutex
+
+func diagRecord(format string, args ...any) {
+	path := os.Getenv("PACKETCODE_DIAG_FILE")
+	if path == "" {
+		return
+	}
+	diagMu.Lock()
+	defer diagMu.Unlock()
+	f, err := os.OpenFile(path, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o644)
+	if err != nil {
+		return
+	}
+	defer f.Close()
+	fmt.Fprintf(f, format+"\n", args...)
+}

internal/hooks/hooks_test.go

@@ -2,6 +2,7 @@ package hooks
 
 import (
 	"context"
+	"os/exec"
 	"runtime"
 	"strings"
 	"testing"
@@ -20,25 +21,64 @@ func TestRunUserPromptSubmit_CollectsStdout(t *testing.T) {
 		command = "$data = [Console]::In.ReadToEnd(); if ($data -match 'hello') { 'injected-context' } else { exit 1 }"
 		timeoutSec = 5
 	}
+	if runtime.GOOS == "windows" {
+		timeoutSec = 120 // DIAGNOSTIC: measure the real cost, do not truncate it
+	}
+
+	// DIAGNOSTIC discriminator, taken immediately before the first hook and in
+	// this order: a bare CreateProcess, then a cold PowerShell that touches no
+	// stdin, then the real hook. If all three are slow the machine is
+	// contended; if only the last two are, the cost is PowerShell start-up; if
+	// only the last is, it is stdin plumbing or internal/hooks itself.
+	if runtime.GOOS == "windows" {
+		t0 := time.Now()
+		bare := exec.Command("cmd.exe", "/c", "exit")
+		bareErr := bare.Run()
+		bareD := time.Since(t0)
+
+		t1 := time.Now()
+		ps := exec.Command("powershell", "-NoLogo", "-NoProfile", "-NonInteractive",
+			"-ExecutionPolicy", "Bypass", "-Command", "exit 0")
+		psErr := ps.Run()
+		psD := time.Since(t1)
+
+		diagRecord("DIAG cold-probe bare_createprocess=%s (err=%v) cold_powershell_no_stdin=%s (err=%v)",
+			bareD.Round(time.Millisecond), bareErr, psD.Round(time.Millisecond), psErr)
+	}
+
 	r := New(config.HooksConfig{
 		UserPromptSubmit: []config.HookConfig{{Command: command, TimeoutSec: timeoutSec}},
 	}, t.TempDir())
 
+	start := time.Now()
 	out, err := r.RunUserPromptSubmit(context.Background(), PromptPayload{Prompt: "hello"})
+	diagRecord("DIAG first-hook-spawn elapsed=%s err=%v", time.Since(start).Round(time.Millisecond), err)
 	require.NoError(t, err)
 	assert.Equal(t, "injected-context", out)
+
+	for i := 0; i < 5; i++ {
+		s := time.Now()
+		_, err := r.RunUserPromptSubmit(context.Background(), PromptPayload{Prompt: "hello"})
+		diagRecord("DIAG warm-hook-spawn[%d] elapsed=%s err=%v", i, time.Since(s).Round(time.Millisecond), err)
+	}
 }
 
 func TestRunPreToolUse_MatcherCanBlock(t *testing.T) {
 	command := "echo blocked >&2; exit 7"
 	if runtime.GOOS == "windows" {
 		command = "Write-Error blocked; exit 7"
 	}
+	blockTimeout := 2
+	if runtime.GOOS == "windows" {
+		blockTimeout = 120 // DIAGNOSTIC
+	}
 	r := New(config.HooksConfig{
-		PreToolUse: []config.HookConfig{{Matcher: "execute_command", Command: command, TimeoutSec: 2}},
+		PreToolUse: []config.HookConfig{{Matcher: "execute_command", Command: command, TimeoutSec: blockTimeout}},
 	}, t.TempDir())
 
+	blockStart := time.Now()
 	_, err := r.RunPreToolUse(context.Background(), ToolPayload{ToolName: "execute_command"})
+	diagRecord("DIAG matcher-block-spawn elapsed=%s\n", time.Since(blockStart).Round(time.Millisecond))
 	require.Error(t, err)
 	assert.Contains(t, err.Error(), "blocked")
 
@@ -57,22 +97,28 @@ func TestRunPreToolUse_TimeoutMessage(t *testing.T) {
 
 	start := time.Now()
 	_, err := r.RunPreToolUse(context.Background(), ToolPayload{ToolName: "execute_command"})
+	diagRecord("DIAG timeout-path elapsed=%s err=%v\n", time.Since(start).Round(time.Millisecond), err)
 	require.Error(t, err)
 	assert.Contains(t, err.Error(), "timed out after 1s")
 	assert.Contains(t, err.Error(), "process tree cancellation requested")
-	assert.Less(t, time.Since(start), 3*time.Second)
 }
 
 func TestRunPostToolUse_TruncatesStdoutAndStderr(t *testing.T) {
 	command := "(yes o | head -c 70000); (yes e | head -c 70000 >&2); exit 3"
 	if runtime.GOOS == "windows" {
 		command = "$out = 'o' * 70000; $err = 'e' * 70000; [Console]::Out.Write($out); [Console]::Error.Write($err); exit 3"
 	}
+	truncTimeout := 5
+	if runtime.GOOS == "windows" {
+		truncTimeout = 120 // DIAGNOSTIC
+	}
 	r := New(config.HooksConfig{
-		PostToolUse: []config.HookConfig{{Matcher: "execute_command", Command: command, TimeoutSec: 5}},
+		PostToolUse: []config.HookConfig{{Matcher: "execute_command", Command: command, TimeoutSec: truncTimeout}},
 	}, t.TempDir())
 
+	truncStart := time.Now()
 	out, err := r.RunPostToolUse(context.Background(), ToolPayload{ToolName: "execute_command"})
+	diagRecord("DIAG truncate-spawn elapsed=%s\n", time.Since(truncStart).Round(time.Millisecond))
 	require.NoError(t, err)
 	assert.Contains(t, out, "stdout truncated at 64KB")
 	assert.Contains(t, out, "stderr truncated at 64KB")

internal/hooks/timing_diag_windows_test.go

@@ -0,0 +1,155 @@
+//go:build windows
+
+package hooks
+
+import (
+	"bytes"
+	"context"
+	"fmt"
+	"os"
+	"os/exec"
+	"sort"
+	"sync"
+	"testing"
+	"time"
+
+	"github.com/packetcode/packetcode/internal/config"
+	"github.com/packetcode/packetcode/internal/procrun"
+)
+
+// TestHookTimingDiagnostics is temporary instrumentation. It is not an
+// assertion about anything; it measures where the Windows hook budget goes.
+func TestHookTimingDiagnostics(t *testing.T) {
+	if os.Getenv("PACKETCODE_HOOK_TIMING") != "1" {
+		t.Skip("set PACKETCODE_HOOK_TIMING=1 to run the timing instrumentation")
+	}
+	const runs = 7
+
+	report := func(name string, fn func() error) []time.Duration {
+		var ds []time.Duration
+		for i := 0; i < runs; i++ {
+			start := time.Now()
+			err := fn()
+			d := time.Since(start)
+			ds = append(ds, d)
+			if err != nil {
+				t.Logf("%-46s run %d: ERROR %v", name, i, err)
+			}
+		}
+		sorted := append([]time.Duration(nil), ds...)
+		sort.Slice(sorted, func(i, j int) bool { return sorted[i] < sorted[j] })
+		t.Logf("%-46s first=%-9s min=%-9s med=%-9s max=%-9s all=%v",
+			name, ds[0].Round(time.Millisecond), sorted[0].Round(time.Millisecond),
+			sorted[len(sorted)/2].Round(time.Millisecond), sorted[len(sorted)-1].Round(time.Millisecond),
+			roundAll(ds))
+		return ds
+	}
+
+	psArgs := []string{"-NoLogo", "-NoProfile", "-NonInteractive", "-ExecutionPolicy", "Bypass", "-Command"}
+	stdinScript := "$data = [Console]::In.ReadToEnd(); if ($data -match 'hello') { 'injected-context' } else { exit 1 }"
+	payload := []byte(`{"event":"UserPromptSubmit","prompt":"hello"}`)
+
+	raw := func(exe string, args []string, stdin []byte) func() error {
+		return func() error {
+			cmd := exec.Command(exe, args...)
+			if stdin != nil {
+				cmd.Stdin = bytes.NewReader(stdin)
+			}
+			cmd.Stdout = &bytes.Buffer{}
+			cmd.Stderr = &bytes.Buffer{}
+			return cmd.Run()
+		}
+	}
+	rawTree := func(exe string, args []string, stdin []byte) func() error {
+		return func() error {
+			cmd := exec.CommandContext(context.Background(), exe, args...)
+			procrun.ConfigureTreeCancel(cmd)
+			if stdin != nil {
+				cmd.Stdin = bytes.NewReader(stdin)
+			}
+			cmd.Stdout = &bytes.Buffer{}
+			cmd.Stderr = &bytes.Buffer{}
+			return cmd.Run()
+		}
+	}
+
+	t.Log("=== sequential, idle ===")
+	report("cmd.exe /c exit (bare CreateProcess)", raw("cmd.exe", []string{"/c", "exit"}, nil))
+	report("cmd.exe /c findstr (stdin)", raw("cmd.exe", []string{"/c", "findstr", "hello"}, payload))
+	report("powershell -Command exit 0 (no stdin)", raw("powershell", append(append([]string{}, psArgs...), "exit 0"), nil))
+	report("powershell -Command exit 0 (stdin attached)", raw("powershell", append(append([]string{}, psArgs...), "exit 0"), payload))
+	report("powershell full hook script (stdin read)", raw("powershell", append(append([]string{}, psArgs...), stdinScript), payload))
+	report("powershell full + ConfigureTreeCancel", rawTree("powershell", append(append([]string{}, psArgs...), stdinScript), payload))
+	if _, err := exec.LookPath("pwsh"); err == nil {
+		report("pwsh full hook script (stdin read)", raw("pwsh", append(append([]string{}, psArgs...), stdinScript), payload))
+	} else {
+		t.Log("pwsh not on PATH")
+	}
+
+	runner := func(command string, timeoutSec int) func() error {
+		return func() error {
+			r := New(config.HooksConfig{
+				UserPromptSubmit: []config.HookConfig{{Command: command, TimeoutSec: timeoutSec}},
+			}, t.TempDir())
+			_, err := r.RunUserPromptSubmit(context.Background(), PromptPayload{Prompt: "hello"})
+			return err
+		}
+	}
+	report("hooks.Runner end-to-end (60s budget)", runner(stdinScript, 60))
+
+	// Now the same thing while the machine is busy, which is the condition the
+	// suite actually runs under.
+	t.Log("=== sequential, under CPU load ===")
+	stop := make(chan struct{})
+	var wg sync.WaitGroup
+	for i := 0; i < 4; i++ {
+		wg.Add(1)
+		go func() {
+			defer wg.Done()
+			x := 0
+			for {
+				select {
+				case <-stop:
+					return
+				default:
+					for j := 0; j < 1e6; j++ {
+						x += j
+					}
+					_ = x
+				}
+			}
+		}()
+	}
+	report("powershell full hook script (loaded)", raw("powershell", append(append([]string{}, psArgs...), stdinScript), payload))
+	report("hooks.Runner end-to-end (loaded)", runner(stdinScript, 60))
+	close(stop)
+	wg.Wait()
+
+	// Concurrent spawns, which is what -parallel does to a suite.
+	t.Log("=== 8 concurrent powershell spawns ===")
+	start := time.Now()
+	var cwg sync.WaitGroup
+	durs := make([]time.Duration, 8)
+	for i := 0; i < 8; i++ {
+		cwg.Add(1)
+		go func(i int) {
+			defer cwg.Done()
+			s := time.Now()
+			_ = raw("powershell", append(append([]string{}, psArgs...), stdinScript), payload)()
+			durs[i] = time.Since(s)
+		}(i)
+	}
+	cwg.Wait()
+	t.Logf("8 concurrent: wall=%s each=%v", time.Since(start).Round(time.Millisecond), roundAll(durs))
+}
+
+func roundAll(ds []time.Duration) string {
+	out := "["
+	for i, d := range ds {
+		if i > 0 {
+			out += " "
+		}
+		out += fmt.Sprint(d.Round(time.Millisecond))
+	}
+	return out + "]"
+}