authorgravatar for me@t3.ggTheo Browne <me@t3.gg> 2026-09-25 19:28:54-07:00
committergravatar for noreply@github.comGitHub <noreply@github.com> 2026-09-25 19:28:54-07:00
log75bf92e652f72cb0062c102236aeb130d1d714b3
tree00cb7541ba73821e1a4dba19d1bb0651f7553d0c
parent8aa5be2f02c3b4b9b5b3b86acbf5f2b0467438f4
signature Signed by PGP key B5690EEEBB952194

feat(cli): summarize the server trace file from the command line (#13698)

Co-authored-by: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

6 files changed, 361 insertions(+), 6 deletions(-)

apps/server/src/bin.ts+2
...@@ -24,6 +24,7 @@ import { serviceLauncherCommand } from "./cli/serviceLauncher.ts";...@@ -24,6 +24,7 @@ import { serviceLauncherCommand } from "./cli/serviceLauncher.ts";
24import { servicePreflightCommand } from "./cli/servicePreflight.ts";24import { servicePreflightCommand } from "./cli/servicePreflight.ts";
25import { sshHelperCommand } from "./cli/sshHelper.ts";25import { sshHelperCommand } from "./cli/sshHelper.ts";
26import { themeCommand } from "./cli/theme.ts";26import { themeCommand } from "./cli/theme.ts";
27import { traceCommand } from "./cli/trace.ts";
27import { triageCommand } from "./cli/triage.ts";28import { triageCommand } from "./cli/triage.ts";
2829
29const CliRuntimeLayer = Layer.mergeAll(NodeServices.layer, NetService.layer);30const CliRuntimeLayer = Layer.mergeAll(NodeServices.layer, NetService.layer);
...@@ -71,6 +72,7 @@ export const makeCli = ({ cloudEnabled = hasCloudPublicConfig } = {}) =>...@@ -71,6 +72,7 @@ export const makeCli = ({ cloudEnabled = hasCloudPublicConfig } = {}) =>
71 servicePreflightCommand,72 servicePreflightCommand,
72 sshHelperCommand,73 sshHelperCommand,
73 themeCommand,74 themeCommand,
75 traceCommand,
74 triageCommand,76 triageCommand,
75 cloudEnabled ? connectCommand : connectUnavailableCommand,77 cloudEnabled ? connectCommand : connectUnavailableCommand,
76 ]),78 ]),
apps/server/src/cli/config.ts+11-5
...@@ -82,16 +82,22 @@ const tailscaleServePortFlag = Flag.Int("tailscale-serve-port").pipe(...@@ -82,16 +82,22 @@ const tailscaleServePortFlag = Flag.Int("tailscale-serve-port").pipe(
82 Flag.optional,82 Flag.optional,
83);83);
8484
85// Trace file location, shared by the server and `t3 trace summary`.
86export const traceFileConfig = Config.String("T3CODE_TRACE_FILE").pipe(
87 Config.option,
88 Config.map(Option.getOrUndefined),
89);
90export const traceMaxFilesConfig = Config.Int("T3CODE_TRACE_MAX_FILES").pipe(
91 Config.withDefault(10),
92);
93
85const EnvServerConfig = Config.all({94const EnvServerConfig = Config.all({
86 logLevel: Config.LogLevel("T3CODE_LOG_LEVEL").pipe(Config.withDefault("Info")),95 logLevel: Config.LogLevel("T3CODE_LOG_LEVEL").pipe(Config.withDefault("Info")),
87 traceMinLevel: Config.LogLevel("T3CODE_TRACE_MIN_LEVEL").pipe(Config.withDefault("Info")),96 traceMinLevel: Config.LogLevel("T3CODE_TRACE_MIN_LEVEL").pipe(Config.withDefault("Info")),
88 traceTimingEnabled: Config.Boolean("T3CODE_TRACE_TIMING_ENABLED").pipe(Config.withDefault(true)),97 traceTimingEnabled: Config.Boolean("T3CODE_TRACE_TIMING_ENABLED").pipe(Config.withDefault(true)),
89 traceFile: Config.String("T3CODE_TRACE_FILE").pipe(98 traceFile: traceFileConfig,
90 Config.option,
91 Config.map(Option.getOrUndefined),
92 ),
93 traceMaxBytes: Config.Int("T3CODE_TRACE_MAX_BYTES").pipe(Config.withDefault(10 * 1024 * 1024)),99 traceMaxBytes: Config.Int("T3CODE_TRACE_MAX_BYTES").pipe(Config.withDefault(10 * 1024 * 1024)),
94 traceMaxFiles: Config.Int("T3CODE_TRACE_MAX_FILES").pipe(Config.withDefault(10)),100 traceMaxFiles: traceMaxFilesConfig,
95 traceBatchWindowMs: Config.Int("T3CODE_TRACE_BATCH_WINDOW_MS").pipe(Config.withDefault(1_000)),101 traceBatchWindowMs: Config.Int("T3CODE_TRACE_BATCH_WINDOW_MS").pipe(Config.withDefault(1_000)),
96 otlpTracesUrl: Config.String("T3CODE_OTLP_TRACES_URL").pipe(102 otlpTracesUrl: Config.String("T3CODE_OTLP_TRACES_URL").pipe(
97 Config.option,103 Config.option,
apps/server/src/cli/trace.test.ts created+100
...@@ -0,0 +1,100 @@
1import { assert, it } from "@effect/vitest";
2
3import { makeTraceSpanSummary } from "./trace.ts";
4
5const MINUTE_MS = 60_000;
6
7function span(name: string, durationMs: number, endMs: number, exitTag = "Success") {
8 return JSON.stringify({
9 type: "effect-span",
10 name,
11 traceId: "trace",
12 spanId: "span",
13 durationMs,
14 endTimeUnixNano: String(BigInt(endMs) * 1_000_000n),
15 exit: { _tag: exitTag, cause: "cause" },
16 });
17}
18
19function browserSpan(name: string, status: { code: string; message?: string }) {
20 return JSON.stringify({
21 type: "otlp-span",
22 name,
23 durationMs: 1,
24 endTimeUnixNano: "1000000",
25 status,
26 });
27}
28
29it("reports count, rate, percentiles, and exits per span name", () => {
30 // Ten `refresh` spans of 1..10 ms end over minutes 0..9, and one `probe`
31 // span ends at minute 10, so the recorded window is 10 minutes.
32 const refreshes = Array.from({ length: 10 }, (_, index) =>
33 span(
34 "refresh",
35 index + 1,
36 index * MINUTE_MS,
37 index === 0 ? "Interrupted" : index === 1 ? "Failure" : "Success",
38 ),
39 );
40 const summarizer = makeTraceSpanSummary();
41 [...refreshes, span("probe", 2_500, 10 * MINUTE_MS)].forEach(summarizer.addLine);
42 const summary = summarizer.finish();
43
44 assert.strictEqual(summary.spanCount, 11);
45 assert.strictEqual(summary.minutes, 10);
46 assert.deepStrictEqual(summary.spans, [
47 {
48 name: "refresh",
49 count: 10,
50 perMinute: 1,
51 p50Ms: 5,
52 p90Ms: 9,
53 maxMs: 10,
54 interrupted: 1,
55 failures: 1,
56 },
57 {
58 name: "probe",
59 count: 1,
60 perMinute: 0.1,
61 p50Ms: 2_500,
62 p90Ms: 2_500,
63 maxMs: 2_500,
64 interrupted: 0,
65 failures: 0,
66 },
67 ]);
68});
69
70it("drops spans that ended before the window and counts unreadable lines", () => {
71 const summarizer = makeTraceSpanSummary(MINUTE_MS);
72 [
73 span("old", 1, 0),
74 "",
75 "{not json",
76 JSON.stringify({ name: "no-duration" }),
77 // Ends past the largest Date, so the report could not print it.
78 JSON.stringify({ name: "far-future", durationMs: 1, endTimeUnixNano: "9".repeat(22) }),
79 span("recent", 4, 5 * MINUTE_MS),
80 ].forEach(summarizer.addLine);
81 const summary = summarizer.finish();
82
83 assert.strictEqual(summary.skippedLineCount, 3);
84 assert.deepStrictEqual(
85 summary.spans.map((entry) => [entry.name, entry.count, entry.perMinute]),
86 [["recent", 1, undefined]],
87 );
88});
89
90it("reads failures and interrupts of browser spans from their OTLP status", () => {
91 const summarizer = makeTraceSpanSummary();
92 [
93 browserSpan("render", { code: "2", message: "boom" }),
94 browserSpan("render", { code: "1", message: "Interrupted" }),
95 browserSpan("render", { code: "1" }),
96 ].forEach(summarizer.addLine);
97
98 const [render] = summarizer.finish().spans;
99 assert.deepStrictEqual([render?.count, render?.interrupted, render?.failures], [3, 1, 1]);
100});
apps/server/src/cli/trace.ts created+227
...@@ -0,0 +1,227 @@
1/**
2 * `t3 trace summary` - per-span counts, rates, and latency percentiles from
3 * the local server trace file and its rotated backups. It reads the files
4 * directly, so it works while the server is stalled or stopped.
5 */
6import { PositiveInt } from "@t3tools/contracts";
7import * as Clock from "effect/Clock";
8import * as Config from "effect/Config";
9import * as Console from "effect/Console";
10import * as DateTime from "effect/DateTime";
11import * as Duration from "effect/Duration";
12import * as Effect from "effect/Effect";
13import * as FileSystem from "effect/FileSystem";
14import * as Option from "effect/Option";
15import * as Schema from "effect/Schema";
16import * as Stream from "effect/Stream";
17import { Command, Flag } from "effect/unstable/cli";
18
19import * as ServerConfig from "../config.ts";
20import { toRotatedTracePaths, TraceFileReadError } from "../diagnostics/TraceDiagnostics.ts";
21import { resolveBaseDir } from "../os-jank.ts";
22import { baseDirFlag, DurationFromString, traceFileConfig, traceMaxFilesConfig } from "./config.ts";
23
24// Only the fields the summary needs. Other record fields are ignored.
25const decodeTraceSpanLine = Schema.decodeUnknownOption(
26 Schema.fromJsonString(
27 Schema.Struct({
28 name: Schema.String,
29 durationMs: Schema.Finite,
30 endTimeUnixNano: Schema.FiniteFromString,
31 // Server (`effect-span`) records.
32 exit: Schema.optional(Schema.Struct({ _tag: Schema.String })),
33 // Browser (`otlp-span`) records. Effect's OTLP tracer writes code "2" for
34 // errors and code "1" with message "Interrupted" for interrupts.
35 status: Schema.optional(
36 Schema.Struct({
37 code: Schema.optional(Schema.String),
38 message: Schema.optional(Schema.String),
39 }),
40 ),
41 }),
42 ),
43);
44
45/**
46 * Groups trace NDJSON by span name. Call `addLine` once per line as the files
47 * stream in, then `finish` for the summary. Spans that ended before `sinceMs`
48 * are left out. Rates are per minute between the first and last span end,
49 * since spans are written when they end.
50 */
51export function makeTraceSpanSummary(sinceMs = -Infinity) {
52 // Keep each span's duration (8 bytes, a few MB for the default 110 MB of
53 // rotated traces) for exact percentiles. A bounded sketch would save little
54 // and make p50 and p90 approximate.
55 const byName = new Map<string, { durations: number[]; interrupted: number; failures: number }>();
56 let spanCount = 0;
57 let skippedLineCount = 0;
58 let firstEndMs = Infinity;
59 let lastEndMs = -Infinity;
60
61 const addLine = (line: string) => {
62 if (line.trim().length === 0) return;
63 const span = Option.getOrUndefined(decodeTraceSpanLine(line));
64 if (span === undefined) {
65 skippedLineCount += 1;
66 return;
67 }
68 const endMs = span.endTimeUnixNano / 1_000_000;
69 // The report prints end times as dates, so skip ones outside the Date range.
70 if (Option.isNone(DateTime.make(endMs))) {
71 skippedLineCount += 1;
72 return;
73 }
74 if (endMs < sinceMs) return;
75
76 spanCount += 1;
77 firstEndMs = Math.min(firstEndMs, endMs);
78 lastEndMs = Math.max(lastEndMs, endMs);
79 const stats = byName.get(span.name) ?? { durations: [], interrupted: 0, failures: 0 };
80 stats.durations.push(span.durationMs);
81 if (span.exit?._tag === "Interrupted" || span.status?.message === "Interrupted") {
82 stats.interrupted += 1;
83 }
84 if (span.exit?._tag === "Failure" || span.status?.code === "2") stats.failures += 1;
85 byName.set(span.name, stats);
86 };
87
88 const finish = () => {
89 const minutes = (lastEndMs - firstEndMs) / 60_000;
90 const spans = [...byName]
91 .map(([name, { durations, interrupted, failures }]) => {
92 const sorted = durations.toSorted((left, right) => left - right);
93 // Nearest-rank percentile.
94 const percentile = (p: number) => sorted[Math.ceil(p * sorted.length) - 1]!;
95 return {
96 name,
97 count: sorted.length,
98 perMinute: minutes > 0 ? sorted.length / minutes : undefined,
99 p50Ms: percentile(0.5),
100 p90Ms: percentile(0.9),
101 maxMs: sorted[sorted.length - 1]!,
102 interrupted,
103 failures,
104 };
105 })
106 .toSorted((left, right) => right.count - left.count || left.name.localeCompare(right.name));
107
108 return { spanCount, skippedLineCount, firstEndMs, lastEndMs, minutes, spans };
109 };
110
111 return { addLine, finish };
112}
113
114const formatMs = (ms: number) =>
115 ms < 1_000 ? `${Math.round(ms)}ms` : `${(ms / 1_000).toFixed(1)}s`;
116
117function formatTraceSummary(
118 summary: ReturnType<ReturnType<typeof makeTraceSpanSummary>["finish"]>,
119 limit: number,
120) {
121 const header = ["span", "count", "/min", "p50", "p90", "max", "interrupted", "failed"];
122 const rows = summary.spans
123 .slice(0, limit)
124 .map((span) => [
125 span.name,
126 String(span.count),
127 span.perMinute === undefined
128 ? "-"
129 : span.perMinute < 0.1
130 ? "<0.1"
131 : span.perMinute.toFixed(1),
132 formatMs(span.p50Ms),
133 formatMs(span.p90Ms),
134 formatMs(span.maxMs),
135 String(span.interrupted),
136 String(span.failures),
137 ]);
138 const table = [header, ...rows];
139 const widths = header.map((_, column) => Math.max(...table.map((row) => row[column]!.length)));
140 const formatIso = (ms: number) => DateTime.formatIso(DateTime.makeUnsafe(ms));
141 return [
142 `${summary.spanCount} spans ended from ${formatIso(summary.firstEndMs)} to ${formatIso(summary.lastEndMs)} (${summary.minutes.toFixed(1)} min).`,
143 ...(summary.skippedLineCount > 0
144 ? [`Skipped ${summary.skippedLineCount} lines that are not spans.`]
145 : []),
146 "",
147 ...table.map((row) =>
148 row
149 .map((cell, column) =>
150 column === 0 ? cell.padEnd(widths[column]!) : cell.padStart(widths[column]!),
151 )
152 .join(" "),
153 ),
154 ...(summary.spans.length > limit
155 ? ["", `${summary.spans.length - limit} more span names. Use --limit to show more.`]
156 : []),
157 ].join("\n");
158}
159
160const traceSummaryCommand = Command.make("summary", {
161 baseDir: baseDirFlag,
162 since: Flag.String("since").pipe(
163 Flag.withSchema(DurationFromString),
164 Flag.withDescription("Only count spans that ended in this window, for example 30m or 2h."),
165 Flag.optional,
166 ),
167 limit: Flag.Int("limit").pipe(
168 Flag.withSchema(PositiveInt),
169 Flag.withDescription("Number of span names to show, busiest first."),
170 Flag.withDefault(25),
171 ),
172}).pipe(
173 Command.withDescription("Summarize the local server trace file: counts, rates, and latency."),
174 Command.withHandler(
175 Effect.fn("cli.trace.summary")(function* (flags) {
176 const fs = yield* FileSystem.FileSystem;
177 // T3CODE_TRACE_FILE, else the userdata trace file for --base-dir or
178 // T3CODE_HOME. Implicit dev runs write elsewhere; set T3CODE_TRACE_FILE.
179 const envHome = yield* Config.String("T3CODE_HOME").pipe(Config.option);
180 const baseDir = yield* resolveBaseDir(
181 Option.getOrUndefined(Option.orElse(flags.baseDir, () => envHome)),
182 );
183 const traceFilePath =
184 (yield* traceFileConfig) ??
185 (yield* ServerConfig.deriveServerPaths(baseDir, undefined)).serverTracePath;
186 const sinceMs = Option.isSome(flags.since)
187 ? (yield* Clock.currentTimeMillis) - Duration.toMillis(flags.since.value)
188 : undefined;
189 const summarizer = makeTraceSpanSummary(sinceMs);
190 // Stream each file so only one chunk of text is in memory at a time.
191 yield* Effect.forEach(
192 toRotatedTracePaths(traceFilePath, yield* traceMaxFilesConfig),
193 (path) =>
194 fs.stream(path).pipe(
195 Stream.decodeText,
196 Stream.splitLines,
197 Stream.runForEachArray((lines) => Effect.sync(() => lines.forEach(summarizer.addLine))),
198 Effect.catchTags({
199 PlatformError: (cause) =>
200 cause.reason._tag === "NotFound"
201 ? Effect.void
202 : Effect.fail(
203 new TraceFileReadError({
204 traceFilePath: path,
205 causeTag: cause.reason._tag,
206 cause,
207 }),
208 ),
209 }),
210 ),
211 { discard: true },
212 );
213 const summary = summarizer.finish();
214
215 yield* Console.log(
216 summary.spanCount === 0
217 ? `No spans found in ${traceFilePath} or its rotated files${sinceMs === undefined ? "" : " in that window"}.${summary.skippedLineCount > 0 ? ` Skipped ${summary.skippedLineCount} lines that are not spans.` : ""}`
218 : formatTraceSummary(summary, flags.limit),
219 );
220 }),
221 ),
222);
223
224export const traceCommand = Command.make("trace").pipe(
225 Command.withDescription("Inspect the local server trace file."),
226 Command.withSubcommands([traceSummaryCommand]),
227);
apps/server/src/diagnostics/TraceDiagnostics.ts+6-1
...@@ -81,7 +81,12 @@ interface TraceDiagnosticsErrorSummary {...@@ -81,7 +81,12 @@ interface TraceDiagnosticsErrorSummary {
81const DEFAULT_SLOW_SPAN_THRESHOLD_MS = 1_000;81const DEFAULT_SLOW_SPAN_THRESHOLD_MS = 1_000;
82const TOP_LIMIT = 10;82const TOP_LIMIT = 10;
83const RECENT_LIMIT = 20;83const RECENT_LIMIT = 20;
84function toRotatedTracePaths(traceFilePath: string, maxFiles: number): ReadonlyArray<string> {84
85/** The trace file and its rotated backups, oldest first. */
86export function toRotatedTracePaths(
87 traceFilePath: string,
88 maxFiles: number,
89): ReadonlyArray<string> {
85 const backupCount = Math.max(0, Math.floor(maxFiles));90 const backupCount = Math.max(0, Math.floor(maxFiles));
86 const backups = Array.from(91 const backups = Array.from(
87 { length: backupCount },92 { length: backupCount },
docs/operations/observability.md+15
...@@ -62,6 +62,21 @@ far in the future for the environment server's allowed window. It can point to...@@ -62,6 +62,21 @@ far in the future for the environment server's allowed window. It can point to
62a date or time problem on either device, but it can also result from a delayed62a date or time problem on either device, but it can also result from a delayed
63request.63request.
6464
65#### Summarize the trace file
66
67`t3 trace summary` reads the trace file and its rotated backups directly, so it works while the
68server is stalled or stopped. It prints counts, rates, and latency percentiles per span name. Use
69it to measure background work or to compare two builds.
70
71```bash
72t3 trace summary --since 30m --limit 40
73```
74
75It reads `T3CODE_TRACE_FILE` if set, else `<home>/userdata/logs/server.trace.ndjson` for
76`--base-dir` or `T3CODE_HOME`, plus the `T3CODE_TRACE_MAX_FILES` rotated backups. For a dev run or
77a copied file, set `T3CODE_TRACE_FILE`. `--since 30m` keeps spans that ended in the last 30
78minutes. The rate is per minute between the first and last span end.
79
65### Metrics80### Metrics
6681
67Metrics are not written to a local file.82Metrics are not written to a local file.