How to check job order in a queue

Stamp a sequence number at claim, at start and at completion, then count inverted pairs. node run.mjs 4 1 0 24 1 handed the 24 jobs out in perfect order and completed them 1 3 5 4 2 6, 17 inverted pairs of 276. One worker inverted nothing and took 1974 ms against 663.

Why check this

A queue that hands work out in order and a system that completes work in order are two different promises. Most queues make the first. Almost nothing gives you the second.

Run this after raising worker concurrency, and when a ticket says a record holds an older value than the one written last. The failure it prevents: two updates to the same row, enqueued 40 ms apart, are claimed by two workers and finish backwards, so the row keeps the earlier value. Nothing errors, nothing retries, no duplicate appears.

Separate three orders first: the order the queue handed rows out, the order handlers began, and the order side effects landed. Step 4 makes the first perfect and the second not.

Prerequisites

• Node 22. The queue is a table in node:sqlite, experimental and warning on import. Step 1 shows it; later commands set NODE_NO_WARNINGS=1.
• The three programs below, in one directory. The workers are separate processes started with child_process.fork, so they contend for real.
• Timings came from one machine with 8 cores. The inversion counts transfer, the milliseconds do not.
• The queue and the seeding. Save as queue-init.mjs.

// queue-init.mjs <jobs> <per>. Rebuilds queue.db, enqueues jobs 1..n in order,
// <per> consecutive jobs to an entity. entity is the row a job updates, so at
// n = 24, per = 3 there are 8 entities and 24 pairs that must not be reordered.
import { DatabaseSync } from 'node:sqlite';
import { rmSync } from 'node:fs';

const n = Number(process.argv[2] ?? 24);
const per = Number(process.argv[3] ?? 3);
for (const f of ['queue.db', 'queue.db-wal', 'queue.db-shm']) rmSync(f, { force: true });
const db = new DatabaseSync('queue.db');
db.exec(`
  PRAGMA journal_mode = WAL;
  CREATE TABLE jobs (
    id      INTEGER PRIMARY KEY,
    entity  TEXT NOT NULL,
    state   TEXT NOT NULL DEFAULT 'pending',
    worker  TEXT,
    claim_n INTEGER,
    start_n INTEGER,
    done_n  INTEGER
  );
  CREATE TABLE seq (name TEXT PRIMARY KEY, n INTEGER NOT NULL);
  INSERT INTO seq VALUES ('claim', 0), ('start', 0), ('done', 0);
`);
const ins = db.prepare('INSERT INTO jobs (id, entity) VALUES (?, ?)');
for (let i = 1; i <= n; i += 1) ins.run(i, `e${Math.ceil(i / per)}`);
console.log(
  db
    .prepare('SELECT id, entity FROM jobs ORDER BY id')
    .all()
    .map((r) => `${r.id}:${r.entity}`)
    .join(' '),
);
db.close();

• The worker. Its three counters turn an anecdote into a count. Save as worker.mjs.

// worker.mjs <tag> <prefetch> <keyed 0|1>. Claims FIFO, stamps a global
// sequence number at claim, at start and at completion, exits when nothing is
// pending. Service time is fixed per job id, so two runs are comparable.
import { DatabaseSync } from 'node:sqlite';

const tag = process.argv[2];
const prefetch = Number(process.argv[3] ?? 1);
const keyed = process.argv[4] === '1';

const db = new DatabaseSync('queue.db');
db.exec('PRAGMA busy_timeout = 5000');
const next = db.prepare('UPDATE seq SET n = n + 1 WHERE name = ? RETURNING n');
const fifo = db.prepare(
  `UPDATE jobs SET state = 'claimed', worker = ?
     WHERE id IN (SELECT id FROM jobs WHERE state = 'pending' ORDER BY id LIMIT ?)
   RETURNING id`,
);
const perKey = db.prepare(
  `UPDATE jobs SET state = 'claimed', worker = ?
     WHERE id = (SELECT j.id FROM jobs j
                  WHERE j.state = 'pending'
                    AND NOT EXISTS (SELECT 1 FROM jobs r
                                     WHERE r.entity = j.entity
                                       AND r.state IN ('claimed', 'running'))
                  ORDER BY j.id LIMIT 1)
   RETURNING id`,
);
const atClaim = db.prepare('UPDATE jobs SET claim_n = ? WHERE id = ?');
const atStart = db.prepare("UPDATE jobs SET state = 'running', start_n = ? WHERE id = ?");
const atDone = db.prepare("UPDATE jobs SET state = 'done', done_n = ? WHERE id = ?");
const pending = db.prepare("SELECT COUNT(*) AS c FROM jobs WHERE state = 'pending'");
const sleep = (ms) => new Promise((r) => setTimeout(r, ms));
const service = (id) => 15 + ((id * 37) % 5) * 25;

let done = 0;
let polls = 0;
for (;;) {
  const rows = keyed ? perKey.all(tag) : fifo.all(tag, prefetch);
  if (rows.length === 0) {
    if (pending.get().c === 0) break;
    polls += 1;
    await sleep(5);
    continue;
  }
  for (const r of rows) atClaim.run(next.get('claim').n, r.id);
  for (const r of rows) {
    atStart.run(next.get('start').n, r.id);
    await sleep(service(r.id));
    atDone.run(next.get('done').n, r.id);
    done += 1;
  }
}
console.log(`${tag} finished ${done} jobs after ${polls} empty polls`);
db.close();

• The harness. Save as run.mjs.

// run.mjs <workers> <prefetch> <keyed 0|1> <jobs> <repeats> <jobs per entity>
// Rebuilds the queue, forks the workers, waits for all of them, then reads the
// three orders out of the table and counts pairs that came back inverted.
import { fork } from 'node:child_process';
import { DatabaseSync } from 'node:sqlite';

const [w, prefetch, keyed, jobs, repeats, per = 3] = process.argv.slice(2).map(Number);

const order = (rows, col) => rows.slice().sort((a, b) => a[col] - b[col]).map((r) => r.id);
const inversions = (rows, col, samePair) => {
  let n = 0;
  for (let i = 0; i < rows.length; i += 1)
    for (let j = i + 1; j < rows.length; j += 1)
      if ((!samePair || rows[i].entity === rows[j].entity) && rows[i][col] > rows[j][col]) n += 1;
  return n;
};
const samePairs = (rows) => {
  let n = 0;
  for (let i = 0; i < rows.length; i += 1)
    for (let j = i + 1; j < rows.length; j += 1) if (rows[i].entity === rows[j].entity) n += 1;
  return n;
};

const runOnce = async () => {
  await new Promise((res) => fork('queue-init.mjs', [String(jobs), String(per)], { stdio: 'ignore' }).on('exit', res));
  const t0 = Date.now();
  await Promise.all(
    Array.from({ length: w }, (_, i) =>
      new Promise((res) => fork('worker.mjs', [`w${i + 1}`, String(prefetch), String(keyed)], { stdio: 'ignore' }).on('exit', res)),
    ),
  );
  const ms = Date.now() - t0;
  const db = new DatabaseSync('queue.db');
  const rows = db.prepare('SELECT id, entity, worker, claim_n, start_n, done_n FROM jobs ORDER BY id').all();
  db.close();
  return { ms, rows };
};

const summary = [];
let sp = 0;
for (let r = 1; r <= repeats; r += 1) {
  const { ms, rows } = await runOnce();
  const s = {
    ms,
    claim: inversions(rows, 'claim_n', false),
    start: inversions(rows, 'start_n', false),
    done: inversions(rows, 'done_n', false),
    key: inversions(rows, 'done_n', true),
  };
  summary.push(s);
  sp = samePairs(rows);
  if (repeats === 1) {
    console.log(`enqueued   ${rows.map((x) => x.id).join(' ')}`);
    console.log(`claimed    ${order(rows, 'claim_n').join(' ')}`);
    console.log(`started    ${order(rows, 'start_n').join(' ')}`);
    console.log(`completed  ${order(rows, 'done_n').join(' ')}`);
    console.log(`ran on     ${rows.map((x) => `${x.id}=${x.worker}`).join(' ')}`);
  }
  console.log(
    `run ${r}: ${ms} ms, ${(rows.length / (ms / 1000)).toFixed(2)} jobs/s, inverted pairs ` +
      `claim ${s.claim}, start ${s.start}, done ${s.done} of ${(rows.length * (rows.length - 1)) / 2}; ` +
      `${s.key} of ${samePairs(rows)} same-entity pairs out of order`,
  );
}
const sum = (k) => summary.reduce((a, b) => a + b[k], 0);
const mean = (k) => (sum(k) / repeats).toFixed(1);
const runsWith = (k) => summary.filter((s) => s[k] > 0).length;
console.log(
  `${repeats} runs, ${w} workers, prefetch ${prefetch}, keyed ${keyed}: ` +
    `completed out of order in ${runsWith('done')}/${repeats} runs, ` +
    `a same-entity pair reordered in ${runsWith('key')}/${repeats} runs ` +
    `(${sum('key')} pairs of ${repeats * sp}); ` +
    `mean ${(sum('ms') / repeats).toFixed(0)} ms, ` +
    `mean inverted pairs claim ${mean('claim')}, start ${mean('start')}, done ${mean('done')}`,
);

Steps

1. 1

   Step 1.

   Enqueue 24 jobs, three to an entity.

   node queue-init.mjs 24 3
   

   1:e1 2:e1 3:e1 4:e2 5:e2 6:e2 7:e3 8:e3 9:e3 10:e4 11:e4 12:e4 13:e5 14:e5 15:e5 16:e6 17:e6 18:e6 19:e7 20:e7 21:e7 22:e8 23:e8 24:e8
   (node:40760) ExperimentalWarning: SQLite is an experimental feature and might change at any time
   (Use `node --trace-warnings ...` to show where the warning was created)

   Jobs 1, 2 and 3 all update e1, so their relative order is what is under test. There are 24 such pairs; every other may be reordered without harm. Run export NODE_NO_WARNINGS=1 first.

2. 2

   Step 2.

   Run one worker over the queue as the control.

   node run.mjs 1 1 0 24 1
   

   enqueued   1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24
   claimed    1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24
   started    1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24
   completed  1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24
   ran on     1=w1 2=w1 3=w1 4=w1 5=w1 6=w1 7=w1 8=w1 9=w1 10=w1 11=w1 12=w1 13=w1 14=w1 15=w1 16=w1 17=w1 18=w1 19=w1 20=w1 21=w1 22=w1 23=w1 24=w1
   run 1: 1974 ms, 12.16 jobs/s, inverted pairs claim 0, start 0, done 0 of 276; 0 of 24 same-entity pairs out of order
   1 runs, 1 workers, prefetch 1, keyed 0: completed out of order in 0/1 runs, a same-entity pair reordered in 0/1 runs (0 pairs of 24); mean 1974 ms, mean inverted pairs claim 0.0, start 0.0, done 0.0

   All four rows are the same list. This is the only configuration that gives ordering for free, and at 12.16 jobs/s the slowest by a factor of three.

3. 3

   Step 3.

   Run four workers over the same queue.

   node run.mjs 4 1 0 24 1
   

   enqueued   1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24
   claimed    1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24
   started    1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24
   completed  1 3 5 4 2 6 8 10 7 11 9 13 15 12 14 18 16 20 17 19 23 21 22 24
   ran on     1=w1 2=w2 3=w3 4=w4 5=w1 6=w3 7=w1 8=w4 9=w2 10=w3 11=w4 12=w3 13=w1 14=w4 15=w2 16=w1 17=w2 18=w3 19=w4 20=w3 21=w1 22=w3 23=w2 24=w4
   run 1: 663 ms, 36.20 jobs/s, inverted pairs claim 0, start 0, done 17 of 276; 8 of 24 same-entity pairs out of order
   1 runs, 4 workers, prefetch 1, keyed 0: completed out of order in 1/1 runs, a same-entity pair reordered in 1/1 runs (8 pairs of 24); mean 663 ms, mean inverted pairs claim 0.0, start 0.0, done 17.0

   The claimed row is 1 to 24; the completed row is not. Job 5 lands third because it runs 15 ms against 115 for job 2. Read the last number: 8 of the 24 same-entity pairs came back inverted.

4. 4

   Step 4.

   Claim four jobs at a time instead of one.

   node run.mjs 4 4 0 24 1
   

   enqueued   1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24
   claimed    1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24
   started    1 5 9 13 6 2 14 7 10 11 15 3 16 12 4 8 17 21 22 18 19 23 24 20
   completed  5 1 13 6 9 10 14 2 15 11 3 7 16 8 4 12 21 17 18 22 23 19 20 24
   ran on     1=w1 2=w1 3=w1 4=w1 5=w2 6=w2 7=w2 8=w2 9=w3 10=w3 11=w3 12=w3 13=w4 14=w4 15=w4 16=w4 17=w4 18=w4 19=w4 20=w4 21=w2 22=w2 23=w2 24=w2
   run 1: 782 ms, 30.69 jobs/s, inverted pairs claim 0, start 53, done 57 of 276; 6 of 24 same-entity pairs out of order
   1 runs, 4 workers, prefetch 4, keyed 0: completed out of order in 1/1 runs, a same-entity pair reordered in 1/1 runs (6 pairs of 24); mean 782 ms, mean inverted pairs claim 0.0, start 53.0, done 57.0

   The queue handed rows out in flawless order, claim inversions 0, and 53 pairs had already started out of order before any work finished. Batching also cost time, 782 ms against 663.

5. 5

   Step 5.

   Serialise by entity: skip a job whose entity is already in flight.

   node run.mjs 4 1 1 24 1
   

   enqueued   1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24
   claimed    1 4 7 10 11 2 5 12 6 8 3 9 13 16 19 14 17 22 20 15 21 18 23 24
   started    1 4 7 10 11 2 5 12 6 8 3 9 13 16 19 14 17 22 20 15 21 18 23 24
   completed  10 1 4 11 5 7 2 8 6 3 12 13 16 9 19 14 20 15 17 21 22 18 23 24
   ran on     1=w1 2=w1 3=w1 4=w2 5=w2 6=w2 7=w4 8=w4 9=w4 10=w3 11=w3 12=w3 13=w2 14=w2 15=w2 16=w1 17=w1 18=w1 19=w3 20=w3 21=w3 22=w4 23=w4 24=w4
   run 1: 720 ms, 33.33 jobs/s, inverted pairs claim 39, start 39, done 40 of 276; 0 of 24 same-entity pairs out of order
   1 runs, 4 workers, prefetch 1, keyed 1: completed out of order in 1/1 runs, a same-entity pair reordered in 0/1 runs (0 pairs of 24); mean 720 ms, mean inverted pairs claim 39.0, start 39.0, done 40.0

   The queue is now less FIFO than before, 39 inverted pairs at claim against 0 in step 3, and it is correct: none of the 24 same-entity pairs came back out of order. A global FIFO assertion would fail this run and pass the buggy step 3.

6. 6

   Step 6.

   Repeat each of the four configurations ten times and read the counts.

   for cfg in "1 1 0 24 10 3" "4 1 0 24 10 3" "4 4 0 24 10 3" "4 1 1 24 10 3"; do node run.mjs $cfg | tail -1; done
   

   10 runs, 1 workers, prefetch 1, keyed 0: completed out of order in 0/10 runs, a same-entity pair reordered in 0/10 runs (0 pairs of 240); mean 1986 ms, mean inverted pairs claim 0.0, start 0.0, done 0.0
   10 runs, 4 workers, prefetch 1, keyed 0: completed out of order in 10/10 runs, a same-entity pair reordered in 10/10 runs (87 pairs of 240); mean 666 ms, mean inverted pairs claim 0.0, start 0.0, done 17.9
   10 runs, 4 workers, prefetch 4, keyed 0: completed out of order in 10/10 runs, a same-entity pair reordered in 10/10 runs (60 pairs of 240); mean 752 ms, mean inverted pairs claim 0.0, start 53.1, done 57.2
   10 runs, 4 workers, prefetch 1, keyed 1: completed out of order in 10/10 runs, a same-entity pair reordered in 0/10 runs (0 pairs of 240); mean 704 ms, mean inverted pairs claim 37.7, start 37.7, done 39.8

   Ten runs of ten reordered a same-entity pair at four workers, 87 of 240 pairs. Keying fixed all 240 and cost 38 ms on the mean. One worker cost 1320 ms.

7. 7

   Step 7.

   Vary how many jobs share a key.

   for per in 1 3 8 24; do node run.mjs 4 1 1 24 5 $per | tail -1; done
   

   5 runs, 4 workers, prefetch 1, keyed 1: completed out of order in 5/5 runs, a same-entity pair reordered in 0/5 runs (0 pairs of 0); mean 650 ms, mean inverted pairs claim 0.0, start 0.0, done 15.8
   5 runs, 4 workers, prefetch 1, keyed 1: completed out of order in 5/5 runs, a same-entity pair reordered in 0/5 runs (0 pairs of 120); mean 700 ms, mean inverted pairs claim 38.6, start 38.6, done 40.0
   5 runs, 4 workers, prefetch 1, keyed 1: completed out of order in 5/5 runs, a same-entity pair reordered in 0/5 runs (0 pairs of 420); mean 864 ms, mean inverted pairs claim 85.8, start 85.8, done 85.8
   5 runs, 4 workers, prefetch 1, keyed 1: completed out of order in 0/5 runs, a same-entity pair reordered in 0/5 runs (0 pairs of 1380); mean 2220 ms, mean inverted pairs claim 0.0, start 0.0, done 0.0

   One job per key cost 650 ms, three cost 700, eight cost 864, and all 24 on one key cost 2220 ms with every order perfect. That last line is four workers behaving as one, slower than step 2's single worker.

How to read the result

| What you see | What it means | What to do | | --- | --- | --- | | claim 0, done 17 | The queue is FIFO and the system is not. Service time, not the queue, decided the order | Stop looking at the broker. The reorder happened in the workers | | claim 0, start 53 | Work started out of order before anything finished. A batch claim is holding jobs a worker has not begun | Set prefetch or batch size to 1 for the ordered class of jobs | | Same-entity pairs above 0 in any run | Two jobs touching one row landed backwards. This is the defect | Serialise on the key, as step 5 does, or merge the two jobs into one | | Same-entity pairs 0, global inversions high | The keyed claim is working. Step 5 shows 39 at claim and 0 where it matters | Assert on the keyed count. A global FIFO assertion here is a false failure | | All four orders identical at four workers | Either the key is hot or the service time is uniform | Check step 7: one key turned four workers into one and cost 2220 ms | | done inversions above 0 in 1 of 10 runs | A rare race, not a stable property | Raise the repeat count before deciding. Step 6 needed ten runs to produce 87 of 240 |

Common mistakes

What to check next

• How to check queue depth and consumer lag: the throughput half of this trade.
• How to test duplicate job execution: the other concurrency defect; every run here claimed each job once.
• How to check a background job is idempotent: what to add when an ordered pair cannot be serialised.
• Webhook ordering: the same inversion caused by a retry, not by a second consumer.
• How to check websocket message order: ordering on one connection, where the guarantee holds.

FAQ

What is a FIFO queue?

A queue that hands work out in the order it arrived. That is a promise about claiming, not about finishing: step 3 claimed 1 to 24 in order and completed 1 3 5 4 2 6 with four consumers.

Does a queue guarantee jobs finish in order?

Not with more than one consumer. Four workers finished out of order in 10 of 10 runs and reordered 87 of 240 same-entity pairs. Order across consumers needs a per-key lock or a single worker.

How do I test a FIFO queue?

Enqueue a numbered sequence, stamp a counter at claim, at start and at completion, then count inverted pairs over ten runs. Assert on pairs that share a key: a global assertion fails on correct systems, as step 5 shows.

What does serialising by key cost?

It depends on the keys, not on the lock. The keyed run measured 650 ms at 24 keys, 700 ms at 8 keys, 864 ms at 3, and 2220 ms at 1, which is worse than one worker.

Verified