Skip to content

Commit b186c33

Browse files
committed
perf(outbox): resume each retention batch where the previous run's batch ended
The completed-event prune deletes one oldest-first batch per type per run. Every batch started its scan of outbox_event_type_created_idx at the oldest row of its type, and the rows earlier batches deleted stay in that index until vacuum removes them, so while a large backlog drains each batch first walks everything deleted since the last vacuum. That walk grows with each run: on a read replica during a large drain it took about 0.6s before the first live row, and a batch can reach the 10s statement timeout. Each batch now resumes after the (created_at, id) of the last row the previous run's batch deleted, the same shape as the idempotency sweep's resume. Batches are ordered by (created_at, id) so ties on created_at split exactly, the cursor keeps PostgreSQL's microsecond text form, and the row comparison becomes a created_at >= bound on the index, with the full comparison as a filter. Resuming from a cursor, the same batch took about 20ms. The prune runs once per processor run, so the cursor has to outlive the run; it is kept in Redis as a hint, one MGET before the batches and one pipeline after. A row the pass went by before it completed, or while an overlapping run held its lock, is covered by the next pass: the cursor is cleared when a batch comes up short of the cutoff, and a pass older than an hour starts over from the oldest row. Without Redis, or with an unreadable cursor, a batch starts from the oldest row as before. Batch size, timeout, cadence and which rows are eligible are unchanged. Autopsy: the retention suite asserted which rows each run deleted, which a scan from the oldest row gets right, so nothing observed where a batch started. The new Redis cases complete a row behind the cursor between runs: resuming leaves it for the next pass and the old scan takes it at once, so the first case fails on the previous code. The others split one creation time across batches with pending rows mixed in, and restart a pass that is over an hour old or whose cursor is unreadable.
1 parent 467236e commit b186c33

2 files changed

Lines changed: 252 additions & 10 deletions

File tree

‎apps/sim/lib/core/outbox/retention.integration.ts‎

Lines changed: 120 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,18 +1,21 @@
11
/** Real PostgreSQL retention removes only finished events that nothing reads again. */
22

33
import { outboxEvent } from '@sim/db/schema'
4-
import { readTestDatabaseUrl } from '@sim/db/testing/test-infrastructure'
4+
import { readTestDatabaseUrl, readTestRedisUrl } from '@sim/db/testing/test-infrastructure'
55
import { withUtcTimestamps } from '@sim/db/timestamps'
6+
import { redisConfigMock, redisConfigMockFns } from '@sim/testing/mocks/redis-config.mock'
67
import { storageServiceMock, storageServiceMockFns } from '@sim/testing/mocks/storage-service.mock'
78
import { generateId } from '@sim/utils/id'
89
import { sql } from 'drizzle-orm'
910
import { drizzle, type PostgresJsDatabase } from 'drizzle-orm/postgres-js'
11+
import Redis from 'ioredis'
1012
import postgres from 'postgres'
1113
import { afterAll, afterEach, beforeAll, describe, expect, it, vi } from 'vitest'
1214

1315
const database = vi.hoisted(() => ({ current: undefined as PostgresJsDatabase | undefined }))
1416

1517
vi.mock('@/lib/uploads/core/storage-service', () => storageServiceMock)
18+
vi.mock('@/lib/core/config/redis', () => redisConfigMock)
1619

1720
vi.mock('@sim/db', () => ({
1821
get db() {
@@ -24,6 +27,7 @@ vi.mock('@sim/db', () => ({
2427
import {
2528
COMPLETED_OUTBOX_RETENTION_MS,
2629
OUTBOX_PRUNE_BATCH_SIZE,
30+
OUTBOX_PRUNE_PASS_MAX_MS,
2731
pruneCompletedOutboxEvents,
2832
} from '@/lib/core/outbox/retention'
2933
import { writeFramedCheckpoint } from '@/lib/knowledge/documents/processing-checkpoint-store'
@@ -34,6 +38,7 @@ const ADMIN_OPERATION = 'admin.organization-member-operation'
3438
const OCR_CHECKPOINT_EXPIRY = 'knowledge.document.ocr-checkpoint.expire'
3539
const EMBEDDING_CHECKPOINT_EXPIRY = 'knowledge.document.embedding-checkpoint.expire'
3640
const DEPLOYMENT_EFFECT = 'workflow.deployment.sync-active-side-effects'
41+
const redisUrl = readTestRedisUrl()
3742

3843
describe('completed outbox retention in PostgreSQL', () => {
3944
const schemaName = `outbox_retention_${generateId().replaceAll('-', '')}`
@@ -49,14 +54,25 @@ describe('completed outbox retention in PostgreSQL', () => {
4954
)
5055
const testDb = drizzle(connection)
5156
const expired = () => new Date(Date.now() - COMPLETED_OUTBOX_RETENTION_MS - 60_000)
57+
const cursorKeys = [RECOVER, EMBEDDING_CHECKPOINT_EXPIRY].map(
58+
(eventType) => `outbox-prune-cursor:v1:${eventType}`
59+
)
60+
let redis: Redis | undefined
5261

5362
beforeAll(async () => {
5463
await connection`CREATE SCHEMA ${connection(schemaName)}`
5564
await connection`CREATE TABLE outbox_event (LIKE public.outbox_event INCLUDING ALL)`
5665
database.current = testDb
66+
if (redisUrl) {
67+
redis = new Redis(redisUrl, { lazyConnect: true, maxRetriesPerRequest: 0 })
68+
await redis.connect()
69+
await redis.del(...cursorKeys)
70+
}
5771
})
5872

5973
afterEach(async () => {
74+
redisConfigMockFns.mockGetRedisClient.mockReturnValue(null)
75+
await redis?.del(...cursorKeys)
6076
await connection`TRUNCATE outbox_event`
6177
})
6278

@@ -65,10 +81,18 @@ describe('completed outbox retention in PostgreSQL', () => {
6581
await connection`DROP SCHEMA ${connection(schemaName)} CASCADE`
6682
} finally {
6783
await connection.end()
84+
await redis?.quit()
6885
database.current = undefined
6986
}
7087
})
7188

89+
/** Runs the rest of the test with each type's pass resuming through real Redis. */
90+
function resumeThroughRedis(): Redis {
91+
if (!redis) throw new Error('TEST_REDIS_URL is required for the resume cases')
92+
redisConfigMockFns.mockGetRedisClient.mockReturnValue(redis)
93+
return redis
94+
}
95+
7296
async function seed(eventType: string, status: string, createdAt: Date) {
7397
const id = generateId()
7498
await testDb.insert(outboxEvent).values({
@@ -154,4 +178,99 @@ describe('completed outbox retention in PostgreSQL', () => {
154178
const rows = await testDb.select().from(outboxEvent)
155179
expect(rows.map((row) => [row.id, row.status])).toEqual([[gate.id, 'pending']])
156180
})
181+
182+
describe.runIf(Boolean(redisUrl))("resuming each type's pass across runs", () => {
183+
/** One full batch plus one newer row, all completed, a millisecond apart, oldest first. */
184+
async function seedFullBatchPlusOne(eventType: string) {
185+
const newest = expired().toISOString()
186+
await testDb.execute(sql`
187+
INSERT INTO outbox_event (id, event_type, payload, status, available_at, created_at)
188+
SELECT 'row:' || n, ${eventType}, '{}'::json, 'completed',
189+
${newest}::timestamp, ${newest}::timestamp - n * interval '1 millisecond'
190+
FROM generate_series(0, ${OUTBOX_PRUNE_BATCH_SIZE}::integer) AS n
191+
`)
192+
}
193+
194+
/** Pending before any seeded row, then completed once the first batch has gone past it. */
195+
async function seedLateCompletion(eventType: string) {
196+
const id = await seed(
197+
eventType,
198+
'pending',
199+
new Date(expired().getTime() - OUTBOX_PRUNE_BATCH_SIZE - 60_000)
200+
)
201+
return {
202+
id,
203+
complete: () =>
204+
testDb
205+
.update(outboxEvent)
206+
.set({ status: 'completed' })
207+
.where(sql`${outboxEvent.id} = ${id}`),
208+
}
209+
}
210+
211+
it('resumes after the last row the previous batch deleted, and the next pass covers a row it went by', async () => {
212+
resumeThroughRedis()
213+
await seedFullBatchPlusOne(EMBEDDING_CHECKPOINT_EXPIRY)
214+
const late = await seedLateCompletion(EMBEDDING_CHECKPOINT_EXPIRY)
215+
216+
expect(await pruneCompletedOutboxEvents()).toBe(OUTBOX_PRUNE_BATCH_SIZE)
217+
expect(await remainingIds()).toEqual(new Set(['row:0', late.id]))
218+
await late.complete()
219+
220+
/** Starting again from the oldest row would take the late completion in this batch too. */
221+
expect(await pruneCompletedOutboxEvents()).toBe(1)
222+
expect(await remainingIds()).toEqual(new Set([late.id]))
223+
224+
expect(await pruneCompletedOutboxEvents()).toBe(1)
225+
expect(await remainingIds()).toEqual(new Set())
226+
})
227+
228+
it('deletes exactly the eligible rows across batches that split one creation time', async () => {
229+
resumeThroughRedis()
230+
const createdAt = `${expired().toISOString().slice(0, -1)}123Z`
231+
await testDb.execute(sql`
232+
INSERT INTO outbox_event (id, event_type, payload, status, available_at, created_at)
233+
SELECT 'tie:' || lpad(n::text, 5, '0'), ${RECOVER}, '{}'::json,
234+
CASE WHEN n % 100 = 7 THEN 'pending' ELSE 'completed' END,
235+
${createdAt}::timestamp, ${createdAt}::timestamp
236+
FROM generate_series(1, ${OUTBOX_PRUNE_BATCH_SIZE + 500}::integer) AS n
237+
`)
238+
const kept = [
239+
await seed(ADMIN_OPERATION, 'completed', expired()),
240+
await seed(RECOVER, 'completed', new Date(Date.now() - 60_000)),
241+
]
242+
const pendingTies = await testDb
243+
.select({ id: outboxEvent.id })
244+
.from(outboxEvent)
245+
.where(sql`${outboxEvent.status} = 'pending'`)
246+
const completedTies = OUTBOX_PRUNE_BATCH_SIZE + 500 - pendingTies.length
247+
248+
expect(await pruneCompletedOutboxEvents()).toBe(OUTBOX_PRUNE_BATCH_SIZE)
249+
expect(await pruneCompletedOutboxEvents()).toBe(completedTies - OUTBOX_PRUNE_BATCH_SIZE)
250+
expect(await pruneCompletedOutboxEvents()).toBe(0)
251+
expect(await remainingIds()).toEqual(new Set([...kept, ...pendingTies.map((row) => row.id)]))
252+
})
253+
254+
it.each([
255+
['the pass is over its time limit', async () => {}, OUTBOX_PRUNE_PASS_MAX_MS],
256+
[
257+
'the cursor is unreadable',
258+
async (client: Redis) => {
259+
await client.set(`outbox-prune-cursor:v1:${RECOVER}`, '{"createdAt":')
260+
},
261+
0,
262+
],
263+
])('starts again from the oldest row when %s', async (_, corrupt, laterMs) => {
264+
const client = resumeThroughRedis()
265+
await seedFullBatchPlusOne(RECOVER)
266+
const late = await seedLateCompletion(RECOVER)
267+
268+
expect(await pruneCompletedOutboxEvents()).toBe(OUTBOX_PRUNE_BATCH_SIZE)
269+
await late.complete()
270+
await corrupt(client)
271+
272+
expect(await pruneCompletedOutboxEvents(new Date(Date.now() + laterMs))).toBe(2)
273+
expect(await remainingIds()).toEqual(new Set())
274+
})
275+
})
157276
})

‎apps/sim/lib/core/outbox/retention.ts‎

Lines changed: 132 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -1,11 +1,14 @@
11
import { db } from '@sim/db'
22
import { outboxEvent } from '@sim/db/schema'
33
import { createLogger } from '@sim/logger'
4+
import { getErrorMessage } from '@sim/utils/errors'
45
import { and, asc, eq, inArray, lt, sql } from 'drizzle-orm'
6+
import { z } from 'zod'
57
import {
68
CHAT_BACKEND_CLEANUP_EVENT,
79
CHAT_INLINE_IMAGE_CLEANUP_EVENT,
810
} from '@/lib/cleanup/chat-backend-cleanup-event'
11+
import { getRedisClient } from '@/lib/core/config/redis'
912
import {
1013
EMBEDDING_CHECKPOINT_CLEANUP_EVENT,
1114
OCR_CHECKPOINT_CLEANUP_OUTBOX_EVENT,
@@ -57,24 +60,123 @@ const PRUNABLE_OUTBOX_EVENT_TYPES = [
5760
CHAT_INLINE_IMAGE_CLEANUP_EVENT,
5861
] as const
5962

60-
async function pruneCompletedBatch(eventType: string, cutoff: Date): Promise<number> {
63+
/**
64+
* How long one oldest-to-newest pass over a type keeps resuming where the previous run's batch
65+
* ended. The run after that starts again from the oldest row, so a row the pass went by before it
66+
* completed, or while an overlapping run held its lock, is still pruned.
67+
*/
68+
export const OUTBOX_PRUNE_PASS_MAX_MS = 60 * 60_000
69+
70+
/**
71+
* Where a type's pass resumes: the creation time, as PostgreSQL prints it so no microseconds are
72+
* lost, and id of the last row the previous batch deleted.
73+
*/
74+
const resumePointSchema = z.object({ createdAt: z.string(), id: z.string() })
75+
const pruneCursorSchema = resumePointSchema.extend({ passStartedAt: z.number() })
76+
77+
type ResumePoint = z.infer<typeof resumePointSchema>
78+
type PruneCursor = z.infer<typeof pruneCursorSchema>
79+
80+
const pruneCursorKey = (eventType: string) => `outbox-prune-cursor:v1:${eventType}`
81+
82+
/**
83+
* Each type's cursor from the pass in progress, or null when Redis is unavailable. A missing,
84+
* unreadable or expired cursor starts that type's pass from the oldest row.
85+
*/
86+
async function readPruneCursors(now: Date): Promise<Map<string, PruneCursor> | null> {
87+
const redis = getRedisClient()
88+
if (!redis) return null
89+
try {
90+
const stored = await redis.mget(...PRUNABLE_OUTBOX_EVENT_TYPES.map(pruneCursorKey))
91+
const cursors = new Map<string, PruneCursor>()
92+
PRUNABLE_OUTBOX_EVENT_TYPES.forEach((eventType, index) => {
93+
const cursor = parsePruneCursor(stored[index])
94+
if (cursor && now.getTime() - cursor.passStartedAt < OUTBOX_PRUNE_PASS_MAX_MS) {
95+
cursors.set(eventType, cursor)
96+
}
97+
})
98+
return cursors
99+
} catch (error) {
100+
logger.warn('Failed to read outbox prune cursors; pruning from the oldest rows', {
101+
error: getErrorMessage(error),
102+
})
103+
return null
104+
}
105+
}
106+
107+
function parsePruneCursor(stored: string | null): PruneCursor | null {
108+
if (!stored) return null
109+
try {
110+
const parsed = pruneCursorSchema.safeParse(JSON.parse(stored))
111+
return parsed.success ? parsed.data : null
112+
} catch {
113+
return null
114+
}
115+
}
116+
117+
/** Stores each type's next cursor, or clears it when that type's pass is over. */
118+
async function savePruneCursors(next: ReadonlyMap<string, PruneCursor | null>): Promise<void> {
119+
const redis = getRedisClient()
120+
if (!redis || next.size === 0) return
121+
try {
122+
const pipeline = redis.pipeline()
123+
for (const [eventType, cursor] of next) {
124+
if (cursor) {
125+
pipeline.set(
126+
pruneCursorKey(eventType),
127+
JSON.stringify(cursor),
128+
'EX',
129+
OUTBOX_PRUNE_PASS_MAX_MS / 1000
130+
)
131+
} else {
132+
pipeline.del(pruneCursorKey(eventType))
133+
}
134+
}
135+
await pipeline.exec()
136+
} catch (error) {
137+
logger.warn('Failed to save outbox prune cursors', { error: getErrorMessage(error) })
138+
}
139+
}
140+
141+
/**
142+
* Deletes the oldest batch after `resumeAfter` in (creation time, id) order. Returns the last
143+
* deleted row when the batch was full, and null when it reached the cutoff and the pass is over.
144+
*/
145+
async function pruneCompletedBatch(
146+
eventType: string,
147+
cutoff: Date,
148+
resumeAfter: ResumePoint | undefined
149+
): Promise<{ deleted: number; resumeAfter: ResumePoint | null }> {
61150
return db.transaction(async (tx) => {
62151
await tx.execute(sql`SELECT set_config('statement_timeout', '10000', true)`)
63-
const expired = tx
64-
.select({ id: outboxEvent.id })
152+
const expired = await tx
153+
.select({ id: outboxEvent.id, createdAt: sql<string>`${outboxEvent.createdAt}::text` })
65154
.from(outboxEvent)
66155
.where(
67156
and(
68157
eq(outboxEvent.eventType, eventType),
69158
lt(outboxEvent.createdAt, cutoff),
70-
eq(outboxEvent.status, 'completed')
159+
eq(outboxEvent.status, 'completed'),
160+
resumeAfter
161+
? sql`(${outboxEvent.createdAt}, ${outboxEvent.id}) > (${resumeAfter.createdAt}::timestamp, ${resumeAfter.id})`
162+
: undefined
71163
)
72164
)
73-
.orderBy(asc(outboxEvent.createdAt))
165+
.orderBy(asc(outboxEvent.createdAt), asc(outboxEvent.id))
74166
.limit(OUTBOX_PRUNE_BATCH_SIZE)
75167
.for('update', { skipLocked: true })
76-
const deleted = await tx.delete(outboxEvent).where(inArray(outboxEvent.id, expired))
77-
return deleted.count
168+
const last = expired.at(-1)
169+
if (!last) return { deleted: 0, resumeAfter: null }
170+
const deleted = await tx.delete(outboxEvent).where(
171+
inArray(
172+
outboxEvent.id,
173+
expired.map((row) => row.id)
174+
)
175+
)
176+
return {
177+
deleted: deleted.count,
178+
resumeAfter: expired.length === OUTBOX_PRUNE_BATCH_SIZE ? last : null,
179+
}
78180
})
79181
}
80182

@@ -83,12 +185,33 @@ async function pruneCompletedBatch(eventType: string, cutoff: Date): Promise<num
83185
* retention window, through the type/creation index. One bounded batch per run keeps a large
84186
* backlog from turning into a burst of deletes; overlapping runs skip each other's locked rows.
85187
* Pending, processing and dead-letter rows are never deleted.
188+
*
189+
* Each batch resumes after the last row the previous run's batch deleted, kept in Redis. Starting
190+
* again from the oldest row would walk every index entry the earlier batches deleted that vacuum
191+
* has not yet removed, which grows with the backlog being drained. A pass starts over from the
192+
* oldest row once a batch comes up short of the cutoff or the pass is older than an hour; without
193+
* Redis every batch starts from the oldest row.
86194
*/
87195
export async function pruneCompletedOutboxEvents(now = new Date()): Promise<number> {
88196
const cutoff = new Date(now.getTime() - COMPLETED_OUTBOX_RETENTION_MS)
197+
const cursors = await readPruneCursors(now)
198+
const nextCursors = new Map<string, PruneCursor | null>()
89199
let pruned = 0
90-
for (const eventType of PRUNABLE_OUTBOX_EVENT_TYPES) {
91-
pruned += await pruneCompletedBatch(eventType, cutoff)
200+
try {
201+
for (const eventType of PRUNABLE_OUTBOX_EVENT_TYPES) {
202+
const cursor = cursors?.get(eventType)
203+
const batch = await pruneCompletedBatch(eventType, cutoff, cursor)
204+
pruned += batch.deleted
205+
nextCursors.set(
206+
eventType,
207+
batch.resumeAfter && {
208+
...batch.resumeAfter,
209+
passStartedAt: cursor?.passStartedAt ?? now.getTime(),
210+
}
211+
)
212+
}
213+
} finally {
214+
if (cursors) await savePruneCursors(nextCursors)
92215
}
93216
if (pruned > 0) logger.info('Pruned completed outbox events', { pruned })
94217
return pruned

0 commit comments

Comments
 (0)