Skip to content

Commit 67b203d

Browse files
1stvampTrigger.dev RepoOps
authored andcommitted
feat(webapp,clickhouse): measure the task events a failed flush loses
Adds two metrics to the task event flush path, and fixes one that could not be trusted. `ingest.flush.items_lost` counts the items in a batch abandoned after its retries are exhausted, so a flush failure is measurable in items rather than only in batches. Batch counts understate the loss whenever batch sizes differ between producers: a producer with large batches can account for almost all the lost items while contributing a fraction of the failed batches. `ingest.flush.oldest_pending_age` reports the age of the oldest item not yet stored, counting a batch waiting in the queue, one waiting on a concurrency slot, and one being retried, so a flush that has stalled shows up as a rising age rather than as silence. It reads 0 when nothing is pending. Both instruments are per-process and carry only a `scheduler` attribute, so aggregate them with `max` rather than `sum`. `totalQueuedItems` was decremented only when a flush succeeded, so a batch abandoned after its retries left the queue-depth gauge permanently inflated and a leak read as a backlog. The depth is now released on the abandoned path too, with a regression test. On the ClickHouse client, a failed insert now increments `clickhouse.query.errors` with the operation name and the ClickHouse error type. None of the insert paths recorded to that counter before, so it only ever saw reads and an insert failure registered nothing at all. `InsertError` also carries `clickhouseErrorType`, as `QueryError` already did, so a caller can tell a schema mismatch from a transient fault without parsing the message. Mono-RevId: 706c9716b58c1c3016054c837d7744f4de9b9390
1 parent f999516 commit 67b203d

5 files changed

Lines changed: 335 additions & 9 deletions

File tree

apps/webapp/app/v3/dynamicFlushScheduler.server.ts

Lines changed: 67 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,13 @@ export type DynamicFlushSchedulerConfig<T> = {
2626

2727
export class DynamicFlushScheduler<T> {
2828
private batchQueue: T[][];
29+
// First-item time per queued batch, pushed and shifted in lockstep with batchQueue. A
30+
// dequeued batch hands its time to inFlightSince, because the limiter can hold it and a
31+
// retry can hold it longer, and it is unflushed for all of that.
32+
private batchQueuedAt: number[];
33+
private readonly inFlightSince = new Map<number, number>();
34+
private inFlightSeq = 0;
35+
private currentBatchStartedAt: number | undefined;
2936
private currentBatch: T[];
3037
private readonly BATCH_SIZE: number;
3138
private readonly FLUSH_INTERVAL: number;
@@ -69,13 +76,15 @@ export class DynamicFlushScheduler<T> {
6976
private _flushDurationHistogram?: Histogram;
7077
private _batchSizeHistogram?: Histogram;
7178
private _droppedEventsCounter?: Counter;
79+
private _itemsLostCounter?: Counter;
7280

7381
constructor(config: DynamicFlushSchedulerConfig<T>) {
7482
const schedulerName = config.name ?? "unknown";
7583
this._metricAttrs = { scheduler: schedulerName };
7684
this._batchOkAttrs = { scheduler: schedulerName, outcome: "ok" };
7785
this._batchFailedAttrs = { scheduler: schedulerName, outcome: "failed" };
7886
this.batchQueue = [];
87+
this.batchQueuedAt = [];
7988
this.currentBatch = [];
8089
this.BATCH_SIZE = config.batchSize;
8190
this.currentBatchSize = config.batchSize;
@@ -126,6 +135,10 @@ export class DynamicFlushScheduler<T> {
126135
description: "Events dropped by load shedding before they reached the sink",
127136
unit: "events",
128137
});
138+
this._itemsLostCounter = meter.createCounter("ingest.flush.items_lost", {
139+
description: "Items in batches abandoned after retries were exhausted, so never stored",
140+
unit: "items",
141+
});
129142

130143
// Pull-based gauges: read at export time only, so they add zero hot-path cost.
131144
const queueDepthGauge = meter.createObservableGauge("ingest.flush.queue_depth", {
@@ -139,17 +152,40 @@ export class DynamicFlushScheduler<T> {
139152
const loadSheddingGauge = meter.createObservableGauge("ingest.flush.load_shedding", {
140153
description: "1 while actively shedding load, otherwise 0",
141154
});
155+
const oldestPendingAgeGauge = meter.createObservableGauge("ingest.flush.oldest_pending_age", {
156+
description: "Age of the oldest item not yet stored, or 0 when nothing is pending",
157+
unit: "ms",
158+
});
142159

143160
meter.addBatchObservableCallback(
144161
(result) => {
145162
result.observe(queueDepthGauge, this.totalQueuedItems, this._metricAttrs);
146163
result.observe(concurrencyGauge, this.limiter.concurrency, this._metricAttrs);
147164
result.observe(loadSheddingGauge, this.isLoadShedding ? 1 : 0, this._metricAttrs);
165+
result.observe(oldestPendingAgeGauge, this.#oldestPendingAgeMs(), this._metricAttrs);
148166
},
149-
[queueDepthGauge, concurrencyGauge, loadSheddingGauge]
167+
[queueDepthGauge, concurrencyGauge, loadSheddingGauge, oldestPendingAgeGauge]
150168
);
151169
}
152170

171+
// The oldest of everything unflushed: a queued batch, one in flight, or the one still
172+
// accumulating. Queued is checked first because it is FIFO, but a batch in flight is
173+
// usually the older, so both are compared rather than preferred.
174+
#oldestPendingAgeMs(): number {
175+
let oldest: number | undefined = this.batchQueuedAt[0];
176+
177+
for (const since of this.inFlightSince.values()) {
178+
if (oldest === undefined || since < oldest) {
179+
oldest = since;
180+
}
181+
}
182+
183+
oldest ??= this.currentBatchStartedAt;
184+
185+
// Clamped because Date.now() can step backwards.
186+
return oldest === undefined ? 0 : Math.max(0, Date.now() - oldest);
187+
}
188+
153189
addToBatch(items: T[]): void {
154190
let itemsToAdd = items;
155191

@@ -190,6 +226,10 @@ export class DynamicFlushScheduler<T> {
190226
});
191227
}
192228

229+
if (this.currentBatch.length === 0 && itemsToAdd.length > 0) {
230+
this.currentBatchStartedAt = Date.now();
231+
}
232+
193233
this.currentBatch.push(...itemsToAdd);
194234
this.totalQueuedItems += itemsToAdd.length;
195235

@@ -206,7 +246,9 @@ export class DynamicFlushScheduler<T> {
206246
if (this.currentBatch.length === 0) return;
207247

208248
this.batchQueue.push(this.currentBatch);
249+
this.batchQueuedAt.push(this.currentBatchStartedAt ?? Date.now());
209250
this.currentBatch = [];
251+
this.currentBatchStartedAt = undefined;
210252
this.flushBatches();
211253
this.resetFlushTimer();
212254
}
@@ -250,23 +292,36 @@ export class DynamicFlushScheduler<T> {
250292
}
251293

252294
private async flushBatches(): Promise<void> {
253-
const batchesToFlush: T[][] = [];
295+
const batchesToFlush: { batch: T[]; token: number }[] = [];
254296

255297
// Dequeue all available batches up to current concurrency limit
256298
while (this.batchQueue.length > 0 && batchesToFlush.length < this.limiter.concurrency) {
257299
const batch = this.batchQueue.shift();
300+
const queuedAt = this.batchQueuedAt.shift();
258301
if (batch) {
259-
batchesToFlush.push(batch);
302+
// Registered here rather than inside the limiter callback, which does not run until a
303+
// slot frees: the wait for that slot is part of what the age has to cover.
304+
const token = ++this.inFlightSeq;
305+
this.inFlightSince.set(token, queuedAt ?? Date.now());
306+
batchesToFlush.push({ batch, token });
260307
}
261308
}
262309

263310
if (batchesToFlush.length === 0) return;
264311

265312
// Schedule all batches for concurrent processing
266-
const flushPromises = batchesToFlush.map((batch) =>
313+
const flushPromises = batchesToFlush.map(({ batch, token }) =>
267314
this.limiter(async () => {
268315
const itemCount = batch.length;
269316

317+
// Released once per batch, by whichever of the two outcomes gets there.
318+
let depthReleased = false;
319+
const releaseDepth = () => {
320+
if (depthReleased) return;
321+
depthReleased = true;
322+
this.totalQueuedItems -= itemCount;
323+
};
324+
270325
// eslint-disable-next-line no-this-alias
271326
const self = this;
272327

@@ -276,7 +331,7 @@ export class DynamicFlushScheduler<T> {
276331
await self.callback(flushId, batchToFlush);
277332

278333
const duration = Date.now() - startTime;
279-
self.totalQueuedItems -= itemCount;
334+
releaseDepth();
280335
self.consecutiveFlushFailures = 0;
281336
self.lastFlushTime = Date.now();
282337
self.metrics.flushedBatches++;
@@ -323,11 +378,18 @@ export class DynamicFlushScheduler<T> {
323378

324379
const [flushError] = await tryCatch(tryFlush(nanoid(), batch));
325380

381+
this.inFlightSince.delete(token);
382+
326383
if (flushError) {
327384
this.logger.error("Error flushing batch", {
328385
error: flushError,
386+
itemCount,
329387
});
330388
this._batchesCounter?.add(1, this._batchFailedAttrs);
389+
this._itemsLostCounter?.add(itemCount, this._metricAttrs);
390+
// Only the success path released the depth, which left an abandoned batch inflating
391+
// the gauge forever, where it read as backlog rather than as loss.
392+
releaseDepth();
331393
}
332394
})
333395
);

0 commit comments

Comments
 (0)