Skip to content

Commit 94b33d2

Browse files
authored
perf(outbox): resume each retention batch where the previous run's batch ended (#9446)
* 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. * fix(outbox): start a pass from the oldest row when its stored cursor names no real time A cursor whose JSON parsed but whose creation time was not a calendar time reached the batch's ::timestamp cast and failed the run, which stopped every later type's prune until the cursor expired. The cursor's creation time is now checked as PostgreSQL's ISO text with a calendar round trip, so such a cursor is dropped like an unreadable one and the pass starts from the oldest row.
1 parent 8948b54 commit 94b33d2

2 files changed

Lines changed: 277 additions & 10 deletions

File tree

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

Lines changed: 134 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,113 @@ 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+
[
264+
'the cursor names no real creation time',
265+
async (client: Redis) => {
266+
await client.set(
267+
`outbox-prune-cursor:v1:${RECOVER}`,
268+
JSON.stringify({
269+
createdAt: '2026-02-30 00:00:00',
270+
id: 'row:1',
271+
passStartedAt: Date.now(),
272+
})
273+
)
274+
},
275+
0,
276+
],
277+
])('starts again from the oldest row when %s', async (_, corrupt, laterMs) => {
278+
const client = resumeThroughRedis()
279+
await seedFullBatchPlusOne(RECOVER)
280+
const late = await seedLateCompletion(RECOVER)
281+
282+
expect(await pruneCompletedOutboxEvents()).toBe(OUTBOX_PRUNE_BATCH_SIZE)
283+
await late.complete()
284+
await corrupt(client)
285+
286+
expect(await pruneCompletedOutboxEvents(new Date(Date.now() + laterMs))).toBe(2)
287+
expect(await remainingIds()).toEqual(new Set())
288+
})
289+
})
157290
})

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

Lines changed: 143 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,134 @@ 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+
* `created_at::text` under PostgreSQL's ISO date style, to the microsecond. A stored value that is
72+
* not a real calendar time fails the round trip here instead of the batch's `::timestamp` cast.
73+
*/
74+
const postgresTimestampSchema = z.string().refine((value) => {
75+
if (!/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}(\.\d{1,6})?$/.test(value)) return false
76+
const seconds = value.slice(0, 19).replace(' ', 'T')
77+
const parsed = new Date(`${seconds}Z`)
78+
return !Number.isNaN(parsed.getTime()) && parsed.toISOString().startsWith(seconds)
79+
})
80+
81+
/**
82+
* Where a type's pass resumes: the creation time, as PostgreSQL prints it so no microseconds are
83+
* lost, and id of the last row the previous batch deleted.
84+
*/
85+
const resumePointSchema = z.object({ createdAt: postgresTimestampSchema, id: z.string() })
86+
const pruneCursorSchema = resumePointSchema.extend({ passStartedAt: z.number() })
87+
88+
type ResumePoint = z.infer<typeof resumePointSchema>
89+
type PruneCursor = z.infer<typeof pruneCursorSchema>
90+
91+
const pruneCursorKey = (eventType: string) => `outbox-prune-cursor:v1:${eventType}`
92+
93+
/**
94+
* Each type's cursor from the pass in progress, or null when Redis is unavailable. A missing,
95+
* unreadable or expired cursor starts that type's pass from the oldest row.
96+
*/
97+
async function readPruneCursors(now: Date): Promise<Map<string, PruneCursor> | null> {
98+
const redis = getRedisClient()
99+
if (!redis) return null
100+
try {
101+
const stored = await redis.mget(...PRUNABLE_OUTBOX_EVENT_TYPES.map(pruneCursorKey))
102+
const cursors = new Map<string, PruneCursor>()
103+
PRUNABLE_OUTBOX_EVENT_TYPES.forEach((eventType, index) => {
104+
const cursor = parsePruneCursor(stored[index])
105+
if (cursor && now.getTime() - cursor.passStartedAt < OUTBOX_PRUNE_PASS_MAX_MS) {
106+
cursors.set(eventType, cursor)
107+
}
108+
})
109+
return cursors
110+
} catch (error) {
111+
logger.warn('Failed to read outbox prune cursors; pruning from the oldest rows', {
112+
error: getErrorMessage(error),
113+
})
114+
return null
115+
}
116+
}
117+
118+
function parsePruneCursor(stored: string | null): PruneCursor | null {
119+
if (!stored) return null
120+
try {
121+
const parsed = pruneCursorSchema.safeParse(JSON.parse(stored))
122+
return parsed.success ? parsed.data : null
123+
} catch {
124+
return null
125+
}
126+
}
127+
128+
/** Stores each type's next cursor, or clears it when that type's pass is over. */
129+
async function savePruneCursors(next: ReadonlyMap<string, PruneCursor | null>): Promise<void> {
130+
const redis = getRedisClient()
131+
if (!redis || next.size === 0) return
132+
try {
133+
const pipeline = redis.pipeline()
134+
for (const [eventType, cursor] of next) {
135+
if (cursor) {
136+
pipeline.set(
137+
pruneCursorKey(eventType),
138+
JSON.stringify(cursor),
139+
'EX',
140+
OUTBOX_PRUNE_PASS_MAX_MS / 1000
141+
)
142+
} else {
143+
pipeline.del(pruneCursorKey(eventType))
144+
}
145+
}
146+
await pipeline.exec()
147+
} catch (error) {
148+
logger.warn('Failed to save outbox prune cursors', { error: getErrorMessage(error) })
149+
}
150+
}
151+
152+
/**
153+
* Deletes the oldest batch after `resumeAfter` in (creation time, id) order. Returns the last
154+
* deleted row when the batch was full, and null when it reached the cutoff and the pass is over.
155+
*/
156+
async function pruneCompletedBatch(
157+
eventType: string,
158+
cutoff: Date,
159+
resumeAfter: ResumePoint | undefined
160+
): Promise<{ deleted: number; resumeAfter: ResumePoint | null }> {
61161
return db.transaction(async (tx) => {
62162
await tx.execute(sql`SELECT set_config('statement_timeout', '10000', true)`)
63-
const expired = tx
64-
.select({ id: outboxEvent.id })
163+
const expired = await tx
164+
.select({ id: outboxEvent.id, createdAt: sql<string>`${outboxEvent.createdAt}::text` })
65165
.from(outboxEvent)
66166
.where(
67167
and(
68168
eq(outboxEvent.eventType, eventType),
69169
lt(outboxEvent.createdAt, cutoff),
70-
eq(outboxEvent.status, 'completed')
170+
eq(outboxEvent.status, 'completed'),
171+
resumeAfter
172+
? sql`(${outboxEvent.createdAt}, ${outboxEvent.id}) > (${resumeAfter.createdAt}::timestamp, ${resumeAfter.id})`
173+
: undefined
71174
)
72175
)
73-
.orderBy(asc(outboxEvent.createdAt))
176+
.orderBy(asc(outboxEvent.createdAt), asc(outboxEvent.id))
74177
.limit(OUTBOX_PRUNE_BATCH_SIZE)
75178
.for('update', { skipLocked: true })
76-
const deleted = await tx.delete(outboxEvent).where(inArray(outboxEvent.id, expired))
77-
return deleted.count
179+
const last = expired.at(-1)
180+
if (!last) return { deleted: 0, resumeAfter: null }
181+
const deleted = await tx.delete(outboxEvent).where(
182+
inArray(
183+
outboxEvent.id,
184+
expired.map((row) => row.id)
185+
)
186+
)
187+
return {
188+
deleted: deleted.count,
189+
resumeAfter: expired.length === OUTBOX_PRUNE_BATCH_SIZE ? last : null,
190+
}
78191
})
79192
}
80193

@@ -83,12 +196,33 @@ async function pruneCompletedBatch(eventType: string, cutoff: Date): Promise<num
83196
* retention window, through the type/creation index. One bounded batch per run keeps a large
84197
* backlog from turning into a burst of deletes; overlapping runs skip each other's locked rows.
85198
* Pending, processing and dead-letter rows are never deleted.
199+
*
200+
* Each batch resumes after the last row the previous run's batch deleted, kept in Redis. Starting
201+
* again from the oldest row would walk every index entry the earlier batches deleted that vacuum
202+
* has not yet removed, which grows with the backlog being drained. A pass starts over from the
203+
* oldest row once a batch comes up short of the cutoff or the pass is older than an hour; without
204+
* Redis every batch starts from the oldest row.
86205
*/
87206
export async function pruneCompletedOutboxEvents(now = new Date()): Promise<number> {
88207
const cutoff = new Date(now.getTime() - COMPLETED_OUTBOX_RETENTION_MS)
208+
const cursors = await readPruneCursors(now)
209+
const nextCursors = new Map<string, PruneCursor | null>()
89210
let pruned = 0
90-
for (const eventType of PRUNABLE_OUTBOX_EVENT_TYPES) {
91-
pruned += await pruneCompletedBatch(eventType, cutoff)
211+
try {
212+
for (const eventType of PRUNABLE_OUTBOX_EVENT_TYPES) {
213+
const cursor = cursors?.get(eventType)
214+
const batch = await pruneCompletedBatch(eventType, cutoff, cursor)
215+
pruned += batch.deleted
216+
nextCursors.set(
217+
eventType,
218+
batch.resumeAfter && {
219+
...batch.resumeAfter,
220+
passStartedAt: cursor?.passStartedAt ?? now.getTime(),
221+
}
222+
)
223+
}
224+
} finally {
225+
if (cursors) await savePruneCursors(nextCursors)
92226
}
93227
if (pruned > 0) logger.info('Pruned completed outbox events', { pruned })
94228
return pruned

0 commit comments

Comments
 (0)