Operations case study

Debugging a queue backlog before it becomes an incident.

The failure mode is a growing backlog, not an outage. This case reconstructs the debugging path with an executable model: which signals fired, in what order, and what correlation pointed at where the time went.

Open source repository AWS serverless skill area

Problem: Slow-burn queue backlog
Signals: Depth, age, latency, error rate
Approach: Seeded simulation
Scope: Local model, no live deploy
Validation: 19 tests + type check

Source files Show files in the companion repository

Signal names src/signals.ts Metric, log event, and span names used across the model.
Threshold evaluator src/thresholds.ts Age and depth warning and breach events emitted from current metrics.
Correlation builder src/correlation.ts Gathers events and spans for one correlation ID and sums queue, worker, and downstream time.
Runbook assembler src/runbook.ts Turns breach events and peak metrics into a formatted runbook.
Simulation model src/model.ts Seeded queue, worker pool, downstream latency, retries, DLQ, metrics, events, and spans.
Scenario runner src/run-scenario.ts Runs the breach scenario and prints the per-tick timeline plus a correlated trace.

~5 min read · 1 backlog breach scenario · TypeScript · seeded simulation · Source repository

Problem
Constraints
Architecture
Signals and tests
Scenario
Implementation
Tradeoffs

01 — Problem

The failure mode is a growing backlog, not a hard outage.

Accepted work stalls silently. By the time users notice, the queue has been growing for minutes. The debugging question is where time is going: into the queue, into the worker, or into the downstream call.

Queue depth rises when intake outpaces processing, even if every component is healthy.
Message age is often the first user-impact signal, before error rates move.
Worker latency and downstream latency can point at different causes.
One correlated trace is worth more than averages when the backlog is uneven.

02 — Constraints

Public-safe, deterministic, and honest about what the numbers are.

This case stays public-safe. Every identifier is synthetic, there is no live AWS account, and the simulation uses a fixed seed so the output reproduces. The numbers on this page come from the model, not from a production system.

Seeded randomness keeps the run deterministic.
No employer code or production identifiers appear.
Metrics and events use the same names a production dashboard would use.
The model's job is to keep the debugging reasoning executable, not to claim real scale.

03 — Architecture

A small queue system with the signals production would emit.

The model is small on purpose. API submissions enter a FIFO queue, three workers pull from it, and every worker call passes through a downstream dependency. At each step the model emits the metrics, events, and spans that a production system would.

Intake

API submit

Queue

FIFO queue DLQ

Workers

3-worker pool Retries (max 2)

Dependency

Downstream call

Signals

Metrics Log events Spans

The useful path is not a dashboard of averages. It is the sequence an operator actually walks: the symptom, the two signals that name it, the one correlation that locates the time, the downstream call that caused it, and the runbook that says what to do next.

04 — Signals and tests

The signals have names, and the tests pin them down.

Signals are only useful if their names are stable and their thresholds are testable. The companion repo defines the names once and tests them in five files.

Metric signals
Metric name	What it tells an operator
`QueueDepthApproximate`	How many messages are waiting. Rises when intake outpaces processing.
`OldestMessageAgeSeconds`	How long the front message has been waiting. Often the first user-impact signal.
`WorkerProcessingLatencyMs`	p50, p95, and p99 of completed worker cycles. A jump here points at the worker or downstream.
`WorkerErrorRate`	Failed attempts over the recent window. Separates retry pressure from throughput pressure.
`DownstreamLatencyMs`	Average latency of the downstream call. In this run it steps from 40ms to 900ms at tick 200.
`MessagesReceivedPerMin`	Submission rate. Steady here at 30 messages per tick, or 1,800 per minute.
`MessagesDeletedPerMin`	Completion rate. Drops when latency rises and the backlog starts to form.
`DlqMessageCount`	Messages that exhausted retries. Each increment is a candidate for a runbook entry.

Log events: message.received · message.processing.started · message.processing.completed · message.processing.failed · downstream.call.completed · backlog.threshold.warning · backlog.threshold.breached. Spans: api.submit · queue.wait · worker.process · downstream.call. Every event and span carries the correlation ID so a single value traces one message.

Tests

The repo has 19 tests across 5 files. Run them with npm test, npm run build, npm run verify, npm run scenario, or npm run runbook.

Test files
File	Tests	Coverage
`test/signals.test.ts`	3	Metric, log, and span names are stable.
`test/thresholds.test.ts`	6	Age and depth warnings and breaches fire at the configured thresholds.
`test/correlation.test.ts`	3	A correlation ID gathers its events, spans, and timing totals.
`test/runbook.test.ts`	4	Runbook evidence, failure state, and next checks are assembled from the result.
`test/determinism.test.ts`	3	Same seed produces identical output; different seeds keep the same shape.

05 — Scenario

A latency step collapses throughput, and the backlog tells the story.

The scenario runs 600 ticks. Submissions are steady at 30 per tick and three workers normally clear the queue. At tick 200 the downstream latency jumps from 40ms to 900ms. The backlog starts to form immediately.

Tick 207: depth warning fires at 217 messages, above the 200 threshold.
Tick 218: depth breach fires at 515 messages, above the 500 threshold.
Tick 532: age breach fires when the oldest message reaches 300 seconds, above the 300 threshold.
The age warning threshold is 120 seconds; it stays below breach until the backlog is already deep.
By tick 599: depth reaches 10,820 and oldest age reaches 360 seconds.

scenario-timeline.txt

Timeline excerpt around the breach ticks

Generated by npm run scenario in the companion repository.

backlog breach scenario
ticks=600 workers=3 injectionTick=200

tick=195 depth=   0 oldestAge=   0 breaches=-
tick=196 depth=   0 oldestAge=   0 breaches=-
tick=197 depth=   0 oldestAge=   0 breaches=-
tick=198 depth=   0 oldestAge=   0 breaches=-
tick=199 depth=   0 oldestAge=   0 breaches=-
tick=200 depth=  27 oldestAge=   0 breaches=-
tick=201 depth=  54 oldestAge=   1 breaches=-
tick=202 depth=  81 oldestAge=   2 breaches=-
tick=203 depth= 108 oldestAge=   3 breaches=-
tick=204 depth= 135 oldestAge=   4 breaches=-
tick=205 depth= 162 oldestAge=   5 breaches=-
tick=206 depth= 190 oldestAge=   6 breaches=-
tick=207 depth= 217 oldestAge=   7 breaches=backlog.threshold.warning
tick=208 depth= 244 oldestAge=   8 breaches=backlog.threshold.warning
tick=209 depth= 271 oldestAge=   9 breaches=backlog.threshold.warning
tick=210 depth= 298 oldestAge=   9 breaches=backlog.threshold.warning
tick=211 depth= 325 oldestAge=  10 breaches=backlog.threshold.warning
tick=212 depth= 352 oldestAge=  11 breaches=backlog.threshold.warning
tick=213 depth= 379 oldestAge=  12 breaches=backlog.threshold.warning
tick=214 depth= 407 oldestAge=  13 breaches=backlog.threshold.warning
tick=215 depth= 434 oldestAge=  14 breaches=backlog.threshold.warning
tick=216 depth= 461 oldestAge=  15 breaches=backlog.threshold.warning
tick=217 depth= 488 oldestAge=  16 breaches=backlog.threshold.warning
tick=218 depth= 515 oldestAge=  17 breaches=backlog.threshold.breached
tick=219 depth= 542 oldestAge=  18 breaches=backlog.threshold.breached
tick=220 depth= 569 oldestAge=  18 breaches=backlog.threshold.breached
tick=221 depth= 596 oldestAge=  19 breaches=backlog.threshold.breached
tick=222 depth= 623 oldestAge=  20 breaches=backlog.threshold.breached
tick=223 depth= 650 oldestAge=  21 breaches=backlog.threshold.breached
tick=224 depth= 677 oldestAge=  22 breaches=backlog.threshold.breached
tick=225 depth= 704 oldestAge=  23 breaches=backlog.threshold.breached
tick=226 depth= 731 oldestAge=  24 breaches=backlog.threshold.breached
tick=227 depth= 758 oldestAge=  25 breaches=backlog.threshold.breached
tick=228 depth= 785 oldestAge=  26 breaches=backlog.threshold.breached
tick=229 depth= 812 oldestAge=  27 breaches=backlog.threshold.breached
tick=230 depth= 839 oldestAge=  27 breaches=backlog.threshold.breached
tick=231 depth= 866 oldestAge=  28 breaches=backlog.threshold.breached
tick=232 depth= 893 oldestAge=  29 breaches=backlog.threshold.breached
tick=233 depth= 920 oldestAge=  30 breaches=backlog.threshold.breached
tick=234 depth= 947 oldestAge=  31 breaches=backlog.threshold.breached
tick=235 depth= 974 oldestAge=  32 breaches=backlog.threshold.breached
tick=236 depth=1001 oldestAge=  33 breaches=backlog.threshold.breached
tick=237 depth=1028 oldestAge=  34 breaches=backlog.threshold.breached
tick=238 depth=1055 oldestAge=  35 breaches=backlog.threshold.breached
tick=239 depth=1082 oldestAge=  36 breaches=backlog.threshold.breached
tick=240 depth=1109 oldestAge=  36 breaches=backlog.threshold.breached
...
tick=525 depth=8820 oldestAge= 293 breaches=backlog.threshold.warning,backlog.threshold.breached
tick=526 depth=8847 oldestAge= 294 breaches=backlog.threshold.warning,backlog.threshold.breached
tick=527 depth=8874 oldestAge= 295 breaches=backlog.threshold.warning,backlog.threshold.breached
tick=528 depth=8901 oldestAge= 296 breaches=backlog.threshold.warning,backlog.threshold.breached
tick=529 depth=8928 oldestAge= 297 breaches=backlog.threshold.warning,backlog.threshold.breached
tick=530 depth=8955 oldestAge= 298 breaches=backlog.threshold.warning,backlog.threshold.breached
tick=531 depth=8982 oldestAge= 299 breaches=backlog.threshold.warning,backlog.threshold.breached
tick=532 depth=9009 oldestAge= 300 breaches=backlog.threshold.breached,backlog.threshold.breached
tick=533 depth=9036 oldestAge= 301 breaches=backlog.threshold.breached,backlog.threshold.breached
tick=534 depth=9063 oldestAge= 302 breaches=backlog.threshold.breached,backlog.threshold.breached
tick=535 depth=9090 oldestAge= 302 breaches=backlog.threshold.breached,backlog.threshold.breached
tick=536 depth=9117 oldestAge= 303 breaches=backlog.threshold.breached,backlog.threshold.breached
tick=537 depth=9144 oldestAge= 304 breaches=backlog.threshold.breached,backlog.threshold.breached
tick=538 depth=9171 oldestAge= 305 breaches=backlog.threshold.breached,backlog.threshold.breached
tick=539 depth=9199 oldestAge= 306 breaches=backlog.threshold.breached,backlog.threshold.breached
tick=540 depth=9226 oldestAge= 307 breaches=backlog.threshold.breached,backlog.threshold.breached
...
tick=599 depth=10820 oldestAge= 360 breaches=backlog.threshold.breached,backlog.threshold.breached

correlated trace for corr-201-6056 (messageId=msg-201-6056)
queueWaitMs=17974 processingMs=900 downstreamMs=900
log events:
  message.received @201026 worker=- {"tick":201}
  backlog.threshold.breached @218000 worker=- {"tick":218,"thresholdType":"QueueDepthApproximate","observedValue":515,"threshold":500,"severity":"breach"}
  message.processing.started @219000 worker=worker-0 {"tick":219,"downstreamLatencyMs":900}
  downstream.call.completed @219900 worker=worker-0 {"tick":219,"downstreamLatencyMs":900,"status":"success"}
  message.processing.completed @219900 worker=worker-0 {"tick":219}
span tree:
  api.submit [201026-201026] dur=0ms worker=-
    queue.wait [201026-219000] dur=17974ms worker=-
      worker.process [219000-219900] dur=900ms worker=worker-0
        downstream.call [219000-219900] dur=900ms worker=worker-0

One correlated trace

The message corr-201-6056 waited about 18 seconds in the queue before a worker picked it up. The worker then spent 900ms in worker.process, all of it in downstream.call. The span tree in the timeline shows the queue wait dominating the total time.

06 — Implementation

The model, the thresholds, the correlation, the runbook.

The companion repository keeps each concern in its own file. The snippets below are the parts that define the signal names, decide when a threshold fires, and assemble a trace around one correlation ID.

src/signals.ts

Signal names in one place.

Metrics, log events, and spans share these names across the model, tests, and runbook.

export type Metric = {
  name: string;
  value: number;
  unit?: string;
  timestamp: number;
  labels?: Record<string, string>;
};

export type LogEvent = {
  name: string;
  timestamp: number;
  correlationId: string;
  messageId: string;
  workerId?: string;
  attributes?: Record<string, unknown>;
};

export type Span = {
  spanId: string;
  parentId?: string;
  name: string;
  startTime: number;
  endTime?: number;
  correlationId: string;
  messageId: string;
  workerId?: string;
};

export const MetricNames = {
  QueueDepthApproximate: 'QueueDepthApproximate',
  OldestMessageAgeSeconds: 'OldestMessageAgeSeconds',
  WorkerProcessingLatencyMs: 'WorkerProcessingLatencyMs',
  WorkerErrorRate: 'WorkerErrorRate',
  DownstreamLatencyMs: 'DownstreamLatencyMs',
  MessagesReceivedPerMin: 'MessagesReceivedPerMin',
  MessagesDeletedPerMin: 'MessagesDeletedPerMin',
  DlqMessageCount: 'DlqMessageCount',
} as const;

export const LogEventNames = {
  MessageReceived: 'message.received',
  MessageProcessingStarted: 'message.processing.started',
  MessageProcessingCompleted: 'message.processing.completed',
  MessageProcessingFailed: 'message.processing.failed',
  DownstreamCallCompleted: 'downstream.call.completed',
  BacklogThresholdWarning: 'backlog.threshold.warning',
  BacklogThresholdBreached: 'backlog.threshold.breached',
} as const;

export const SpanNames = {
  ApiSubmit: 'api.submit',
  QueueWait: 'queue.wait',
  WorkerProcess: 'worker.process',
  DownstreamCall: 'downstream.call',
} as const;

src/thresholds.ts

Threshold events from current metrics.

Warning and breach events carry the observed value, threshold, and the oldest message ID for correlation.

// @ts-nocheck
import { Metric, LogEvent, MetricNames, LogEventNames } from './signals.js';
import type { ScenarioConfig } from './model.js';

export function evaluateThresholds(
  tick: number,
  timestamp: number,
  metrics: Metric[],
  config: ScenarioConfig,
  oldestMessage?: { correlationId: string; messageId: string }
): LogEvent[] {
  const events: LogEvent[] = [];
  const correlationId = oldestMessage?.correlationId ?? 'system';
  const messageId = oldestMessage?.messageId ?? 'system';

  const ageMetric = metrics.find((m) => m.name === MetricNames.OldestMessageAgeSeconds);
  const depthMetric = metrics.find((m) => m.name === MetricNames.QueueDepthApproximate);

  const age = ageMetric?.value ?? 0;
  const depth = depthMetric?.value ?? 0;

  if (age >= config.ageBreachThresholdSeconds) {
    events.push({
      name: LogEventNames.BacklogThresholdBreached,
      timestamp,
      correlationId,
      messageId,
      attributes: {
        tick,
        thresholdType: MetricNames.OldestMessageAgeSeconds,
        observedValue: age,
        threshold: config.ageBreachThresholdSeconds,
        severity: 'breach',
      },
    });
  } else if (age >= config.ageWarningThresholdSeconds) {
    events.push({
      name: LogEventNames.BacklogThresholdWarning,
      timestamp,
      correlationId,
      messageId,
      attributes: {
        tick,
        thresholdType: MetricNames.OldestMessageAgeSeconds,
        observedValue: age,
        threshold: config.ageWarningThresholdSeconds,
        severity: 'warning',
      },
    });
  }

  if (depth >= config.depthBreachThreshold) {
    events.push({
      name: LogEventNames.BacklogThresholdBreached,
      timestamp,
      correlationId,
      messageId,
      attributes: {
        tick,
        thresholdType: MetricNames.QueueDepthApproximate,
        observedValue: depth,
        threshold: config.depthBreachThreshold,
        severity: 'breach',
      },
    });
  } else if (depth >= config.depthWarningThreshold) {
    events.push({
      name: LogEventNames.BacklogThresholdWarning,
      timestamp,
      correlationId,
      messageId,
      attributes: {
        tick,
        thresholdType: MetricNames.QueueDepthApproximate,
        observedValue: depth,
        threshold: config.depthWarningThreshold,
        severity: 'warning',
      },
    });
  }

  return events;
}

src/correlation.ts

Gather events and spans for one correlation ID.

The correlation result sums queue wait, worker processing, and downstream call durations.

// @ts-nocheck
import type { SimulationResult } from './model.js';
import { SpanNames, type LogEvent, type Span } from './signals.js';

export interface SpanNode {
  span: Span;
  children: SpanNode[];
}

export interface CorrelationResult {
  correlationId: string;
  messageId?: string;
  logEvents: LogEvent[];
  spans: Span[];
  spanTree: SpanNode[];
  queueWaitMs: number;
  processingMs: number;
  downstreamMs: number;
}

export function correlate(id: string, result: SimulationResult): CorrelationResult {
  const logEvents = result.events.filter(
    (e) => e.correlationId === id || e.messageId === id
  );
  const spans = result.spans.filter(
    (s) => s.correlationId === id || s.messageId === id
  );

  const messageId =
    spans.find((s) => s.messageId)?.messageId ??
    logEvents.find((e) => e.messageId)?.messageId;

  const roots = spans.filter((s) => !s.parentId);
  const byParent = new Map<string, Span[]>();
  for (const span of spans) {
    if (span.parentId) {
      const list = byParent.get(span.parentId) ?? [];
      list.push(span);
      byParent.set(span.parentId, list);
    }
  }

  function buildTree(span: Span): SpanNode {
    return {
      span,
      children: (byParent.get(span.spanId) ?? []).map(buildTree),
    };
  }

  const spanTree = roots.map(buildTree);

  const sumSpanDuration = (name: string): number =>
    spans
      .filter((s) => s.name === name)
      .reduce((sum, s) => sum + ((s.endTime ?? s.startTime) - s.startTime), 0);

  return {
    correlationId: id,
    messageId,
    logEvents,
    spans,
    spanTree,
    queueWaitMs: sumSpanDuration(SpanNames.QueueWait),
    processingMs: sumSpanDuration(SpanNames.WorkerProcess),
    downstreamMs: sumSpanDuration(SpanNames.DownstreamCall),
  };
}

runbook-output.txt

Runbook assembled from the breach scenario.

Generated by npm run runbook in the companion repository.

Queue backlog runbook
=====================

Failure state
-------------
- QueueDepthApproximate breached at tick 218 (observed 515, threshold 500)
- OldestMessageAgeSeconds breached at tick 532 (observed 300, threshold 300)

Evidence
--------
- Queue depth grew from 27 at injection to 10820 at tick 599
- Oldest message age reached 360 seconds at tick 599
- Worker processing latency p95 peaked at 900 ms
- Worker processing latency p50 peaked at 900 ms
- Downstream latency peaked at 900 ms
- Worker error rate peaked at 0.045

Next checks
-----------
1. Confirm downstream latency regression
2. Check worker error rate
3. Decide scale-out vs rollback

See src/model.ts, src/scenario.ts, src/runbook.ts, and src/run-scenario.ts for the full simulation, scenario config, runbook formatting, and timeline output.

07 — Tradeoffs

What this model shows, and what it deliberately does not claim.

I would rather follow one correlation ID through the queue than average the backlog into a single latency number.

01

Executable model first

The simulation keeps the failure mode reproducible before adding real cloud telemetry. The tradeoff is that the numbers are synthetic, but every claim on this page can be regenerated.
02

Signal clarity over alert sophistication

Depth, age, worker latency, and downstream latency are emitted with the same names a production dashboard would use. The alerting logic in a real system would need tuning, but the signal boundaries are explicit.
03

Correlation as the debugging unit

Every message carries a correlation ID from submit through queue wait, worker processing, and downstream call. That makes a single slow message traceable, but it requires discipline in how events are stamped.

Intentionally absent

No live AWS account or production traffic. The numbers come from a seeded TypeScript simulation.
No production identity, encryption, or secret rotation. The model stays focused on queue behavior and signals.
No auto-scaling or rollback logic. The runbook stops at 'decide scale-out vs rollback' because that choice depends on real context.

Production path

CloudWatch and X-Ray wiring. Emit the same metric names through EMF and the same spans through X-Ray so the production dashboard matches the model.
Alarm thresholds from real traffic. Set depth and age thresholds using historical p99 behavior, not the synthetic defaults in the model.
Scale-out response automation. Add the policy that follows a breach: concurrency increase, visibility timeout change, or downstream rollback.
Runbook integration. Connect the runbook output to the paging tool so the on-call engineer sees breach state, evidence, and next checks in one place.