Skip to content

Commit 9234ebd

Browse files
author
Sean Roberts
committed
fix: cli duration outputs
1 parent 15a8f39 commit 9234ebd

7 files changed

Lines changed: 55 additions & 22 deletions

File tree

src/adapters/base/acp-adapter.ts

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -112,8 +112,6 @@ interface AcpState {
112112
activeToolCalls: Map<string, { title: string; kind?: string }>;
113113
/** Cumulative session cost from usage_update events. */
114114
totalCostUsd?: number;
115-
/** Duration of the prompt() call only (excludes ACP handshake and process lifecycle). */
116-
promptDurationMs?: number;
117115
}
118116

119117
// ---------------------------------------------------------------------------
@@ -289,13 +287,15 @@ export function createAcpBasedAdapter(spec: AcpAdapterSpec): AgentAdapter {
289287
input.onRawLine?.(line);
290288
}
291289

292-
// 14. Send prompt and wait for completion — time just the agent work
293-
const promptStart = Date.now();
290+
// 14. Send prompt and wait for completion. Signal "agent is now
291+
// doing real work" — for ACP adapters the initialize+newSession
292+
// handshake can take 10–20s (kiro-cli AWS auth, etc.) and shouldn't
293+
// count as `running` in the live UI.
294+
input.onAgentReady?.();
294295
const promptResult = await connection.prompt({
295296
sessionId: sessionResult.sessionId,
296297
prompt: [{ type: "text", text: input.prompt }],
297298
});
298-
state.promptDurationMs = Date.now() - promptStart;
299299
{
300300
const line = JSON.stringify({ type: "prompt_result", ...promptResult });
301301
rawOutput?.push(line);
@@ -391,7 +391,7 @@ export function createAcpBasedAdapter(spec: AcpAdapterSpec): AgentAdapter {
391391
const metadata: AgentMetadata = {
392392
startTime: startTime.toISOString(),
393393
endTime: endTime.toISOString(),
394-
durationMs: state.promptDurationMs ?? endTime.getTime() - startTime.getTime(),
394+
durationMs: endTime.getTime() - startTime.getTime(),
395395
exitCode,
396396
tokenUsage: state.tokenUsage,
397397
totalCostUsd: state.totalCostUsd,

src/report-ui/src/scripts/render.ts

Lines changed: 7 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -767,9 +767,13 @@ function renderWaterfall(si: SparseIndex, totalDurationMs: number): string {
767767
const hasTimingData = interactions.some((ix) => ix.startMs !== null);
768768
if (!hasTimingData || interactions.length === 0) return "";
769769

770-
// Prefer the agent's full run duration so the timeline matches the row's reported duration.
771-
// Fall back to the interaction window if the entry's duration is missing.
772-
const wallClockMs = totalDurationMs > 0 ? totalDurationMs : si.stats.wallClockMs || computeWallClock(interactions);
770+
// Interaction startMs values are measured from process spawn (wall clock),
771+
// so the chart axis must use wall-clock too. For ACP-based adapters
772+
// entry.durationMs is the prompt() time only (excludes handshake/shutdown)
773+
// and is smaller than the interactions' timeline — using it would push bars
774+
// off the right edge. Prefer sparse-index wallClockMs, fall back to entry
775+
// duration for adapters without stats, then to the interaction window.
776+
const wallClockMs = si.stats.wallClockMs || (totalDurationMs > 0 ? totalDurationMs : computeWallClock(interactions));
773777
if (wallClockMs <= 0) return "";
774778

775779
const ticks = computeTickMarks(wallClockMs);

src/runner/runner.ts

Lines changed: 16 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -251,15 +251,22 @@ export async function run(options: RunOptions = {}): Promise<RunOutput> {
251251

252252
const updateStatus = (index: number, status: JobStatus, durationMs?: number) => {
253253
const patch: Partial<JobState> = { status, durationMs };
254-
// Stamp the start time on the first transition into "running" so the
255-
// live UI can tick an elapsed-duration counter.
256-
if (status === "running" && jobStates[index].runStartedAt === undefined) {
254+
// Stamp the start time on the first transition into "starting"/"running"
255+
// so the live UI can tick an elapsed-duration counter that includes the
256+
// adapter's own startup (CLI cold start, ACP handshake, etc.).
257+
if ((status === "starting" || status === "running") && jobStates[index].runStartedAt === undefined) {
257258
patch.runStartedAt = Date.now();
258259
}
259260
jobStates[index] = { ...jobStates[index], ...patch };
260261
logger.onJobUpdate?.(jobStates, jobMeta);
261262
};
262263

264+
const promoteToRunning = (index: number) => {
265+
if (jobStates[index].status === "starting") {
266+
updateStatus(index, "running");
267+
}
268+
};
269+
263270
const setTeardown = (index: number, inTeardown: boolean) => {
264271
if (Boolean(jobStates[index].inTeardown) === inTeardown) return;
265272
jobStates[index] = { ...jobStates[index], inTeardown };
@@ -443,6 +450,7 @@ export async function run(options: RunOptions = {}): Promise<RunOutput> {
443450
logger,
444451
updateStatus,
445452
updateTokens,
453+
promoteToRunning,
446454
resolvedSkillMap,
447455
options.registerCleanup,
448456
options.debug ?? false,
@@ -492,6 +500,7 @@ async function executeJob(
492500
logger: Logger,
493501
updateStatus: (index: number, status: JobStatus, durationMs?: number) => void,
494502
updateTokens: (index: number, tokens: number, final?: boolean) => void,
503+
promoteToRunning: (index: number) => void,
495504
resolvedSkillMap: Map<string, ResolvedSkill>,
496505
registerCleanup?: (fn: () => void) => void,
497506
debug?: boolean,
@@ -618,7 +627,7 @@ async function executeJob(
618627
}
619628

620629
try {
621-
updateStatus(index, "running");
630+
updateStatus(index, "starting");
622631
logger.verbose?.(`[${label}] Executing agent...`);
623632

624633
// Merge top-level + per-agent + per-scenario skills, deduplicate by source
@@ -648,6 +657,8 @@ async function executeJob(
648657
: axisConfig.mcp_servers,
649658
resolvedSkills: agentSkills.length > 0 ? agentSkills : undefined,
650659
onTokenProgress: (tokens) => {
660+
// First token from the agent → it's past startup, into real work.
661+
promoteToRunning(index);
651662
updateTokens(index, tokens);
652663
// Per-scenario token limit
653664
if (jobLimits?.tokenLimit && tokens >= jobLimits.tokenLimit) {
@@ -656,6 +667,7 @@ async function executeJob(
656667
// Overall token limit (checks cumulative across all jobs)
657668
checkOverallTokenLimit?.();
658669
},
670+
onAgentReady: () => promoteToRunning(index),
659671
...(jobLimits?.timeoutMs ? { timeoutMs: jobLimits.timeoutMs } : {}),
660672
...(jobAbortController ? { signal: jobAbortController.signal } : {}),
661673
debug,

src/types/agent.ts

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -86,6 +86,14 @@ export interface AgentInput {
8686
* below the true count so the UI never has to reverse.
8787
*/
8888
onTokenProgress?: (estimatedTokens: number) => void;
89+
/**
90+
* Adapters call this when the agent has finished its own startup work
91+
* (CLI cold start, ACP handshake, session bootstrap) and is actually
92+
* processing the prompt. The runner uses it to flip job status from
93+
* `starting` to `running`. Adapters with negligible startup may skip
94+
* calling it — the first `onTokenProgress` will auto-promote.
95+
*/
96+
onAgentReady?: () => void;
8997
/** Override the adapter's default timeout (in ms). Set by the runner from resolved scenario limits. */
9098
timeoutMs?: number;
9199
/** Abort signal. When fired, the adapter kills the child process with SIGTERM → SIGKILL. */

src/types/output.ts

Lines changed: 5 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -64,7 +64,7 @@ export interface RunSummary {
6464
skipped?: number;
6565
}
6666

67-
export type JobStatus = "pending" | "setup" | "running" | "teardown" | "done" | "failed" | "scoring";
67+
export type JobStatus = "pending" | "setup" | "starting" | "running" | "teardown" | "done" | "failed" | "scoring";
6868

6969
export interface JobState {
7070
scenarioKey: string;
@@ -87,9 +87,10 @@ export interface JobState {
8787
*/
8888
tokensFinal?: boolean;
8989
/**
90-
* Wall-clock ms-epoch when the agent transitioned to `running`. Used by the
91-
* live UI to tick an elapsed-duration counter before the job finishes (once
92-
* finished, `durationMs` takes over as the authoritative value).
90+
* Wall-clock ms-epoch when the agent transitioned out of `pending` into
91+
* `starting`/`running`. Used by the live UI to tick an elapsed-duration
92+
* counter before the job finishes (once finished, `durationMs` takes over
93+
* as the authoritative value).
9394
*/
9495
runStartedAt?: number;
9596
/**

src/ui/LiveStatus.tsx

Lines changed: 11 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -12,7 +12,13 @@ interface LiveStatusProps {
1212
/** A job is "active" when it's mid-flight — counts toward the live scenario list. */
1313
function isActive(job: JobState): boolean {
1414
if (job.inTeardown) return true;
15-
return job.status === "setup" || job.status === "running" || job.status === "teardown" || job.status === "scoring";
15+
return (
16+
job.status === "setup" ||
17+
job.status === "starting" ||
18+
job.status === "running" ||
19+
job.status === "teardown" ||
20+
job.status === "scoring"
21+
);
1622
}
1723

1824
export function LiveStatus({ jobs, skippedCount = 0 }: LiveStatusProps) {
@@ -109,15 +115,15 @@ function AgentRow({ job }: { job: JobState }) {
109115
? "green"
110116
: job.status === "failed"
111117
? "red"
112-
: job.status === "running" || job.status === "scoring"
118+
: job.status === "starting" || job.status === "running" || job.status === "scoring"
113119
? "yellow"
114120
: undefined;
115121

116122
// The timer and token counter are both visible in every state where they
117-
// have a value. The timer shows live-elapsed during running/scoring and
118-
// the final `durationMs` afterwards. The token counter keeps animating
123+
// have a value. The timer shows live-elapsed during starting/running/scoring
124+
// and the final `durationMs` afterwards. The token counter keeps animating
119125
// until it catches up to the final real total even after the job is done.
120-
const active = job.status === "running" || job.status === "scoring";
126+
const active = job.status === "starting" || job.status === "running" || job.status === "scoring";
121127
const hasTime = job.runStartedAt !== undefined || job.durationMs !== undefined;
122128
const hasTokens = (job.liveTokens ?? 0) > 0;
123129

src/ui/format.ts

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -45,6 +45,7 @@ const CRITERION_MEDIUM = 4;
4545
export const STATUS_ICONS: Record<string, string> = {
4646
pending: "○",
4747
setup: "◌",
48+
starting: "◔",
4849
running: "●",
4950
teardown: "◌",
5051
done: "✓",
@@ -55,6 +56,7 @@ export const STATUS_ICONS: Record<string, string> = {
5556
export const STATUS_LABELS: Record<string, string> = {
5657
pending: "pending",
5758
setup: "setup",
59+
starting: "starting",
5860
running: "running",
5961
teardown: "teardown",
6062
done: "done",

0 commit comments

Comments
 (0)