Skip to content

Commit e48ff41

Browse files
committed
fix: actually fix ordering again
1 parent f426aaa commit e48ff41

5 files changed

Lines changed: 200 additions & 25 deletions

File tree

src/queue.ts

Lines changed: 31 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -298,6 +298,25 @@ export type QueueOptions = {
298298
*/
299299
orderingGracePeriodDecay?: number;
300300

301+
/**
302+
* Maximum number of jobs to collect in a single batch when using `orderingMethod: 'in-memory'`.
303+
*
304+
* When the grace period expires, the worker collects all remaining jobs in the group up to this limit.
305+
* This prevents memory issues and processing delays when many jobs have accumulated.
306+
*
307+
* @default 10
308+
* @example 5 // Smaller batches for faster processing
309+
* @example 20 // Larger batches for better throughput
310+
* @example 50 // Very large batches for high-volume scenarios
311+
*
312+
* **When to adjust:**
313+
* - High job volume: Increase (20-50) to process more jobs per batch
314+
* - Memory constraints: Decrease (5-10) to reduce memory usage
315+
* - Processing time: Smaller batches = more responsive, larger batches = better throughput
316+
* - Large payloads: Decrease if individual jobs have large data payloads
317+
*/
318+
orderingMaxBatchSize?: number;
319+
301320
/**
302321
* Number of completed jobs to keep in Redis for inspection and debugging.
303322
* Older completed jobs are automatically removed to prevent memory growth.
@@ -540,6 +559,7 @@ export class Queue<T = any> {
540559
private _graceCollectionMs: number; // For 'in-memory' method
541560
private _orderingMaxWaitMultiplier: number; // Max grace period multiplier
542561
private _orderingGracePeriodDecay: number; // Grace period decay factor
562+
private _orderingMaxBatchSize: number; // Max jobs to collect in a batch
543563
private keepFailed: number;
544564
private schedulerLockTtlMs: number;
545565
public name: string;
@@ -565,6 +585,10 @@ export class Queue<T = any> {
565585
return this._orderingGracePeriodDecay;
566586
}
567587

588+
public get orderingMaxBatchSize(): number {
589+
return this._orderingMaxBatchSize;
590+
}
591+
568592
// Inline defineCommand bindings removed; using external Lua via evalsha
569593

570594
constructor(opts: QueueOptions) {
@@ -649,6 +673,13 @@ export class Queue<T = any> {
649673
);
650674
}
651675

676+
// Initialize max batch size (default: 10)
677+
// Clamp between 1 and 100 to prevent extreme values
678+
this._orderingMaxBatchSize = Math.max(
679+
1,
680+
Math.min(100, opts.orderingMaxBatchSize ?? 10),
681+
);
682+
652683
this.r.on('error', (err) => {
653684
this.logger.error('Redis error (main):', err);
654685
});

src/worker.ts

Lines changed: 79 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -300,6 +300,10 @@ class _Worker<T = any> extends TypedEventEmitter<WorkerEvents<T>> {
300300
private redisReadyHandler?: () => void;
301301
private runLoopPromise?: Promise<void>;
302302

303+
// Track when we started collecting for each group (for in-memory ordering)
304+
// This ensures we wait the full grace period from when we FIRST picked up a job from the group
305+
private groupCollectionStartTimes = new Map<string, number>();
306+
303307
constructor(opts: WorkerOptions<T>) {
304308
super();
305309

@@ -346,6 +350,10 @@ class _Worker<T = any> extends TypedEventEmitter<WorkerEvents<T>> {
346350
this.setupRedisEventHandlers();
347351
}
348352

353+
get isClosed() {
354+
return this.closed;
355+
}
356+
349357
/**
350358
* Add jitter to prevent thundering herd problems in high-concurrency environments
351359
* @param baseInterval The base interval in milliseconds
@@ -918,6 +926,10 @@ class _Worker<T = any> extends TypedEventEmitter<WorkerEvents<T>> {
918926
* @param gracefulTimeoutMs Maximum time to wait for current job to finish (default: 30 seconds)
919927
*/
920928
async close(gracefulTimeoutMs = 30_000): Promise<void> {
929+
// Give some time if we just received a job
930+
// Otherwise jobsInProgress will be 0 and we will exit immediately
931+
await this.delay(100);
932+
921933
this.stopping = true;
922934

923935
if (this.cleanupTimer) {
@@ -1062,12 +1074,18 @@ class _Worker<T = any> extends TypedEventEmitter<WorkerEvents<T>> {
10621074
*
10631075
* How it works:
10641076
* 1. Worker picks up first job and holds it in memory
1065-
* 2. Waits for the grace period for new jobs to arrive
1066-
* 3. When a new job arrives, reset the timer and hold ALL jobs for another full grace period
1077+
* 2. Waits for the grace period to allow concurrent enqueue operations to finish
1078+
* 3. When new jobs are detected, reset the timer (with decay) and wait again
10671079
* 4. Repeat until no new jobs arrive for the full grace period
10681080
* 5. Process all collected jobs sorted by orderMs
10691081
*
1070-
* This ensures jobs arriving close together are batched and processed in correct order.
1082+
* This solves the race condition where jobs are enqueued within 1-2ms:
1083+
* - Worker reserves job 1 while jobs 2-4 are still being written to Redis
1084+
* - By always waiting the grace period, we give concurrent writes time to complete
1085+
* - Then we collect all jobs that finished enqueueing during our wait
1086+
*
1087+
* NOTE: The grace window is measured from when WE picked up the job (Date.now()),
1088+
* NOT from when the job was enqueued. This is critical for handling concurrent enqueues.
10711089
*/
10721090
private async collectJobsWithGrace(
10731091
firstJob: ReservedJob<T>,
@@ -1078,60 +1096,94 @@ class _Worker<T = any> extends TypedEventEmitter<WorkerEvents<T>> {
10781096
return [firstJob];
10791097
}
10801098

1099+
const groupId = firstJob.groupId;
10811100
const collected: ReservedJob<T>[] = [firstJob];
1082-
const initialCount = await this.q.getGroupJobCount(firstJob.groupId);
1083-
let lastSeenCount = initialCount;
1084-
let lastJobArrivalTime = Date.now(); // Reset every time a new job arrives
1085-
const startTime = Date.now();
1101+
const now = Date.now();
1102+
1103+
// Check if we're already in a collection window for this group
1104+
let collectionStartTime = this.groupCollectionStartTimes.get(groupId);
1105+
1106+
if (!collectionStartTime) {
1107+
// First job from this group - start tracking the collection window
1108+
collectionStartTime = now;
1109+
this.groupCollectionStartTimes.set(groupId, collectionStartTime);
1110+
1111+
this.logger.debug(
1112+
`Started collection window for group ${groupId} (${initialGraceMs}ms grace period)`,
1113+
);
1114+
} else {
1115+
// We're continuing an existing collection for this group
1116+
// Check if we've already waited long enough
1117+
const elapsedSinceStart = now - collectionStartTime;
1118+
if (elapsedSinceStart >= initialGraceMs) {
1119+
this.logger.debug(
1120+
`Collection window for group ${groupId} already expired (${elapsedSinceStart}ms elapsed), processing immediately`,
1121+
);
1122+
return [firstJob];
1123+
}
1124+
1125+
this.logger.debug(
1126+
`Continuing collection for group ${groupId} (${elapsedSinceStart}ms elapsed)`,
1127+
);
1128+
}
1129+
1130+
let lastSeenCount = 0;
1131+
let lastJobArrivalTime = now; // Reset every time we detect new jobs
10861132
let currentGraceMs = initialGraceMs; // Decaying grace window
10871133
const minGraceMs = 20; // Minimum wait time
10881134
const decayFactor = this.q.orderingGracePeriodDecay;
10891135

1090-
this.logger.debug(
1091-
`Grace period collection started for group ${firstJob.groupId} (initial count: ${initialCount}, ${initialGraceMs}ms window, decay: ${decayFactor})`,
1092-
);
1136+
// ALWAYS wait the grace period when we first pick up a job
1137+
// This gives concurrent enqueue operations time to finish writing to Redis
1138+
// The goal is to collect ALL jobs that exist at the END of the grace period
10931139

10941140
// Keep checking for NEW jobs until grace period expires with no new arrivals
10951141
while (Date.now() - lastJobArrivalTime < currentGraceMs) {
10961142
await this.delay(10); // Check every 10ms
10971143

1098-
const currentCount = await this.q.getGroupJobCount(firstJob.groupId);
1144+
const currentCount = await this.q.getGroupJobCount(groupId);
10991145

11001146
if (currentCount > lastSeenCount) {
11011147
// New jobs arrived! Reset the grace period timer with decay
11021148
const newJobsCount = currentCount - lastSeenCount;
11031149
lastSeenCount = currentCount;
1104-
lastJobArrivalTime = Date.now(); // RESET timer
1150+
lastJobArrivalTime = Date.now(); // RESET timer to when we detected new jobs
11051151

11061152
// Apply decay: reduce the grace window for the next iteration
11071153
currentGraceMs = Math.max(minGraceMs, currentGraceMs * decayFactor);
11081154

11091155
this.logger.debug(
1110-
`${newJobsCount} new job(s) detected in group ${firstJob.groupId}, resetting grace period to ${Math.round(currentGraceMs)}ms (${Math.round((currentGraceMs / initialGraceMs) * 100)}% of original)`,
1156+
`${newJobsCount} new job(s) detected in group ${groupId}, resetting grace period to ${Math.round(currentGraceMs)}ms (${Math.round((currentGraceMs / initialGraceMs) * 100)}% of original)`,
11111157
);
11121158
}
11131159

11141160
// Safety: don't wait forever (max multiplier from queue config)
11151161
const maxWaitMs = initialGraceMs * this.q.orderingMaxWaitMultiplier;
1116-
if (Date.now() - startTime > maxWaitMs) {
1162+
const totalWaitTime = Date.now() - collectionStartTime;
1163+
if (totalWaitTime > maxWaitMs) {
11171164
this.logger.warn(
1118-
`Grace period exceeded ${this.q.orderingMaxWaitMultiplier}x limit (${maxWaitMs}ms) for group ${firstJob.groupId}, proceeding`,
1165+
`Grace period exceeded ${this.q.orderingMaxWaitMultiplier}x limit (${maxWaitMs}ms) for group ${groupId} (waited ${totalWaitTime}ms), proceeding`,
11191166
);
11201167
break;
11211168
}
11221169
}
11231170

1124-
// Only collect jobs we detected DURING the grace period
1125-
// lastSeenCount is the count at the last detection, which happened within the grace window
1126-
const jobsArrivedDuringGrace = Math.max(0, lastSeenCount - initialCount);
1171+
// Collect ALL remaining jobs in the group (up to configured batch limit)
1172+
// These are the jobs that were there when the grace period ended
1173+
const finalCount = await this.q.getGroupJobCount(groupId);
1174+
const maxBatchSize = this.q.orderingMaxBatchSize;
1175+
const jobsToCollect = Math.min(finalCount, maxBatchSize);
1176+
1177+
this.logger.debug(
1178+
`Grace period complete for group ${groupId}, collecting ${jobsToCollect} of ${finalCount} remaining jobs (max batch: ${maxBatchSize})`,
1179+
);
11271180

1128-
// Only collect jobs that arrived DURING the grace period
1129-
// Don't collect ALL jobs - that would break the FIFO guarantee
1130-
for (let i = 0; i < jobsArrivedDuringGrace && i < 20; i++) {
1181+
// Collect remaining jobs from the group (up to max batch size)
1182+
for (let i = 0; i < jobsToCollect; i++) {
11311183
try {
11321184
// Reserve next job from this group, passing first job's ID to bypass lock
11331185
const nextJob = await this.reserveNextFromSameGroup(
1134-
firstJob.groupId,
1186+
groupId,
11351187
firstJob.id,
11361188
);
11371189
if (!nextJob) break;
@@ -1155,7 +1207,7 @@ class _Worker<T = any> extends TypedEventEmitter<WorkerEvents<T>> {
11551207

11561208
if (collected.length > 1) {
11571209
this.logger.info(
1158-
`Collected ${collected.length} jobs from group ${firstJob.groupId} during ${Date.now() - startTime}ms grace period`,
1210+
`Collected ${collected.length} jobs from group ${groupId} during ${Date.now() - now}ms grace period`,
11591211
{
11601212
unsorted: oldCollected.map((job) => job.id),
11611213
sorted: collected.map((job, index) => ({
@@ -1169,6 +1221,10 @@ class _Worker<T = any> extends TypedEventEmitter<WorkerEvents<T>> {
11691221
);
11701222
}
11711223

1224+
// Clear the tracking for this group after we've collected the batch
1225+
// This allows the next batch to start fresh
1226+
this.groupCollectionStartTimes.delete(groupId);
1227+
11721228
return collected;
11731229
}
11741230

test/queue.graceful-shutdown.test.ts

Lines changed: 31 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -254,7 +254,7 @@ describe('Graceful Shutdown Tests', () => {
254254
const elapsed = Date.now() - startTime;
255255

256256
expect(elapsed).toBeGreaterThan(190);
257-
expect(elapsed).toBeLessThan(500); // Increased tolerance for proper run loop shutdown
257+
expect(elapsed).toBeLessThan(600);
258258
expect(sawGracefulTimeout).toBe(true);
259259

260260
shouldStop = true; // Allow the handler to finish
@@ -481,4 +481,34 @@ describe('Graceful Shutdown Tests', () => {
481481

482482
await redis.quit();
483483
}, 10000); // 10 second timeout for the test
484+
485+
it('should shutdown gracefully when we have orderingWindowMs + orderingMethod = "in-memory"', async () => {
486+
const redis = new Redis(REDIS_URL);
487+
const queue = new Queue({
488+
redis,
489+
logger: true,
490+
namespace: `${namespace}:in-memory`,
491+
orderingMethod: 'in-memory',
492+
orderingWindowMs: 1000,
493+
});
494+
let isCompleted = false;
495+
const worker = new Worker({
496+
queue: queue,
497+
logger: true,
498+
handler: async (job) => {
499+
await new Promise((resolve) => setTimeout(resolve, 1000));
500+
isCompleted = true;
501+
},
502+
});
503+
await queue.add({ groupId: 'test-group', data: { id: 1 } });
504+
worker.on('completed', (job) => {
505+
console.log('Completed', job.id);
506+
});
507+
worker.run();
508+
await worker.close(2000);
509+
expect(isCompleted).toBe(true);
510+
expect(worker.isProcessing()).toBe(false);
511+
expect(worker.getCurrentJob()).toBe(null);
512+
expect(worker.isClosed).toBe(true);
513+
});
484514
});

test/queue.ordering-grace.test.ts

Lines changed: 58 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -251,6 +251,64 @@ describe('Ordering Grace Period (orderingGraceMs)', () => {
251251

252252
await worker.close();
253253
});
254+
255+
it('should collect jobs added within 1-2ms (race condition test)', async () => {
256+
const q = new Queue({
257+
redis,
258+
namespace: `${namespace}:race-condition`,
259+
jobTimeoutMs: 5000,
260+
orderingMethod: 'in-memory',
261+
orderingWindowMs: 100, // Grace period to allow concurrent adds to complete
262+
orderingGracePeriodDecay: 0.9,
263+
orderingMaxWaitMultiplier: 8,
264+
logger: true, // Disable verbose logging
265+
});
266+
267+
const collectCalls: number[] = []; // Track how many jobs collected in each call
268+
const processed: number[] = [];
269+
270+
const worker = new Worker<{ seq: number }>({
271+
queue: q,
272+
concurrency: 6,
273+
logger: true,
274+
handler: async (job) => {
275+
processed.push(job.data.seq);
276+
// Don't do atomic completion - process jobs slower to avoid
277+
// the next job being grabbed before we can see the collection
278+
await wait(50); // Longer than grace period to ensure we see batching
279+
},
280+
});
281+
worker.run();
282+
283+
const baseTime = Date.now();
284+
285+
// Add all 4 jobs concurrently (within ~1ms)
286+
// This simulates the real-world scenario where multiple API calls
287+
// trigger job creation almost simultaneously
288+
console.log(
289+
'Adding jobs within 1ms window (simulating concurrent API calls)...',
290+
);
291+
await q.add({
292+
groupId: 'device-1',
293+
data: { seq: 3 },
294+
orderMs: baseTime + 2,
295+
});
296+
await wait(50);
297+
await Promise.all([
298+
q.add({ groupId: 'device-1', data: { seq: 2 }, orderMs: baseTime + 1 }),
299+
q.add({ groupId: 'device-1', data: { seq: 1 }, orderMs: baseTime }),
300+
q.add({ groupId: 'device-1', data: { seq: 4 }, orderMs: baseTime + 3 }),
301+
]);
302+
console.log('All 4 jobs added');
303+
304+
await q.waitForEmpty();
305+
await wait(100);
306+
307+
// All jobs should be processed in order
308+
expect(processed).toEqual([1, 2, 3, 4]);
309+
310+
await worker.close();
311+
});
254312
});
255313

256314
async function wait(ms: number) {

test/queue.stress.test.ts

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -217,7 +217,7 @@ describe('Stress and Performance Degradation Tests', () => {
217217
// In production, worker churn would be much less aggressive.
218218
expect(duplicateRate).toBeLessThan(0.1); // Less than 10% duplicates
219219

220-
await redis.quit();
220+
// await redis.quit();
221221
}, 30000);
222222

223223
it('should handle burst traffic patterns', async () => {

0 commit comments

Comments
 (0)