/**
* Tests for the working-time tracker and its extension wiring.
*
* The tracker measures two metrics: `worked` (model streaming only,
* tools excluded) and `totalMs` (wall-clock from user prompt to settle,
* retries/tools/overhead included). The wiring drives it from pi
* lifecycle events: before_agent_start / agent_start /
* before_provider_request / message_end / agent_settled. The durable
* history line is produced via pi.appendEntry + registerEntryRenderer.
*/
import { beforeEach, describe, expect, it, vi } from "vitest";
import piFaceliftExtension from "./index.ts";
import {
formatClock,
WorkingTimeTracker,
WORKING_TIME_ENTRY,
workingMessageText,
workingTimeLine,
type WorkingTimeEntry,
} from "./working-time.ts";
describe("WorkingTimeTracker", () => {
it("accumulates a single streaming segment", () => {
let now = 1000;
const t = new WorkingTimeTracker(() => now);
t.beginRun();
now = 2000;
t.beginSegment();
now = 4500;
t.endSegment();
expect(t.elapsedMs()).toBe(2500);
const entry = t.settle();
expect(entry?.ms).toBe(2500);
expect(entry?.startedAt).toBe(1000);
});
it("measures totalMs as wall-clock across the whole run (incl. tool gap)", () => {
let now = 0;
const t = new WorkingTimeTracker(() => now);
t.beginRun();
t.beginSegment();
now = 1000;
t.endSegment();
// tool + overhead from 1000..9000 counts toward total, not worked
now = 9000;
t.beginSegment();
now = 10000;
t.endSegment();
const entry = t.settle();
expect(entry?.ms).toBe(2000);
expect(entry?.totalMs).toBe(10000);
});
it("ensureRun does not reset an in-progress run", () => {
let now = 0;
const t = new WorkingTimeTracker(() => now);
t.beginRun();
t.beginSegment();
now = 500;
t.endSegment();
now = 1000;
t.ensureRun(); // agent_start fallback mid-run — must not reset
expect(t.elapsedMs()).toBe(500);
now = 3000;
expect(t.settle()?.totalMs).toBe(3000);
});
it("estimates live tps from streamed deltas over worked time", () => {
let now = 0;
const t = new WorkingTimeTracker(() => now);
t.beginRun();
t.beginSegment();
t.addDelta(4000); // ~1000 estimated tokens at 4 chars/token
now = 2000; // 2s of worked time
expect(t.estimatedTokens()).toBe(1000);
expect(t.liveTps()).toBe(500); // 1000 tokens / 2s
});
it("liveTps is 0 before any time elapses", () => {
const t = new WorkingTimeTracker(() => 0);
t.beginRun();
t.beginSegment();
t.addDelta(400);
expect(t.liveTps()).toBe(0);
});
it("computes exact final tps from recorded tokens over worked ms", () => {
let now = 0;
const t = new WorkingTimeTracker(() => now);
t.beginRun();
t.beginSegment();
now = 2000;
t.recordExactTokens(1500);
t.endSegment();
const entry = t.settle();
expect(entry?.tokens).toBe(1500);
expect(entry?.tps).toBe(750); // 1500 tokens / 2s worked
});
it("excludes the gap between segments (tool execution time)", () => {
let now = 0;
const t = new WorkingTimeTracker(() => now);
t.beginRun();
// first model segment: 0..1000
t.beginSegment();
now = 1000;
t.endSegment();
// "tool" runs from 1000..9000 — must NOT count
now = 9000;
// second model segment: 9000..10000
t.beginSegment();
now = 10000;
t.endSegment();
expect(t.settle()?.ms).toBe(2000);
});
it("includes an open segment in elapsedMs while streaming", () => {
let now = 0;
const t = new WorkingTimeTracker(() => now);
t.beginRun();
t.beginSegment();
now = 3000;
expect(t.elapsedMs()).toBe(3000);
expect(t.isActive()).toBe(true);
});
it("returns undefined for a zero-time run", () => {
const t = new WorkingTimeTracker(() => 0);
t.beginRun();
expect(t.settle()).toBeUndefined();
});
it("resets state after settle", () => {
let now = 0;
const t = new WorkingTimeTracker(() => now);
t.beginRun();
t.beginSegment();
now = 1000;
t.endSegment();
t.settle();
expect(t.isActive()).toBe(false);
expect(t.elapsedMs()).toBe(0);
});
});
describe("formatClock", () => {
it("keeps one decimal below a minute", () => {
expect(formatClock(0)).toBe("0.0s");
expect(formatClock(45_200)).toBe("45.2s");
expect(formatClock(59_900)).toBe("59.9s");
});
it("formats minutes and seconds, always ending in seconds", () => {
expect(formatClock(60_000)).toBe("1m0s");
expect(formatClock(75_000)).toBe("1m15s");
expect(formatClock(720_000)).toBe("12m0s"); // 0h12m0s -> 12m0s
});
it("formats hours, keeping interior zeros", () => {
expect(formatClock(4_356_000)).toBe("1h12m36s");
expect(formatClock(3_605_000)).toBe("1h0m5s");
expect(formatClock(3_600_000)).toBe("1h0m0s");
});
it("drops the leading zero hours part", () => {
expect(formatClock(65_000)).toBe("1m5s"); // 0h1m5s -> 1m5s
});
it("never returns a negative duration", () => {
expect(formatClock(-5000)).toBe("0.0s");
});
});
describe("workingMessageText / workingTimeLine", () => {
it("formats the live message using formatClock rules", () => {
expect(workingMessageText(0, 0)).toBe("Working... 0.0s · tps: ~0");
expect(workingMessageText(1999, 120)).toBe("Working... 2.0s · tps: ~120");
expect(workingMessageText(65_000, 756)).toBe("Working... 1m5s · tps: ~756");
expect(workingMessageText(720_000, 800)).toBe("Working... 12m0s · tps: ~800");
});
it("renders a muted history line with worked, total and exact tps", () => {
const dim = (s: string) => `${s}`;
const entry: WorkingTimeEntry = {
ms: 45_200,
totalMs: 75_000,
tokens: 34_200,
tps: 756,
startedAt: 0,
endedAt: 0,
};
expect(workingTimeLine(entry, dim)).toBe("⏱ worked 45.2s (total: 1m15s) · tps: 756");
});
});
// --- extension wiring ---------------------------------------------------
class MockText {
private text: string;
constructor(text = "", _x = 0, _y = 0) {
this.text = text;
}
setText(value: string) {
this.text = value;
}
getText() {
return this.text;
}
}
function mockToolFactory(exec: any) {
return (_cwd: string) => ({
name: "mock",
description: "mock",
parameters: { type: "object", properties: {} },
execute: exec,
});
}
interface MockCtx {
hasUI: boolean;
ui: { setWorkingMessage: ReturnType };
}
function loadExtension() {
const handlers = new Map void>();
const entryRenderers = new Map unknown>();
const entries: Array<{ type: string; data: unknown }> = [];
const pi = {
registerTool: () => {},
registerCommand: () => {},
on: (name: string, h: (event: unknown, ctx: MockCtx) => void) => handlers.set(name, h),
registerEntryRenderer: (type: string, r: any) => entryRenderers.set(type, r),
appendEntry: (type: string, data: unknown) => entries.push({ type, data }),
};
const noopExec = async () => ({ content: [{ type: "text", text: "" }] });
piFaceliftExtension(pi as any, {
sdk: {
createReadToolDefinition: mockToolFactory(noopExec),
getAgentDir: () => "/tmp/pi-facelift-test",
},
TextComponent: MockText as any,
});
const ctx: MockCtx = { hasUI: true, ui: { setWorkingMessage: vi.fn() } };
const fire = (name: string, event: unknown) => handlers.get(name)?.(event, ctx);
return { fire, ctx, entries, entryRenderers };
}
const asst = { message: { role: "assistant" } };
const user = { message: { role: "user" } };
describe("working-time wiring", () => {
beforeEach(() => vi.restoreAllMocks());
it("worked counts request→message_end; total counts the whole run", () => {
vi.useFakeTimers();
const { fire, entries } = loadExtension();
fire("before_agent_start", {}); // anchors the total clock
vi.advanceTimersByTime(500); // pre-loop overhead
fire("agent_start", {});
fire("before_provider_request", {});
vi.advanceTimersByTime(5000);
fire("message_end", asst);
// tool gap — counts toward total, NOT worked
vi.advanceTimersByTime(3000);
fire("before_provider_request", {});
vi.advanceTimersByTime(2000);
fire("message_end", asst);
fire("agent_settled", {});
vi.useRealTimers();
expect(entries).toHaveLength(1);
expect(entries[0].type).toBe(WORKING_TIME_ENTRY);
const data = entries[0].data as WorkingTimeEntry;
expect(data.ms).toBe(7000);
expect(data.totalMs).toBe(10500); // 500 + 5000 + 3000 + 2000
});
it("tracks live estimated tps (~) and final exact tps from usage.output", () => {
vi.useFakeTimers();
const { fire, entries, ctx } = loadExtension();
fire("before_agent_start", {});
fire("agent_start", {});
fire("before_provider_request", {});
// Stream ~4000 chars => ~1000 estimated tokens over 2s of worked time.
fire("message_update", {
message: { role: "assistant" },
assistantMessageEvent: { type: "text_delta", delta: "x".repeat(4000) },
});
vi.advanceTimersByTime(2000);
const calls = ctx.ui.setWorkingMessage.mock.calls.map((c) => c[0]);
expect(calls).toContain("Working... 2.0s · tps: ~500");
// Final exact tokens come from usage.output, not the estimate.
fire("message_end", { message: { role: "assistant", usage: { output: 1500 } } });
fire("agent_settled", {});
vi.useRealTimers();
expect(entries).toHaveLength(1);
const data = entries[0].data as WorkingTimeEntry;
expect(data.tokens).toBe(1500);
expect(data.tps).toBe(750); // 1500 / 2s worked
});
it("ignores non-assistant message_end (does not close the segment early)", () => {
vi.useFakeTimers();
const { fire, entries } = loadExtension();
fire("before_agent_start", {});
fire("agent_start", {});
fire("before_provider_request", {});
vi.advanceTimersByTime(1000);
fire("message_end", user); // stray non-assistant end — ignored
vi.advanceTimersByTime(1000);
fire("message_end", asst);
fire("agent_settled", {});
vi.useRealTimers();
expect(entries).toHaveLength(1);
expect((entries[0].data as WorkingTimeEntry).ms).toBe(2000);
});
it("updates the live working message from request send and restores on settle", () => {
vi.useFakeTimers();
const { fire, ctx } = loadExtension();
fire("before_agent_start", {});
fire("agent_start", {});
fire("before_provider_request", {});
vi.advanceTimersByTime(2000);
const calls = ctx.ui.setWorkingMessage.mock.calls.map((c) => c[0]);
expect(calls[0]).toBe("Working... 0.0s · tps: ~0");
expect(calls).toContain("Working... 2.0s · tps: ~0");
fire("message_end", asst);
fire("agent_settled", {});
vi.useRealTimers();
// last call restores the default (undefined)
const last = ctx.ui.setWorkingMessage.mock.calls.at(-1);
expect(last?.[0]).toBeUndefined();
});
it("registers an entry renderer that produces a dim worked+total line", () => {
const { entryRenderers } = loadExtension();
const renderer = entryRenderers.get(WORKING_TIME_ENTRY);
expect(renderer).toBeDefined();
const theme = { fg: (_k: string, s: string) => `dim(${s})` };
const out = renderer!(
{ data: { ms: 1500, totalMs: 4000, tokens: 300, tps: 200, startedAt: 0, endedAt: 0 } },
{ expanded: false },
theme,
) as MockText;
expect(out.getText()).toBe("dim(⏱ worked 1.5s (total: 4.0s) · tps: 200)");
});
});