diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 0dfa72a..99712da 100644 --- a/.github/workflows/ci.yml +++ b/.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 diff --git a/internal/hooks/diagrec_test.go b/internal/hooks/diagrec_test.go new file mode 100644 index 0000000..7b50138 --- /dev/null +++ b/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...) +} diff --git a/internal/hooks/hooks_test.go b/internal/hooks/hooks_test.go index db1088f..a8eec86 100644 --- a/internal/hooks/hooks_test.go +++ b/internal/hooks/hooks_test.go @@ -2,6 +2,7 @@ package hooks import ( "context" + "os/exec" "runtime" "strings" "testing" @@ -20,13 +21,46 @@ 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) { @@ -34,11 +68,17 @@ func TestRunPreToolUse_MatcherCanBlock(t *testing.T) { 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,10 +97,10 @@ 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) { @@ -68,11 +108,17 @@ func TestRunPostToolUse_TruncatesStdoutAndStderr(t *testing.T) { 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") diff --git a/internal/hooks/timing_diag_windows_test.go b/internal/hooks/timing_diag_windows_test.go new file mode 100644 index 0000000..dd19898 --- /dev/null +++ b/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 + "]" +}