Skip to content

Commit 90f1687

Browse files
wonderwhy-erclaude
andauthored
Add verbose timing telemetry and improvements to terminal commands performance (#257)
* Add verbose timing telemetry and fix 8s timeout bug in process tools This commit adds comprehensive performance telemetry and fixes a critical bug where interact_with_process waited 8+ seconds despite output arriving in 2-6ms. Changes: - Add TimingInfo and OutputEvent types to track performance metrics - Add verbose_timing parameter to start_process, read_process_output, and interact_with_process - Implement detailed timing collection including exit reasons and output event timelines - Fix interact_with_process bug: removed broken duplicate stream listeners - Optimize polling: reduced interval from 200ms to 50ms (4x faster response) - Update tool documentation with performance debugging instructions Performance improvement: REPL interactions now complete in 50-100ms instead of 8s timeout (160x faster). Telemetry shows: - Exit reason (early_exit_quick_pattern, early_exit_periodic_check, process_exit, timeout) - Total duration and time to first output - Complete timeline of output events with timestamps and sources - Which detection mechanism triggered early exit 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude <[email protected]> * Fix listener cleanup bug in read_process_output Fixed critical bug where removeAllListeners('data') was removing TerminalManager's persistent listeners, breaking all future calls. Problem: - read_process_output attached temporary listeners for immediate detection - Used removeAllListeners('data') to clean up, which removed ALL listeners - This broke TerminalManager's accumulator, causing future getNewOutput() to return empty - Second call to read_process_output would always timeout Solution: - Store references to our specific detector functions - Use .off('data', specificFunction) instead of .removeAllListeners('data') - Only removes our temporary listeners, preserves TerminalManager's listeners Testing: - Added test-listener-bug.js that reproduces the issue - Test verifies multiple sequential read_process_output calls work correctly - All tests pass after fix Credit: Fix suggested by code reviewer 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude <[email protected]> * Strengthen test validation for listener cleanup bug Improved test-listener-bug.js to validate output content, not just presence: Changes: - Added validation that output contains expected result "4" from "2 + 2" - Added validation that output contains REPL prompt ">" - More detailed success messages showing what was validated - Better error messages if validation fails This prevents false positives where the test could pass even if: - Output is corrupt or incomplete - REPL prompt detection stops working - Listeners are partially broken All validations pass, confirming: ✓ Output contains correct computation result ✓ REPL prompt is properly detected ✓ Multiple sequential calls work correctly 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude <[email protected]> --------- Co-authored-by: Claude <[email protected]>
1 parent babda00 commit 90f1687

File tree

6 files changed

+558
-115
lines changed

6 files changed

+558
-115
lines changed

src/server.ts

Lines changed: 32 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -651,12 +651,20 @@ server.setRequestHandler(ListToolsRequestSchema, async () => {
651651
652652
STATES DETECTED:
653653
Process waiting for input (shows prompt)
654-
Process finished execution
654+
Process finished execution
655655
Process running (use read_process_output)
656-
656+
657+
PERFORMANCE DEBUGGING (verbose_timing parameter):
658+
Set verbose_timing: true to get detailed timing information including:
659+
- Exit reason (early_exit_quick_pattern, early_exit_periodic_check, process_exit, timeout)
660+
- Total duration and time to first output
661+
- Complete timeline of all output events with timestamps
662+
- Which detection mechanism triggered early exit
663+
Use this to identify missed optimization opportunities and improve detection patterns.
664+
657665
ALWAYS USE FOR: Local file analysis, CSV processing, data exploration, system commands
658666
NEVER USE ANALYSIS TOOL FOR: Local file access (analysis tool is browser-only and WILL FAIL)
659-
667+
660668
${PATH_GUIDANCE}
661669
${CMD_PREFIX_DESCRIPTION}`,
662670
inputSchema: zodToJsonSchema(StartProcessArgsSchema),
@@ -690,7 +698,15 @@ server.setRequestHandler(ListToolsRequestSchema, async () => {
690698
Process waiting for input (ready for interact_with_process)
691699
Process finished execution
692700
Timeout reached (may still be running)
693-
701+
702+
PERFORMANCE DEBUGGING (verbose_timing parameter):
703+
Set verbose_timing: true to get detailed timing information including:
704+
- Exit reason (early_exit_quick_pattern, early_exit_periodic_check, process_finished, timeout)
705+
- Total duration and time to first output
706+
- Complete timeline of all output events with timestamps
707+
- Which detection mechanism triggered early exit
708+
Use this to identify when timeouts could be reduced or detection patterns improved.
709+
694710
${CMD_PREFIX_DESCRIPTION}`,
695711
inputSchema: zodToJsonSchema(ReadProcessOutputArgsSchema),
696712
annotations: {
@@ -741,12 +757,21 @@ server.setRequestHandler(ListToolsRequestSchema, async () => {
741757
- input: Code/command to execute
742758
- timeout_ms: Max wait (default: 8000ms)
743759
- wait_for_prompt: Auto-wait for response (default: true)
744-
760+
- verbose_timing: Enable detailed performance telemetry (default: false)
761+
745762
Returns execution result with status indicators.
746-
763+
764+
PERFORMANCE DEBUGGING (verbose_timing parameter):
765+
Set verbose_timing: true to get detailed timing information including:
766+
- Exit reason (early_exit_quick_pattern, early_exit_periodic_check, process_finished, timeout, no_wait)
767+
- Total duration and time to first output
768+
- Complete timeline of all output events with timestamps
769+
- Which detection mechanism triggered early exit
770+
Use this to identify slow interactions and optimize detection patterns.
771+
747772
ALWAYS USE FOR: CSV analysis, JSON processing, file statistics, data visualization prep, ANY local file work
748773
NEVER USE ANALYSIS TOOL FOR: Local file access (it cannot read files from disk and WILL FAIL)
749-
774+
750775
${CMD_PREFIX_DESCRIPTION}`,
751776
inputSchema: zodToJsonSchema(InteractWithProcessArgsSchema),
752777
annotations: {

src/terminal-manager.ts

Lines changed: 79 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
import { spawn } from 'child_process';
2-
import { TerminalSession, CommandExecutionResult, ActiveSession } from './types.js';
2+
import { TerminalSession, CommandExecutionResult, ActiveSession, TimingInfo, OutputEvent } from './types.js';
33
import { DEFAULT_COMMAND_TIMEOUT } from './config.js';
44
import { configManager } from './config-manager.js';
55
import {capture} from "./utils/capture.js";
@@ -43,7 +43,7 @@ export class TerminalManager {
4343
}
4444
}
4545

46-
async executeCommand(command: string, timeoutMs: number = DEFAULT_COMMAND_TIMEOUT, shell?: string): Promise<CommandExecutionResult> {
46+
async executeCommand(command: string, timeoutMs: number = DEFAULT_COMMAND_TIMEOUT, shell?: string, collectTiming: boolean = false): Promise<CommandExecutionResult> {
4747
// Get the shell from config if not specified
4848
let shellToUse: string | boolean | undefined = shell;
4949
if (!shellToUse) {
@@ -55,29 +55,29 @@ export class TerminalManager {
5555
shellToUse = true;
5656
}
5757
}
58-
58+
5959
// For REPL interactions, we need to ensure stdin, stdout, and stderr are properly configured
6060
// Note: No special stdio options needed here, Node.js handles pipes by default
61-
61+
6262
// Enhance SSH commands automatically
6363
let enhancedCommand = command;
6464
if (command.trim().startsWith('ssh ') && !command.includes(' -t')) {
6565
enhancedCommand = command.replace(/^ssh /, 'ssh -t ');
6666
console.log(`Enhanced SSH command: ${enhancedCommand}`);
6767
}
68-
69-
const spawnOptions: any = {
68+
69+
const spawnOptions: any = {
7070
shell: shellToUse,
7171
env: {
7272
...process.env,
7373
TERM: 'xterm-256color' // Better terminal compatibility
7474
}
7575
};
76-
76+
7777
// Spawn the process with an empty array of arguments and our options
7878
const childProcess = spawn(enhancedCommand, [], spawnOptions);
7979
let output = '';
80-
80+
8181
// Ensure childProcess.pid is defined before proceeding
8282
if (!childProcess.pid) {
8383
// Return a consistent error object instead of throwing
@@ -87,39 +87,84 @@ export class TerminalManager {
8787
isBlocked: false
8888
};
8989
}
90-
90+
9191
const session: TerminalSession = {
9292
pid: childProcess.pid,
9393
process: childProcess,
9494
lastOutput: '',
9595
isBlocked: false,
9696
startTime: new Date()
9797
};
98-
98+
9999
this.sessions.set(childProcess.pid, session);
100100

101+
// Timing telemetry
102+
const startTime = Date.now();
103+
let firstOutputTime: number | undefined;
104+
let lastOutputTime: number | undefined;
105+
const outputEvents: OutputEvent[] = [];
106+
let exitReason: TimingInfo['exitReason'] = 'timeout';
107+
101108
return new Promise((resolve) => {
102109
let resolved = false;
103110
let periodicCheck: NodeJS.Timeout | null = null;
104-
111+
105112
// Quick prompt patterns for immediate detection
106113
const quickPromptPatterns = />>>\s*$|>\s*$|\$\s*$|#\s*$/;
107-
114+
108115
const resolveOnce = (result: CommandExecutionResult) => {
109116
if (resolved) return;
110117
resolved = true;
111118
if (periodicCheck) clearInterval(periodicCheck);
119+
120+
// Add timing info if requested
121+
if (collectTiming) {
122+
const endTime = Date.now();
123+
result.timingInfo = {
124+
startTime,
125+
endTime,
126+
totalDurationMs: endTime - startTime,
127+
exitReason,
128+
firstOutputTime,
129+
lastOutputTime,
130+
timeToFirstOutputMs: firstOutputTime ? firstOutputTime - startTime : undefined,
131+
outputEvents: outputEvents.length > 0 ? outputEvents : undefined
132+
};
133+
}
134+
112135
resolve(result);
113136
};
114137

115138
childProcess.stdout.on('data', (data: any) => {
116139
const text = data.toString();
140+
const now = Date.now();
141+
142+
if (!firstOutputTime) firstOutputTime = now;
143+
lastOutputTime = now;
144+
117145
output += text;
118146
session.lastOutput += text;
119-
147+
148+
// Record output event if collecting timing
149+
if (collectTiming) {
150+
outputEvents.push({
151+
timestamp: now,
152+
deltaMs: now - startTime,
153+
source: 'stdout',
154+
length: text.length,
155+
snippet: text.slice(0, 50).replace(/\n/g, '\\n')
156+
});
157+
}
158+
120159
// Immediate check for obvious prompts
121160
if (quickPromptPatterns.test(text)) {
122161
session.isBlocked = true;
162+
exitReason = 'early_exit_quick_pattern';
163+
164+
if (collectTiming && outputEvents.length > 0) {
165+
outputEvents[outputEvents.length - 1].matchedPattern = 'quick_pattern';
166+
}
167+
123168
resolveOnce({
124169
pid: childProcess.pid!,
125170
output,
@@ -130,8 +175,24 @@ export class TerminalManager {
130175

131176
childProcess.stderr.on('data', (data: any) => {
132177
const text = data.toString();
178+
const now = Date.now();
179+
180+
if (!firstOutputTime) firstOutputTime = now;
181+
lastOutputTime = now;
182+
133183
output += text;
134184
session.lastOutput += text;
185+
186+
// Record output event if collecting timing
187+
if (collectTiming) {
188+
outputEvents.push({
189+
timestamp: now,
190+
deltaMs: now - startTime,
191+
source: 'stderr',
192+
length: text.length,
193+
snippet: text.slice(0, 50).replace(/\n/g, '\\n')
194+
});
195+
}
135196
});
136197

137198
// Periodic comprehensive check every 100ms
@@ -140,6 +201,7 @@ export class TerminalManager {
140201
const processState = analyzeProcessState(output, childProcess.pid);
141202
if (processState.isWaitingForInput) {
142203
session.isBlocked = true;
204+
exitReason = 'early_exit_periodic_check';
143205
resolveOnce({
144206
pid: childProcess.pid!,
145207
output,
@@ -152,6 +214,7 @@ export class TerminalManager {
152214
// Timeout fallback
153215
setTimeout(() => {
154216
session.isBlocked = true;
217+
exitReason = 'timeout';
155218
resolveOnce({
156219
pid: childProcess.pid!,
157220
output,
@@ -169,15 +232,16 @@ export class TerminalManager {
169232
startTime: session.startTime,
170233
endTime: new Date()
171234
});
172-
235+
173236
// Keep only last 100 completed sessions
174237
if (this.completedSessions.size > 100) {
175238
const oldestKey = Array.from(this.completedSessions.keys())[0];
176239
this.completedSessions.delete(oldestKey);
177240
}
178-
241+
179242
this.sessions.delete(childProcess.pid);
180243
}
244+
exitReason = 'process_exit';
181245
resolveOnce({
182246
pid: childProcess.pid!,
183247
output,

0 commit comments

Comments
 (0)