Skip to content

Commit cbf4215

Browse files
matt-aitkenTrigger.dev RepoOps
authored andcommitted
fix(webapp): stop the OTLP ingest worker pool reaping healthy workers when queued batches time out
## Summary Under a burst of telemetry, the OpenTelemetry ingest worker pool could terminate its own healthy workers and then keep terminating every replacement, leaving a server rejecting every OTLP batch until the process was restarted. Batches that wait too long in the queue are now dropped individually, workers are only terminated when they are genuinely stuck on a single batch, and every worker termination is logged. ## Root cause The pool starts a task's timeout when the batch is enqueued, but the timeout handler treated any dispatched task as evidence of a stuck worker. When queue wait alone exceeded the budget, the first timer to fire belonged to a batch a healthy worker was actively computing, so that worker was terminated. Each replacement worker was handed the oldest queued batch, whose timer was already about to fire, and was terminated moments later. With respawn backoff at its cap the pool sat at zero workers indefinitely, and the termination path logged nothing. ## Fix - Track when a task is dispatched. On timeout the caller is still rejected, but the worker is only reaped once it has spent a full timeout computing that one task; otherwise a compute timer gives it the remaining budget and the worker returns to the idle set when it replies. Deadline arithmetic uses a monotonic clock so a wall-clock step cannot trigger sheds or reaps. - Before dispatch, shed queued tasks whose remaining budget is below a small floor (recorded as `outcome=stale` on `ingest.worker_pool.tasks`) so a free worker starts on a batch it can finish. - Log every reap with reason, task age, time since dispatch, queue depth and alive workers; aggregate shed counts into at most one debug line per second. - Timeout and respawn backoff are constructor options with unchanged defaults so the overload scenario is testable. The new tests reproduce the failure on the previous code (all respawns `reason=timeout`, zero alive workers, throughput frozen) and cover the late-reply and hang-after-queue-wait paths. Mono-RevId: 69295ed642e15b72d3ee8d15c6fe734e6579b94e
1 parent a3f3fc0 commit cbf4215

5 files changed

Lines changed: 525 additions & 22 deletions

File tree

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,6 @@
1+
---
2+
area: webapp
3+
type: fix
4+
---
5+
6+
Fixed a bug where a burst of telemetry could leave OpenTelemetry ingest rejecting every batch for a long time. Batches that wait too long are now dropped individually instead of restarting the processing workers, so ingest recovers as soon as the burst passes.

‎apps/webapp/app/v3/otlpWorkerPool.server.ts‎

Lines changed: 199 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
import { Worker } from "node:worker_threads";
22
import path from "node:path";
3+
import { performance } from "node:perf_hooks";
34
import {
45
getMeter,
56
type Counter,
@@ -31,15 +32,40 @@ type Task = {
3132
// Wall-clock stamp at enqueue; the task-duration histogram measures enqueue -> terminal state
3233
// (queue wait + worker compute), so the gap from the worker-reported compute time is queue wait.
3334
enqueuedAt: number;
35+
/** Monotonic stamps (performance.now) drive every deadline decision so a wall-clock step can't shed or reap. */
36+
enqueuedAtMono: number;
37+
dispatchedAtMono?: number;
3438
};
3539

3640
type ReapReason = "error" | "exit" | "timeout";
3741

42+
export type ReapEvent = {
43+
reason: ReapReason;
44+
taskAgeMs?: number;
45+
sinceDispatchMs?: number;
46+
queueDepth: number;
47+
aliveWorkers: number;
48+
};
49+
50+
export type OtlpWorkerPoolOptions = {
51+
taskTimeoutMs?: number;
52+
respawnBaseMs?: number;
53+
respawnMaxMs?: number;
54+
/**
55+
* Observer for every reap, carrying the same fields as the warn log. It must not affect pool
56+
* liveness: it runs after the worker is terminated and the respawn is scheduled, and any
57+
* exception it throws or promise it rejects is logged and swallowed.
58+
*/
59+
onReap?: (event: ReapEvent) => void | Promise<void>;
60+
};
61+
3862
const TASK_TIMEOUT_MS = 30_000;
3963
const MAX_QUEUE_DEPTH = 2_000;
4064
const RESPAWN_BASE_MS = 500;
4165
const RESPAWN_MAX_MS = 30_000;
4266
const SHUTDOWN_DRAIN_MS = 5_000;
67+
const STALE_FLOOR_MAX_MS = 1_000;
68+
const SHED_LOG_INTERVAL_MS = 1_000;
4369

4470
// Hand-rolled worker_threads pool: one in-flight task per worker so CPU-bound transforms run
4571
// fully in parallel. The main thread stays the only DB reader and broadcasts pricing to workers.
@@ -48,11 +74,21 @@ export class OtlpWorkerPool {
4874
private readonly idle: Worker[] = [];
4975
private readonly queue: number[] = [];
5076
private readonly tasks = new Map<number, Task>();
51-
private readonly busyByWorker = new Map<Worker, number>();
77+
private readonly busyByWorker = new Map<Worker, Task>();
78+
private readonly computeTimers = new Map<Worker, NodeJS.Timeout>();
5279
private nextId = 1;
5380
private consecutiveFailures = 0;
5481
private isShuttingDown = false;
5582
private latestPricingModels: unknown[];
83+
private readonly taskTimeoutMs: number;
84+
private readonly respawnBaseMs: number;
85+
private readonly respawnMaxMs: number;
86+
private readonly staleFloorMs: number;
87+
private readonly onReap?: (event: ReapEvent) => void | Promise<void>;
88+
private shedInWindow = 0;
89+
private shedWindowStartMono = 0;
90+
private lastShedMono = 0;
91+
private shedFlushTimer?: NodeJS.Timeout;
5692

5793
// Pre-allocated per-kind {kind} attribute objects so the per-task record path never allocates.
5894
private readonly _kindAttrs: Record<TransformKind, { kind: TransformKind }> = {
@@ -69,9 +105,15 @@ export class OtlpWorkerPool {
69105
private readonly size: number,
70106
private readonly workerPath: string,
71107
pricingModels: unknown[],
72-
meter?: Meter
108+
meter?: Meter,
109+
options?: OtlpWorkerPoolOptions
73110
) {
74111
this.latestPricingModels = pricingModels;
112+
this.taskTimeoutMs = options?.taskTimeoutMs ?? TASK_TIMEOUT_MS;
113+
this.respawnBaseMs = options?.respawnBaseMs ?? RESPAWN_BASE_MS;
114+
this.respawnMaxMs = options?.respawnMaxMs ?? RESPAWN_MAX_MS;
115+
this.staleFloorMs = Math.min(STALE_FLOOR_MAX_MS, this.taskTimeoutMs / 10);
116+
this.onReap = options?.onReap;
75117
this.#setupOtelMetrics(meter);
76118
for (let i = 0; i < size; i++) this.spawn();
77119
logger.info("OtlpWorkerPool started", { size, workerPath });
@@ -131,6 +173,15 @@ export class OtlpWorkerPool {
131173
}
132174
}
133175

176+
/**
177+
* A task that already timed out for its caller recorded its outcome and duration then; its
178+
* compute time only becomes known when the worker finally replies, and skipping it would drop
179+
* exactly the slow samples from the compute histogram.
180+
*/
181+
#recordLateCompute(task: Task, computeMs: number): void {
182+
this._computeDurationHistogram?.record(computeMs, this._kindAttrs[task.message.kind]);
183+
}
184+
134185
private spawn() {
135186
const worker = new Worker(this.workerPath, {
136187
workerData: { pricingModels: this.latestPricingModels },
@@ -141,7 +192,9 @@ export class OtlpWorkerPool {
141192
(msg: { id: number; ok: boolean; result?: any; error?: string; computeMs?: number }) => {
142193
if (this.workers.indexOf(worker) === -1) return; // late message from an already-reaped worker
143194
this.consecutiveFailures = 0;
195+
const inFlight = this.busyByWorker.get(worker);
144196
this.busyByWorker.delete(worker);
197+
this.#clearComputeTimer(worker);
145198
const task = this.tasks.get(msg.id);
146199
if (task) {
147200
clearTimeout(task.timer);
@@ -153,6 +206,8 @@ export class OtlpWorkerPool {
153206
this.#recordTaskEnd(task, "error", msg.computeMs);
154207
task.reject(new Error(msg.error ?? "otlp worker error"));
155208
}
209+
} else if (inFlight?.message.id === msg.id && msg.computeMs !== undefined) {
210+
this.#recordLateCompute(inFlight, msg.computeMs);
156211
}
157212
this.release(worker);
158213
}
@@ -182,30 +237,92 @@ export class OtlpWorkerPool {
182237

183238
const ii = this.idle.indexOf(worker);
184239
if (ii !== -1) this.idle.splice(ii, 1);
240+
this.#clearComputeTimer(worker);
185241

186-
const inFlightId = this.busyByWorker.get(worker);
242+
const now = performance.now();
243+
const inFlight = this.busyByWorker.get(worker);
187244
this.busyByWorker.delete(worker);
188-
if (inFlightId !== undefined) {
189-
const task = this.tasks.get(inFlightId);
190-
if (task) {
191-
clearTimeout(task.timer);
192-
this.tasks.delete(inFlightId);
193-
// A timed-out task already recorded its own end + was removed from the map, so this only
194-
// fires for a crash that killed a task mid-flight.
195-
this.#recordTaskEnd(task, "crash");
196-
task.reject(error);
197-
}
245+
if (inFlight !== undefined && this.tasks.has(inFlight.message.id)) {
246+
clearTimeout(inFlight.timer);
247+
this.tasks.delete(inFlight.message.id);
248+
this.#recordTaskEnd(inFlight, "crash");
249+
inFlight.reject(error);
198250
}
199251

200252
this._respawnsCounter?.add(1, { reason });
253+
const event: ReapEvent = {
254+
reason,
255+
queueDepth: this.queue.length,
256+
aliveWorkers: this.workers.length,
257+
taskAgeMs: inFlight === undefined ? undefined : Math.round(now - inFlight.enqueuedAtMono),
258+
sinceDispatchMs:
259+
inFlight?.dispatchedAtMono === undefined
260+
? undefined
261+
: Math.round(now - inFlight.dispatchedAtMono),
262+
};
263+
logger.warn("OtlpWorkerPool reaped worker", { ...event, error: error.message });
201264
void worker.terminate().catch(() => {});
202265
this.scheduleRespawn();
266+
this.#notifyReap(event);
267+
}
268+
269+
#notifyReap(event: ReapEvent): void {
270+
if (this.onReap === undefined) return;
271+
try {
272+
const result = this.onReap(event);
273+
if (result !== undefined && typeof result.then === "function") {
274+
result.then(undefined, (thrown) => this.#logObserverError(thrown));
275+
}
276+
} catch (thrown) {
277+
this.#logObserverError(thrown);
278+
}
279+
}
280+
281+
#logObserverError(thrown: unknown): void {
282+
logger.error("OtlpWorkerPool onReap observer threw", {
283+
error: thrown instanceof Error ? thrown.message : String(thrown),
284+
});
285+
}
286+
287+
#clearComputeTimer(worker: Worker) {
288+
const timer = this.computeTimers.get(worker);
289+
if (timer === undefined) return;
290+
clearTimeout(timer);
291+
this.computeTimers.delete(worker);
292+
}
293+
294+
/**
295+
* A dispatched task whose caller deadline passed is not evidence the worker is stuck: it may
296+
* have sat in the queue for most of its budget. Give the worker the rest of a full compute
297+
* budget for it, and only reap if it still hasn't replied by then. The worker's reply (or a
298+
* crash reap) clears this timer.
299+
*/
300+
#armComputeTimer(worker: Worker, task: Task, delayMs: number) {
301+
this.#clearComputeTimer(worker);
302+
const timer = setTimeout(
303+
() => {
304+
this.computeTimers.delete(worker);
305+
if (this.busyByWorker.get(worker) !== task) return;
306+
const remainingMs = this.taskTimeoutMs - (performance.now() - task.dispatchedAtMono!);
307+
if (remainingMs > 0) {
308+
this.#armComputeTimer(worker, task, remainingMs);
309+
return;
310+
}
311+
this.reap(
312+
worker,
313+
new Error(`otlp worker stuck for ${this.taskTimeoutMs}ms on a single task`),
314+
"timeout"
315+
);
316+
},
317+
Math.max(1, Math.ceil(delayMs))
318+
);
319+
this.computeTimers.set(worker, timer);
203320
}
204321

205322
private scheduleRespawn() {
206323
if (this.isShuttingDown) return;
207324
if (this.workers.length >= this.size) return;
208-
const delay = Math.min(RESPAWN_BASE_MS * 2 ** this.consecutiveFailures, RESPAWN_MAX_MS);
325+
const delay = Math.min(this.respawnBaseMs * 2 ** this.consecutiveFailures, this.respawnMaxMs);
209326
this.consecutiveFailures++;
210327
setTimeout(() => {
211328
if (this.isShuttingDown) return;
@@ -219,28 +336,83 @@ export class OtlpWorkerPool {
219336
this.drain();
220337
}
221338

339+
/**
340+
* Hand queued tasks to idle workers in FIFO order, shedding any task whose remaining budget is
341+
* below the stale floor so a free worker starts on something it can still finish. The floor is
342+
* a small fraction of the timeout, so only tasks whose deadline is effectively already here are
343+
* dropped; everything else keeps its FIFO turn.
344+
*/
222345
private drain() {
346+
const now = performance.now();
223347
while (this.queue.length > 0 && this.idle.length > 0) {
224-
const worker = this.idle.pop()!;
225348
const id = this.queue.shift()!;
226349
const task = this.tasks.get(id);
227350
if (!task) continue;
351+
const remainingMs = task.enqueuedAtMono + this.taskTimeoutMs - now;
352+
if (remainingMs < this.staleFloorMs) {
353+
this.#shed(task, remainingMs, now);
354+
continue;
355+
}
356+
const worker = this.idle.pop()!;
228357
task.worker = worker;
229-
this.busyByWorker.set(worker, id);
358+
task.dispatchedAtMono = now;
359+
this.busyByWorker.set(worker, task);
230360
worker.postMessage(task.message, task.transfer);
231361
}
232362
}
233363

364+
/**
365+
* Sheds are aggregated into at most one debug line per second; each line carries the count and
366+
* the span between the first and last shed it covers.
367+
*/
368+
#shed(task: Task, remainingMs: number, now: number) {
369+
clearTimeout(task.timer);
370+
this.tasks.delete(task.message.id);
371+
this.#recordTaskEnd(task, "stale");
372+
task.reject(
373+
new Error(
374+
`otlp worker task shed after ${Math.round(now - task.enqueuedAtMono)}ms in queue with ${Math.max(
375+
0,
376+
Math.round(remainingMs)
377+
)}ms of ${this.taskTimeoutMs}ms budget left`
378+
)
379+
);
380+
if (this.shedInWindow === 0) this.shedWindowStartMono = now;
381+
this.lastShedMono = now;
382+
this.shedInWindow++;
383+
if (this.shedFlushTimer !== undefined) return;
384+
this.shedFlushTimer = setTimeout(() => {
385+
this.shedFlushTimer = undefined;
386+
logger.debug("OtlpWorkerPool shed stale tasks", {
387+
shed: this.shedInWindow,
388+
windowMs: Math.round(this.lastShedMono - this.shedWindowStartMono),
389+
queueDepth: this.queue.length,
390+
aliveWorkers: this.workers.length,
391+
});
392+
this.shedInWindow = 0;
393+
}, SHED_LOG_INTERVAL_MS);
394+
this.shedFlushTimer.unref();
395+
}
396+
397+
/**
398+
* The caller's budget (queue wait + compute) is spent, so reject it now. Whether the worker is
399+
* at fault depends on how long it has held the task: reap only once it has had a full timeout
400+
* of compute time on this one task, otherwise let it finish via the compute timer and return to
401+
* the idle set on reply. The task is removed here, so neither path can double-reject.
402+
*/
234403
private onTimeout(id: number) {
235404
const task = this.tasks.get(id);
236405
if (!task) return;
237406
this.tasks.delete(id);
238407
this.#recordTaskEnd(task, "timeout");
239-
const err = new Error(`otlp worker task timed out after ${TASK_TIMEOUT_MS}ms`);
240-
if (task.worker) {
241-
// Dispatched to a stuck worker: reap it. The task is already removed, so reap won't
242-
// double-reject.
243-
this.reap(task.worker, err, "timeout");
408+
const err = new Error(`otlp worker task timed out after ${this.taskTimeoutMs}ms`);
409+
if (task.worker !== undefined && task.dispatchedAtMono !== undefined) {
410+
const remainingComputeMs = this.taskTimeoutMs - (performance.now() - task.dispatchedAtMono);
411+
if (remainingComputeMs <= 0) {
412+
this.reap(task.worker, err, "timeout");
413+
} else {
414+
this.#armComputeTimer(task.worker, task, remainingComputeMs);
415+
}
244416
} else {
245417
const qi = this.queue.indexOf(id);
246418
if (qi !== -1) this.queue.splice(qi, 1);
@@ -262,7 +434,7 @@ export class OtlpWorkerPool {
262434
}
263435
const id = this.nextId++;
264436
return new Promise((resolve, reject) => {
265-
const timer = setTimeout(() => this.onTimeout(id), TASK_TIMEOUT_MS);
437+
const timer = setTimeout(() => this.onTimeout(id), this.taskTimeoutMs);
266438
this.tasks.set(id, {
267439
message: {
268440
id,
@@ -277,6 +449,7 @@ export class OtlpWorkerPool {
277449
reject,
278450
timer,
279451
enqueuedAt: Date.now(),
452+
enqueuedAtMono: performance.now(),
280453
});
281454
this.queue.push(id);
282455
this.drain();
@@ -319,6 +492,10 @@ export class OtlpWorkerPool {
319492
this.idle.length = 0;
320493
this.queue.length = 0;
321494
this.busyByWorker.clear();
495+
for (const timer of this.computeTimers.values()) clearTimeout(timer);
496+
this.computeTimers.clear();
497+
clearTimeout(this.shedFlushTimer);
498+
this.shedFlushTimer = undefined;
322499
// Reject anything that didn't drain within the deadline.
323500
for (const [, task] of this.tasks) {
324501
clearTimeout(task.timer);
Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,6 @@
1+
/**
2+
* Real worker that never replies, to exercise the pool's stuck-worker reap path.
3+
*/
4+
const { parentPort } = require("node:worker_threads");
5+
6+
parentPort.on("message", () => {});
Lines changed: 22 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,22 @@
1+
/**
2+
* Real worker that takes a fixed wall-clock time per task, so pool tests can drive queue wait past
3+
* the task deadline while the worker itself stays healthy. Delay comes from
4+
* OTLP_SLOW_WORKER_DELAY_MS (default 100). When OTLP_SLOW_WORKER_HANG_AFTER is set the worker
5+
* answers that many tasks and then never replies again, to model a worker that wedges mid-run.
6+
*/
7+
const { parentPort } = require("node:worker_threads");
8+
9+
const delayMs = Number(process.env.OTLP_SLOW_WORKER_DELAY_MS ?? 100);
10+
const hangAfter = process.env.OTLP_SLOW_WORKER_HANG_AFTER
11+
? Number(process.env.OTLP_SLOW_WORKER_HANG_AFTER)
12+
: Infinity;
13+
let answered = 0;
14+
15+
parentPort.on("message", (message) => {
16+
if (message && message.type === "pricing") return;
17+
if (answered >= hangAfter) return;
18+
answered++;
19+
setTimeout(() => {
20+
parentPort.postMessage({ id: message.id, ok: true, result: { rows: [] }, computeMs: delayMs });
21+
}, delayMs);
22+
});

0 commit comments

Comments
 (0)