Skip to content

Commit e5d427c

Browse files
authored
feat(telemetry): halve JSONL storage, cap SSH sample rate, restructure OTLP export (#1003)
Cuts local telemetry disk usage roughly in half, caps the noisiest emitter, and aligns the OTLP export with OTLP standards. - JSONL files open with a once-per-file header carrying the 8 session-constant context fields; rows keep only per-event fields plus `deployment_url`. Headers are rewritten on rotation so every rolling file stays independently readable. Saves ~45% of file bytes. - `http.requests` emits `count.*` keys only when nonzero (~8% of bytes). - `ssh.network.sampled` changes are gated behind a 15s cooldown. - OTLP output is restructured into per-session resource blocks: session context becomes the OTel resource, data points group under one metric per (name, unit), and cumulative counters reset per block so a new session does not inherit prior totals. - A telemetry file that cannot be read or parsed no longer aborts the export: the stream skips it from its first bad line (keeping events already parsed), each skip is logged with file:line detail, the completion notification names the skip count, and the diagnostic span gains a `file.skipped_count` measurement.
1 parent 773c56e commit e5d427c

35 files changed

Lines changed: 1530 additions & 809 deletions

src/core/container.ts

Lines changed: 5 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -53,18 +53,17 @@ export class ServiceContainer implements vscode.Disposable {
5353
this.logger,
5454
);
5555

56-
const sessionId = newSessionId();
56+
const session = buildSession(
57+
extractExtensionVersion(context.extension.packageJSON),
58+
newSessionId(),
59+
);
5760
const localJsonlSink = LocalJsonlSink.start(
5861
{
5962
baseDir: this.pathResolver.getTelemetryPath(),
60-
sessionId,
63+
session,
6164
},
6265
this.logger,
6366
);
64-
const session = buildSession(
65-
extractExtensionVersion(context.extension.packageJSON),
66-
sessionId,
67-
);
6867
this.telemetryService = new TelemetryService(
6968
session,
7069
[localJsonlSink],

src/instrumentation/CONVENTIONS.md

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -115,6 +115,8 @@ Coder's own pipeline, so a bare `cache_source` can't collide with a future OTel
115115
- **Measurements** are raw numbers. Don't pre-bucket into string labels: both
116116
export as record attributes, and a query can bucket the raw number at read
117117
time. `result` and `durationMs` are framework-managed and cannot be set.
118+
`durationMs` never reaches OTLP; the export derives span start/end times
119+
from it.
118120
- **Units.** There is no unit field at emit time, so put the unit in the
119121
measurement key as a `_ms` / `_seconds` / `_mbits` suffix, the same way for
120122
every event.

src/instrumentation/EVENTS.md

Lines changed: 66 additions & 37 deletions
Original file line numberDiff line numberDiff line change
@@ -34,46 +34,73 @@ Signal kinds, which each category groups its events by:
3434

3535
Framework-managed envelope fields (wire keys, JSONL):
3636

37-
| Field | Meaning |
38-
| ----------------- | ------------------------------------------------------------------------------------------- |
39-
| `event_id` | Unique per event (OTel span id, 16 hex) |
40-
| `event_name` | The event names below |
41-
| `timestamp` | ISO 8601 emission time |
42-
| `event_sequence` | Monotonic per-session counter |
43-
| `schema_version` | Integer, currently `1`; bumped only on breaking wire changes, additive fields never bump it |
44-
| `trace_id` | Spans and their child events only (OTel trace id, 32 hex) |
45-
| `parent_event_id` | Phases and span logs only; the parent span's `event_id` |
46-
| `error` | `{ message, type?, code? }`, only when an error was captured |
47-
48-
Session context, stamped on every event under `context`:
49-
50-
| Field | Source |
51-
| -------------------------------------- | ------------------------------------------------------------------------- |
52-
| `extension_version` | package.json version |
53-
| `machine_id` | `vscode.env.machineId` |
54-
| `session_id` | Generated per session |
55-
| `os_type` / `os_version` / `host_arch` | `process.platform` (windows normalized) / `os.release()` / `process.arch` |
56-
| `platform_name` / `platform_version` | `vscode.env.appName` / `vscode.version` |
57-
| `deployment_url` | Set once known via `setDeploymentUrl` |
37+
| Field | Meaning |
38+
| ----------------- | ---------------------------------------------------------------------- |
39+
| `event_id` | Unique per event (OTel span id, 16 hex) |
40+
| `event_name` | The event names below |
41+
| `timestamp` | ISO 8601 emission time |
42+
| `event_sequence` | Monotonic per-session counter |
43+
| `deployment_url` | Deployment active at emit time; empty until set via `setDeploymentUrl` |
44+
| `trace_id` | Spans and their child events only (OTel trace id, 32 hex) |
45+
| `parent_event_id` | Phases and span logs only; the parent span's `event_id` |
46+
| `error` | `{ message, type?, code? }`, only when an error was captured |
47+
48+
Session-constant context is written once per file instead of on every row:
49+
the first line of every telemetry file (including rotated `.N` segments) is
50+
a header carrying the wire schema version, the sink start time, and the
51+
session context; each row below it implicitly inherits the version and
52+
context.
53+
54+
```json
55+
{
56+
"kind": "header",
57+
"schema_version": 1,
58+
"timestamp": "...",
59+
"context": {
60+
"extension_version": "...",
61+
"machine_id": "...",
62+
"session_id": "...",
63+
"os_type": "...",
64+
"os_version": "...",
65+
"host_arch": "...",
66+
"platform_name": "...",
67+
"platform_version": "..."
68+
}
69+
}
70+
```
71+
72+
| Field | Source |
73+
| -------------------------------------- | ------------------------------------------------------------------------------------------- |
74+
| `schema_version` | Integer, currently `1`; bumped only on breaking wire changes, additive fields never bump it |
75+
| `timestamp` | ISO 8601 sink start time; at or before every row's timestamp |
76+
| `extension_version` | package.json version |
77+
| `machine_id` | `vscode.env.machineId` |
78+
| `session_id` | Generated per session |
79+
| `os_type` / `os_version` / `host_arch` | `process.platform` (windows normalized) / `os.release()` / `process.arch` |
80+
| `platform_name` / `platform_version` | `vscode.env.appName` / `vscode.version` |
5881

5982
On OTLP export the context becomes resource attributes (`service.name:
6083
coder-vscode-extension`, `service.version`, `service.instance.id`, `host.id`,
6184
`host.arch`, `os.type`, `os.version`, `vscode.platform.name`,
62-
`vscode.platform.version`, `coder.deployment.url`) plus per-record provenance
63-
(`coder.event.extension_version`, `coder.event.session_id`,
64-
`coder.event.deployment_url`).
85+
`vscode.platform.version`, `coder.deployment.url`) on the resource block
86+
holding the producing session's records.
6587

6688
## Consuming exports
6789

6890
Events buffer on disk as JSONL; nothing leaves the machine on its own. The
6991
**Coder: Export Telemetry** command flushes the buffer and writes a chosen
7092
date range in one of two formats:
7193

72-
- **JSON**: one file holding an array of the wire-format rows described
73-
above, for direct inspection or ad-hoc processing.
94+
- **JSON**: one file holding an array of self-contained events, each
95+
carrying its full context and schema version, for direct inspection or
96+
ad-hoc processing.
7497
- **OTLP**: a zip of standard OTLP/JSON envelopes (spans in `traces.json`,
7598
logs in `logs.json`, metric events as data points in `metrics.json`) plus
76-
a `manifest.json` describing the export. Feed these to any OTel-compatible
99+
a `manifest.json` describing the export. Each envelope holds one resource
100+
block per producing session and UTC date, carrying that session's context
101+
as resource attributes; within a block, metric data points are grouped
102+
under one `metrics[]` entry per metric name and unit, and cumulative
103+
counters restart at the block boundary. Feed these to any OTel-compatible
77104
tool that ingests OTLP/JSON, such as an OpenTelemetry Collector pipeline or
78105
your observability backend's import tooling.
79106

@@ -271,6 +298,7 @@ Emitted by `DiagnosticTelemetry` around each diagnostic command.
271298
| `interval.count` (measurement) | speed test only |
272299
| `throughput_mbits` (measurement) | speed test only |
273300
| `event.count` (measurement) | telemetry export only |
301+
| `file.skipped_count` (measurement) | telemetry export only; unreadable files skipped, omitted at zero |
274302

275303
## Deployment
276304

@@ -358,9 +386,10 @@ Emitted by `SshTelemetry`.
358386

359387
#### `ssh.network.sampled`
360388

361-
Tunnel network sample. Emitted on a p2p flip, a preferred-DERP change, a
362-
meaningful latency change (at least 25 ms or 20 %), or a roughly 60 s
363-
heartbeat.
389+
Tunnel network sample. Emitted on a roughly 60 s heartbeat, or on a p2p
390+
flip, a preferred-DERP change, or a meaningful latency change (at least
391+
25 ms and at least 20 %). Change-triggered emissions are limited to one per
392+
15 s; a change that persists past that cooldown is emitted when it expires.
364393

365394
| Attribute | Values |
366395
| ------------------------------ | ------------------------------------------------------------------ |
@@ -380,13 +409,13 @@ Emitted by `HttpRequestsTelemetry`, which lives with the HTTP logging in
380409
`src/logging`. A per-minute rollup of REST traffic, one event per method and
381410
route bucket.
382411

383-
| Attribute | Values |
384-
| ---------------------------------------------------------------------- | ------------------------------------------------------------------- |
385-
| `method` | HTTP method |
386-
| `route` | normalized route (ids replaced by placeholders) |
387-
| `window_seconds` (measurement) | actual window length |
388-
| `count.1xx` through `count.5xx`, `count.network_error` (measurements) | export as cumulative counters with unit `{request}` |
389-
| `duration.p50_ms`, `duration.p95_ms`, `duration.p99_ms` (measurements) | export as gauges (`http.requests.duration.p50` etc.) with unit `ms` |
412+
| Attribute | Values |
413+
| ---------------------------------------------------------------------- | -------------------------------------------------------------------------------------------------------------------- |
414+
| `method` | HTTP method |
415+
| `route` | normalized route (ids replaced by placeholders) |
416+
| `window_seconds` (measurement) | actual window length |
417+
| `count.1xx` through `count.5xx`, `count.network_error` (measurements) | omitted when 0; export as cumulative counters with unit `{request}` |
418+
| `duration.p50_ms`, `duration.p95_ms`, `duration.p99_ms` (measurements) | omitted when no request carried timing metadata; export as gauges (`http.requests.duration.p50` etc.) with unit `ms` |
390419

391420
## WebSocket connections
392421

src/instrumentation/diagnostics.ts

Lines changed: 7 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@ import { recordAborted, recordError } from "./outcomes";
22

33
import type { SpeedtestResult } from "@repo/shared";
44

5+
import type { ExportResult } from "../telemetry/export/pipeline";
56
import type { ExportFormat } from "../telemetry/export/writers/types";
67
import type { TelemetryReporter } from "../telemetry/reporter";
78
import type { Span } from "../telemetry/span";
@@ -29,7 +30,7 @@ export interface DiagnosticTrace {
2930
error(category?: DiagnosticErrorCategory): void;
3031
setRequestedDuration(seconds: number): void;
3132
succeedSpeedtest(result: SpeedtestResult): void;
32-
succeedExport(format: ExportFormat, eventCount: number): void;
33+
succeedExport(format: ExportFormat, result: ExportResult): void;
3334
}
3435

3536
/** Emits `command.diagnostic.completed` around each diagnostic command. */
@@ -71,8 +72,11 @@ class SpanDiagnosticTrace implements DiagnosticTrace {
7172
);
7273
}
7374

74-
public succeedExport(format: ExportFormat, eventCount: number): void {
75+
public succeedExport(format: ExportFormat, result: ExportResult): void {
7576
this.span.setProperty("format", format);
76-
this.span.setMeasurement("event.count", eventCount);
77+
this.span.setMeasurement("event.count", result.eventCount);
78+
if (result.skippedFileCount > 0) {
79+
this.span.setMeasurement("file.skipped_count", result.skippedFileCount);
80+
}
7781
}
7882
}

src/instrumentation/ssh.ts

Lines changed: 12 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@ import type { NetworkInfo } from "../remote/sshProcess";
22
import type { TelemetryReporter } from "../telemetry/reporter";
33

44
const NETWORK_SAMPLE_INTERVAL_MS = 60_000;
5+
const NETWORK_CHANGE_COOLDOWN_MS = 15_000;
56
const NETWORK_LATENCY_CHANGE_RATIO = 0.2;
67
const NETWORK_LATENCY_MIN_ABSOLUTE_CHANGE_MS = 25;
78

@@ -141,15 +142,22 @@ export class SshTelemetry {
141142
}
142143
}
143144

144-
/** Emit on p2p flip, DERP change, large latency swing, or heartbeat interval. */
145+
/** Emit on the heartbeat interval, or on a p2p flip, DERP change, or large
146+
* latency swing once the change cooldown has elapsed. Suppression leaves the
147+
* last emitted sample in place, so a change that persists through the
148+
* cooldown is emitted when it expires rather than lost. */
145149
function shouldEmitSample(
146150
previous: NetworkSample,
147151
current: NetworkInfo,
148152
now: number,
149153
): boolean {
150-
if (now - previous.emittedAtMs >= NETWORK_SAMPLE_INTERVAL_MS) {
154+
const sinceLastEmit = now - previous.emittedAtMs;
155+
if (sinceLastEmit >= NETWORK_SAMPLE_INTERVAL_MS) {
151156
return true;
152157
}
158+
if (sinceLastEmit < NETWORK_CHANGE_COOLDOWN_MS) {
159+
return false;
160+
}
153161
if (current.p2p !== previous.p2p) {
154162
return true;
155163
}
@@ -167,8 +175,9 @@ function hasMeaningfulLatencyChange(
167175
return current !== 0;
168176
}
169177
const absoluteChange = Math.abs(current - previous);
178+
// The absolute floor mutes fast-link jitter; the ratio mutes slow-link noise.
170179
return (
171-
absoluteChange >= NETWORK_LATENCY_MIN_ABSOLUTE_CHANGE_MS ||
180+
absoluteChange >= NETWORK_LATENCY_MIN_ABSOLUTE_CHANGE_MS &&
172181
absoluteChange / Math.abs(previous) >= NETWORK_LATENCY_CHANGE_RATIO
173182
);
174183
}

src/logging/httpRequestsTelemetry.ts

Lines changed: 26 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -142,23 +142,31 @@ export class HttpRequestsTelemetry implements Disposable {
142142
);
143143
for (const [method, byRoute] of this.#buckets) {
144144
for (const [route, bucket] of byRoute) {
145-
const sortedDurations = bucket.durationsMs.toSorted((a, b) => a - b);
146-
this.#telemetry.log(
147-
EVENT_NAME,
148-
{ method, route },
149-
{
150-
window_seconds: elapsedSeconds,
151-
"count.1xx": bucket.count1xx,
152-
"count.2xx": bucket.count2xx,
153-
"count.3xx": bucket.count3xx,
154-
"count.4xx": bucket.count4xx,
155-
"count.5xx": bucket.count5xx,
156-
"count.network_error": bucket.countNetworkError,
157-
"duration.p50_ms": percentile(sortedDurations, 0.5),
158-
"duration.p95_ms": percentile(sortedDurations, 0.95),
159-
"duration.p99_ms": percentile(sortedDurations, 0.99),
160-
},
161-
);
145+
const counts: Record<string, number> = {
146+
"count.1xx": bucket.count1xx,
147+
"count.2xx": bucket.count2xx,
148+
"count.3xx": bucket.count3xx,
149+
"count.4xx": bucket.count4xx,
150+
"count.5xx": bucket.count5xx,
151+
"count.network_error": bucket.countNetworkError,
152+
};
153+
const measurements: Record<string, number> = {
154+
window_seconds: elapsedSeconds,
155+
};
156+
// Zero counters are omitted; absence reads as "none in this window".
157+
for (const [key, count] of Object.entries(counts)) {
158+
if (count > 0) {
159+
measurements[key] = count;
160+
}
161+
}
162+
// Percentiles are omitted when no request carried timing metadata.
163+
if (bucket.durationsMs.length > 0) {
164+
const sorted = bucket.durationsMs.toSorted((a, b) => a - b);
165+
measurements["duration.p50_ms"] = percentile(sorted, 0.5);
166+
measurements["duration.p95_ms"] = percentile(sorted, 0.95);
167+
measurements["duration.p99_ms"] = percentile(sorted, 0.99);
168+
}
169+
this.#telemetry.log(EVENT_NAME, { method, route }, measurements);
162170
}
163171
}
164172
this.#buckets.clear();
@@ -189,6 +197,7 @@ function elapsedMs(
189197
}
190198

191199
function percentile(sortedValues: readonly number[], p: number): number {
200+
// Indexing an empty array would return undefined as a number.
192201
if (sortedValues.length === 0) {
193202
return 0;
194203
}

0 commit comments

Comments
 (0)