Skip to content

Commit df6803b

Browse files
authored
feat(init): measure interactive prompt wait time (#1257)
## Summary Separates human think-time from actual `sentry init` execution time. Every real Ink prompt now emits a `ui.prompt` child span, while automatic `--yes` and non-interactive paths remain uninstrumented. The root transaction also gets an accumulated `wizard.user_wait_ms` measurement, so active wizard time can be calculated as total duration minus user wait. Workflow prompts include the active step ID (for example `select-features`); welcome, git, and preflight prompts are marked as `preflight`. Feature selection now records `wizard.features.offered` before the prompt and `wizard.features.selected` after the response. This preserves the offered set even when the user cancels at the feature prompt or the workflow fails later. ## Test plan - `pnpm exec tsc --noEmit` - `pnpm exec biome check src/lib/telemetry.ts src/lib/init/interactive.ts src/lib/init/ui/ink-ui.ts test/lib/telemetry.test.ts test/lib/init/interactive.test.ts test/lib/init/ui/ink-ui-telemetry.test.ts` - `pnpm vitest run test/lib/init` - `pnpm vitest run test/lib/telemetry.test.ts`
1 parent 39b25bd commit df6803b

6 files changed

Lines changed: 385 additions & 11 deletions

File tree

src/lib/init/interactive.ts

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,7 @@
1010
* `LoggingUI` (CI / npm fallback).
1111
*/
1212

13+
import { setTag } from "@sentry/node-core/light";
1314
import chalk from "chalk";
1415
import { WizardError } from "../errors.js";
1516
import {
@@ -198,6 +199,7 @@ async function handleMultiSelect(
198199
}
199200
hints.push(`${bar} ${chalk.dim("space=toggle, a=all, enter=confirm")}`);
200201

202+
setTag("wizard.features.offered", available.join(","));
201203
const selected = await ui.multiselect<string>({
202204
message: `${payload.prompt}\n${hints.join("\n")}`,
203205
options: optional.map((feature) => {
@@ -213,7 +215,9 @@ async function handleMultiSelect(
213215
});
214216

215217
const chosen = abortIfCancelled(selected);
216-
return { features: prependRequiredFeature(chosen, hasRequired) };
218+
const features = prependRequiredFeature(chosen, hasRequired);
219+
setTag("wizard.features.selected", features.join(","));
220+
return { features };
217221
}
218222

219223
async function handleConfirm(

src/lib/init/ui/ink-ui.ts

Lines changed: 52 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -56,6 +56,10 @@ import { setTag } from "@sentry/node-core/light";
5656
import { FULL_BANNER_LINES } from "../../banner.js";
5757
import { CLI_VERSION } from "../../constants.js";
5858
import { stripAnsi } from "../../formatters/plain-detect.js";
59+
import {
60+
createWizardPromptTelemetry,
61+
type WizardPromptKind,
62+
} from "../../telemetry.js";
5963
import { formatFeedbackHint, type InitFeedbackOutcome } from "../feedback.js";
6064
import { formatFailureReport, formatSuccessReport } from "./ink-report.js";
6165
import { LEARN_SEQUENCE } from "./learn-content.js";
@@ -81,10 +85,16 @@ type CreateInkUIOptions = {
8185

8286
type PendingWelcome = {
8387
promise: Promise<"continue" | Cancelled>;
88+
tracedPromise?: Promise<"continue" | Cancelled>;
8489
resolve: (value: "continue" | Cancelled) => void;
8590
settled: boolean;
8691
};
8792

93+
type InkPromptOptions = {
94+
initialWelcome?: PendingWelcome;
95+
telemetry?: ReturnType<typeof createWizardPromptTelemetry>;
96+
};
97+
8898
/** Tip rotation cadence in the sidebar — slow enough to read each tip. */
8999
const TIP_ROTATE_INTERVAL_MS = 15_000;
90100

@@ -273,6 +283,7 @@ export async function createInkUI(
273283
if (opts.initialWelcome && initialWelcome) {
274284
seedWelcomePrompt(store, opts.initialWelcome, initialWelcome);
275285
}
286+
const promptTelemetry = createWizardPromptTelemetry();
276287

277288
// Open a fresh /dev/tty so Ink's `readable` event listener
278289
// actually fires — see the module docstring for the Bun bug
@@ -305,7 +316,10 @@ export async function createInkUI(
305316
try {
306317
const instance = app.mountApp(store, renderOptions);
307318

308-
return new InkUI(instance, store, freshStdin, initialWelcome);
319+
return new InkUI(instance, store, freshStdin, {
320+
initialWelcome,
321+
telemetry: promptTelemetry,
322+
});
309323
} catch (error) {
310324
// Restore the terminal if Ink rendering or UI init fails,
311325
// otherwise the user is stuck in the alternate screen buffer.
@@ -356,6 +370,9 @@ export class InkUI implements WizardUI {
356370
* `process.stdin` in that case.
357371
*/
358372
private readonly freshStdin: ReadStream | null;
373+
private readonly promptTelemetry: ReturnType<
374+
typeof createWizardPromptTelemetry
375+
>;
359376
private tipTimer: ReturnType<typeof setInterval> | undefined;
360377
private learnTimer: ReturnType<typeof setInterval> | undefined;
361378

@@ -401,13 +418,23 @@ export class InkUI implements WizardUI {
401418
instance: InkInstance,
402419
store: WizardStore,
403420
freshStdin: ReadStream | null,
404-
initialWelcome?: PendingWelcome
421+
promptOptions: InkPromptOptions = {}
405422
) {
406423
this.instance = instance;
407424
this.store = store;
408425
this.freshStdin = freshStdin;
409-
this.initialWelcome = initialWelcome;
410-
if (initialWelcome && !initialWelcome.settled) {
426+
this.initialWelcome = promptOptions.initialWelcome;
427+
this.promptTelemetry =
428+
promptOptions.telemetry ?? createWizardPromptTelemetry();
429+
if (this.initialWelcome && !this.initialWelcome.tracedPromise) {
430+
const initialWelcome = this.initialWelcome;
431+
initialWelcome.tracedPromise = this.promptTelemetry.tracePrompt(
432+
"welcome",
433+
() => initialWelcome.promise
434+
);
435+
}
436+
if (this.initialWelcome && !this.initialWelcome.settled) {
437+
const initialWelcome = this.initialWelcome;
411438
this.activePromptCancel = () => {
412439
this.store.setPrompt(null);
413440
this.activePromptCancel = undefined;
@@ -469,6 +496,7 @@ export class InkUI implements WizardUI {
469496
stepId: string,
470497
status: "in_progress" | "completed" | "failed" | "skipped"
471498
): void {
499+
this.promptTelemetry.setActiveStep(stepId, status === "in_progress");
472500
this.store.setStepStatus(stepId, status);
473501
}
474502

@@ -543,8 +571,16 @@ export class InkUI implements WizardUI {
543571

544572
// ── Prompts ───────────────────────────────────────────────────────
545573

574+
/** Measures only the interval in which the prompt can accept user input. */
575+
private waitForPrompt<T>(
576+
kind: WizardPromptKind,
577+
mount: (resolve: (value: T) => void) => void
578+
): Promise<T> {
579+
return this.promptTelemetry.tracePrompt(kind, () => new Promise<T>(mount));
580+
}
581+
546582
select<T extends string>(opts: SelectOptions<T>): Promise<T | Cancelled> {
547-
return new Promise((resolve) => {
583+
return this.waitForPrompt<T | Cancelled>("select", (resolve) => {
548584
const initialIndex =
549585
opts.initialValue !== undefined
550586
? Math.max(
@@ -584,7 +620,7 @@ export class InkUI implements WizardUI {
584620
multiselect<T extends string>(
585621
opts: MultiSelectOptions<T>
586622
): Promise<T[] | Cancelled> {
587-
return new Promise((resolve) => {
623+
return this.waitForPrompt<T[] | Cancelled>("multiselect", (resolve) => {
588624
this.activePromptCancel = () => {
589625
this.store.setPrompt(null);
590626
this.activePromptCancel = undefined;
@@ -614,7 +650,7 @@ export class InkUI implements WizardUI {
614650
}
615651

616652
confirm(opts: ConfirmOptions): Promise<boolean | Cancelled> {
617-
return new Promise<boolean | Cancelled>((resolve) => {
653+
return this.waitForPrompt<boolean | Cancelled>("confirm", (resolve) => {
618654
this.activePromptCancel = () => {
619655
this.store.setPrompt(null);
620656
this.activePromptCancel = undefined;
@@ -644,12 +680,19 @@ export class InkUI implements WizardUI {
644680
if (!this.initialWelcome.settled) {
645681
seedWelcomePrompt(this.store, opts, this.initialWelcome);
646682
}
647-
return this.initialWelcome.promise.finally(() => {
683+
const initialWelcome = this.initialWelcome;
684+
const promptPromise =
685+
initialWelcome.tracedPromise ??
686+
this.promptTelemetry.tracePrompt(
687+
"welcome",
688+
() => initialWelcome.promise
689+
);
690+
return promptPromise.finally(() => {
648691
this.activePromptCancel = undefined;
649692
this.initialWelcome = undefined;
650693
});
651694
}
652-
return new Promise<"continue" | Cancelled>((resolve) => {
695+
return this.waitForPrompt<"continue" | Cancelled>("welcome", (resolve) => {
653696
this.activePromptCancel = () => {
654697
this.store.setPrompt(null);
655698
this.activePromptCancel = undefined;

src/lib/telemetry.ts

Lines changed: 67 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -922,6 +922,73 @@ export function recordCacheHit(cacheName: string, hit: boolean): void {
922922
});
923923
}
924924

925+
export type WizardPromptKind = "select" | "multiselect" | "confirm" | "welcome";
926+
927+
type WizardPromptTelemetry = {
928+
setActiveStep(stepId: string, active: boolean): void;
929+
tracePrompt<T>(kind: WizardPromptKind, prompt: () => Promise<T>): Promise<T>;
930+
};
931+
932+
/**
933+
* Track time spent waiting for human input during `sentry init`.
934+
*
935+
* Prompt spans make user think-time visible in the trace instead of folding it
936+
* into the top-level `sentry.init` duration. The measurement is accumulated on
937+
* the root span so a run can be compared both with and without user wait time.
938+
*/
939+
export function createWizardPromptTelemetry(): WizardPromptTelemetry {
940+
let activeStepId: string | undefined;
941+
let totalWaitMs = 0;
942+
943+
return {
944+
setActiveStep(stepId, active) {
945+
if (active) {
946+
activeStepId = stepId;
947+
} else if (activeStepId === stepId) {
948+
activeStepId = undefined;
949+
}
950+
},
951+
tracePrompt(kind, prompt) {
952+
const stepId = activeStepId;
953+
return withTracingSpan(
954+
`wizard.prompt.${kind}`,
955+
"ui.prompt",
956+
async (span) => {
957+
const startedAt = performance.now();
958+
try {
959+
return await prompt();
960+
} finally {
961+
const waitMs = Math.max(0, performance.now() - startedAt);
962+
totalWaitMs += waitMs;
963+
964+
span.setAttributes({
965+
"wizard.user_wait_ms": waitMs,
966+
"wizard.user_wait_total_ms": totalWaitMs,
967+
});
968+
Sentry.setMeasurement(
969+
"wizard.user_wait_ms",
970+
totalWaitMs,
971+
"millisecond",
972+
Sentry.getRootSpan(span)
973+
);
974+
Sentry.metrics.distribution("wizard.user_wait_ms", waitMs, {
975+
attributes: {
976+
prompt_kind: kind,
977+
...(stepId ? { workflow_step: stepId } : {}),
978+
},
979+
});
980+
}
981+
},
982+
{
983+
"wizard.prompt.kind": kind,
984+
"wizard.prompt.phase": stepId ? "workflow" : "preflight",
985+
...(stepId ? { "wizard.step.id": stepId } : {}),
986+
}
987+
);
988+
},
989+
};
990+
}
991+
925992
/**
926993
* Wrap an operation with a Sentry span for tracing.
927994
*

test/lib/init/interactive.test.ts

Lines changed: 46 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,9 @@
77
* terminal.
88
*/
99

10-
import { describe, expect, test } from "vitest";
10+
// biome-ignore lint/performance/noNamespaceImport: needed for spyOn mocking
11+
import * as Sentry from "@sentry/node-core/light";
12+
import { afterEach, describe, expect, test, vi } from "vitest";
1113
import { WizardError } from "../../../src/lib/errors.js";
1214
import { handleInteractive } from "../../../src/lib/init/interactive.js";
1315
import type { InteractiveContext } from "../../../src/lib/init/types.js";
@@ -24,6 +26,10 @@ function makeOptions(
2426
};
2527
}
2628

29+
afterEach(() => {
30+
vi.restoreAllMocks();
31+
});
32+
2733
describe("handleInteractive dispatcher", () => {
2834
test("throws WizardError for unknown kind", async () => {
2935
const { ui } = createMockUI();
@@ -270,6 +276,36 @@ describe("handleSelect with --app flag", () => {
270276
});
271277

272278
describe("handleMultiSelect", () => {
279+
test("records offered and selected features for interactive prompts", async () => {
280+
const setTagSpy = vi.spyOn(Sentry, "setTag");
281+
const { ui, respond } = createMockUI();
282+
respond.multiselect(["sessionReplay"]);
283+
284+
await handleInteractive(
285+
{
286+
type: "interactive",
287+
prompt: "Select features",
288+
kind: "multi-select",
289+
availableFeatures: [
290+
"errorMonitoring",
291+
"performanceMonitoring",
292+
"sessionReplay",
293+
],
294+
},
295+
makeOptions(),
296+
ui
297+
);
298+
299+
expect(setTagSpy).toHaveBeenCalledWith(
300+
"wizard.features.offered",
301+
"errorMonitoring,performanceMonitoring,sessionReplay"
302+
);
303+
expect(setTagSpy).toHaveBeenCalledWith(
304+
"wizard.features.selected",
305+
"errorMonitoring,sessionReplay"
306+
);
307+
});
308+
273309
test("auto-selects all features with --yes", async () => {
274310
const { ui } = createMockUI();
275311
const result = await handleInteractive(
@@ -336,6 +372,7 @@ describe("handleMultiSelect", () => {
336372
});
337373

338374
test("throws WizardCancelledError when user cancels multi-select", async () => {
375+
const setTagSpy = vi.spyOn(Sentry, "setTag");
339376
const { ui, respond } = createMockUI();
340377
respond.multiselect(CANCELLED);
341378

@@ -351,6 +388,14 @@ describe("handleMultiSelect", () => {
351388
ui
352389
)
353390
).rejects.toThrow("Setup cancelled");
391+
expect(setTagSpy).toHaveBeenCalledWith(
392+
"wizard.features.offered",
393+
"errorMonitoring,performanceMonitoring"
394+
);
395+
expect(setTagSpy).not.toHaveBeenCalledWith(
396+
"wizard.features.selected",
397+
expect.anything()
398+
);
354399
});
355400

356401
test("returns required feature without calling multiselect when only errorMonitoring available", async () => {

0 commit comments

Comments
 (0)