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 { Command, Flag } from "effect/cli";
17
18import * as ServerConfig from "../config.ts";
19import { streamTraceFileLines, toRotatedTracePaths } from "../diagnostics/TraceDiagnostics.ts";
20import { resolveBaseDir } from "../os-jank.ts";
21import { baseDirFlag, DurationFromString, traceFileConfig, traceMaxFilesConfig } from "./config.ts";
22
23// Only the fields the summary needs. Other record fields are ignored.
24const decodeTraceSpanLine = Schema.decodeUnknownOption(
25 Schema.fromJsonString(
26 Schema.Struct({
27 name: Schema.String,
28 durationMs: Schema.Finite,
29 endTimeUnixNano: Schema.FiniteFromString,
30 // Server (`effect-span`) records.
31 exit: Schema.optional(Schema.Struct({ _tag: Schema.String })),
32 // Browser (`otlp-span`) records. Effect's OTLP tracer writes code "2" for
33 // errors. It marks interrupts with an `effect.fiber.interrupted`
34 // attribute; clients before Effect 4.0.2 wrote code "1" with message
35 // "Interrupted" instead.
36 status: Schema.optional(
37 Schema.Struct({
38 code: Schema.optional(Schema.String),
39 message: Schema.optional(Schema.String),
40 }),
41 ),
42 attributes: Schema.optional(
43 Schema.Struct({ "effect.fiber.interrupted": Schema.optional(Schema.Unknown) }),
44 ),
45 }),
46 ),
47);
48
49/**
50 * Groups trace NDJSON by span name. Call `addLine` once per line as the files
51 * stream in, then `finish` for the summary. Spans that ended before `sinceMs`
52 * are left out. Rates are per minute between the first and last span end,
53 * since spans are written when they end.
54 */
55export function makeTraceSpanSummary(sinceMs = -Infinity) {
56 // Keep each span's duration (8 bytes, a few MB for the default 110 MB of
57 // rotated traces) for exact percentiles. A bounded sketch would save little
58 // and make p50 and p90 approximate.
59 const byName = new Map<string, { durations: number[]; interrupted: number; failures: number }>();
60 let spanCount = 0;
61 let skippedLineCount = 0;
62 let firstEndMs = Infinity;
63 let lastEndMs = -Infinity;
64
65 const addLine = (line: string) => {
66 if (line.trim().length === 0) return;
67 const span = Option.getOrUndefined(decodeTraceSpanLine(line));
68 if (span === undefined) {
69 skippedLineCount += 1;
70 return;
71 }
72 const endMs = span.endTimeUnixNano / 1_000_000;
73 // The report prints end times as dates, so skip ones outside the Date range.
74 if (Option.isNone(DateTime.make(endMs))) {
75 skippedLineCount += 1;
76 return;
77 }
78 if (endMs < sinceMs) return;
79
80 spanCount += 1;
81 firstEndMs = Math.min(firstEndMs, endMs);
82 lastEndMs = Math.max(lastEndMs, endMs);
83 const stats = byName.get(span.name) ?? { durations: [], interrupted: 0, failures: 0 };
84 stats.durations.push(span.durationMs);
85 if (
86 span.exit?._tag === "Interrupted" ||
87 span.attributes?.["effect.fiber.interrupted"] === true ||
88 span.status?.message === "Interrupted"
89 ) {
90 stats.interrupted += 1;
91 }
92 if (span.exit?._tag === "Failure" || span.status?.code === "2") stats.failures += 1;
93 byName.set(span.name, stats);
94 };
95
96 const finish = () => {
97 const minutes = (lastEndMs - firstEndMs) / 60_000;
98 const spans = [...byName]
99 .map(([name, { durations, interrupted, failures }]) => {
100 const sorted = durations.toSorted((left, right) => left - right);
101 // Nearest-rank percentile.
102 const percentile = (p: number) => sorted[Math.ceil(p * sorted.length) - 1]!;
103 return {
104 name,
105 count: sorted.length,
106 perMinute: minutes > 0 ? sorted.length / minutes : undefined,
107 p50Ms: percentile(0.5),
108 p90Ms: percentile(0.9),
109 maxMs: sorted[sorted.length - 1]!,
110 interrupted,
111 failures,
112 };
113 })
114 .toSorted((left, right) => right.count - left.count || left.name.localeCompare(right.name));
115
116 return { spanCount, skippedLineCount, firstEndMs, lastEndMs, minutes, spans };
117 };
118
119 return { addLine, finish };
120}
121
122const formatMs = (ms: number) =>
123 ms < 1_000 ? `${Math.round(ms)}ms` : `${(ms / 1_000).toFixed(1)}s`;
124
125function formatTraceSummary(
126 summary: ReturnType<ReturnType<typeof makeTraceSpanSummary>["finish"]>,
127 limit: number,
128) {
129 const header = ["span", "count", "/min", "p50", "p90", "max", "interrupted", "failed"];
130 const rows = summary.spans
131 .slice(0, limit)
132 .map((span) => [
133 span.name,
134 String(span.count),
135 span.perMinute === undefined
136 ? "-"
137 : span.perMinute < 0.1
138 ? "<0.1"
139 : span.perMinute.toFixed(1),
140 formatMs(span.p50Ms),
141 formatMs(span.p90Ms),
142 formatMs(span.maxMs),
143 String(span.interrupted),
144 String(span.failures),
145 ]);
146 const table = [header, ...rows];
147 const widths = header.map((_, column) => Math.max(...table.map((row) => row[column]!.length)));
148 const formatIso = (ms: number) => DateTime.formatIso(DateTime.makeUnsafe(ms));
149 return [
150 `${summary.spanCount} spans ended from ${formatIso(summary.firstEndMs)} to ${formatIso(summary.lastEndMs)} (${summary.minutes.toFixed(1)} min).`,
151 ...(summary.skippedLineCount > 0
152 ? [`Skipped ${summary.skippedLineCount} lines that are not spans.`]
153 : []),
154 "",
155 ...table.map((row) =>
156 row
157 .map((cell, column) =>
158 column === 0 ? cell.padEnd(widths[column]!) : cell.padStart(widths[column]!),
159 )
160 .join(" "),
161 ),
162 ...(summary.spans.length > limit
163 ? ["", `${summary.spans.length - limit} more span names. Use --limit to show more.`]
164 : []),
165 ].join("\n");
166}
167
168const traceSummaryCommand = Command.make("summary", {
169 baseDir: baseDirFlag,
170 since: Flag.String("since").pipe(
171 Flag.withSchema(DurationFromString),
172 Flag.withDescription("Only count spans that ended in this window, for example 30m or 2h."),
173 Flag.optional,
174 ),
175 limit: Flag.Int("limit").pipe(
176 Flag.withSchema(PositiveInt),
177 Flag.withDescription("Number of span names to show, busiest first."),
178 Flag.withDefault(25),
179 ),
180}).pipe(
181 Command.withDescription("Summarize the local server trace file: counts, rates, and latency."),
182 Command.withHandler(
183 Effect.fn("cli.trace.summary")(function* (flags) {
184 const fs = yield* FileSystem.FileSystem;
185 // T3CODE_TRACE_FILE, else the userdata trace file for --base-dir or
186 // T3CODE_HOME. Implicit dev runs write elsewhere; set T3CODE_TRACE_FILE.
187 const envHome = yield* Config.String("T3CODE_HOME").pipe(Config.option);
188 const baseDir = yield* resolveBaseDir(
189 Option.getOrUndefined(Option.orElse(flags.baseDir, () => envHome)),
190 );
191 const traceFilePath =
192 (yield* traceFileConfig) ??
193 (yield* ServerConfig.deriveServerPaths(baseDir, undefined)).serverTracePath;
194 const sinceMs = Option.isSome(flags.since)
195 ? (yield* Clock.currentTimeMillis) - Duration.toMillis(flags.since.value)
196 : undefined;
197 const summarizer = makeTraceSpanSummary(sinceMs);
198 yield* Effect.forEach(
199 toRotatedTracePaths(traceFilePath, yield* traceMaxFilesConfig),
200 (path) => streamTraceFileLines(fs, path, summarizer.addLine),
201 { discard: true },
202 );
203 const summary = summarizer.finish();
204
205 yield* Console.log(
206 summary.spanCount === 0
207 ? `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.` : ""}`
208 : formatTraceSummary(summary, flags.limit),
209 );
210 }),
211 ),
212);
213
214export const traceCommand = Command.make("trace").pipe(
215 Command.withDescription("Inspect the local server trace file."),
216 Command.withSubcommands([traceSummaryCommand]),
217);