Skip to content

Commit f25e9c0

Browse files
vicbvicb
committed
debug logs + debug script
1 parent 931a648 commit f25e9c0

2 files changed

Lines changed: 263 additions & 3 deletions

File tree

‎packages/cloudflare/scripts/debug-r2-memory.mjs‎

Lines changed: 253 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,253 @@
1+
/**
2+
* Standalone script to reproduce the OOM issue when populating R2 via unstable_startWorker.
3+
*
4+
* This mirrors the exact pattern used by populateR2IncrementalCache in populate-cache.ts:
5+
* - Starts a local worker with a remote R2 binding via unstable_startWorker
6+
* - Sends concurrent POST requests with FormData (key + value) to the worker
7+
* - The worker writes each entry to R2
8+
*
9+
* Memory usage is logged every 50 completed entries to detect leaks.
10+
*
11+
* Usage:
12+
* pnpm build
13+
* node --expose-gc packages/cloudflare/scripts/debug-r2-memory.mjs [bucket-name]
14+
*
15+
* bucket-name defaults to "cache".
16+
*/
17+
18+
import os from "node:os";
19+
import path from "node:path";
20+
import { fileURLToPath } from "node:url";
21+
22+
import { unstable_startWorker } from "wrangler";
23+
24+
// --- Configuration ---
25+
26+
const TOTAL_ENTRIES = 10_000;
27+
const CONCURRENCY = 1;
28+
const VALUE = "0".repeat(50_000);
29+
const MEMORY_LOG_INTERVAL = 50;
30+
31+
const bucketName = process.argv[2] ?? "cache";
32+
33+
// --- Memory tracking ---
34+
35+
/** @type {Array<{ entries: number; rss: number; heapUsed: number; heapTotal: number; external: number; arrayBuffers: number; sysFree: number }>} */
36+
const memorySnapshots = [];
37+
38+
/**
39+
* Forces a GC cycle (if --expose-gc was used) and records a memory snapshot.
40+
*
41+
* @param {number} entriesCompleted - Number of entries completed so far.
42+
*/
43+
function logMemory(entriesCompleted) {
44+
if (globalThis.gc) {
45+
globalThis.gc();
46+
}
47+
48+
const mem = process.memoryUsage();
49+
const sysFree = os.freemem();
50+
const snapshot = {
51+
entries: entriesCompleted,
52+
rss: Math.round(mem.rss / 1024 / 1024),
53+
heapUsed: Math.round(mem.heapUsed / 1024 / 1024),
54+
heapTotal: Math.round(mem.heapTotal / 1024 / 1024),
55+
external: Math.round(mem.external / 1024 / 1024),
56+
arrayBuffers: Math.round(mem.arrayBuffers / 1024 / 1024),
57+
sysFree: Math.round(sysFree / 1024 / 1024),
58+
};
59+
memorySnapshots.push(snapshot);
60+
61+
console.log(
62+
`[${String(entriesCompleted).padStart(5)}/${TOTAL_ENTRIES}] ` +
63+
`RSS=${String(snapshot.rss).padStart(5)}MB ` +
64+
`heap=${String(snapshot.heapUsed).padStart(5)}MB ` +
65+
`external=${String(snapshot.external).padStart(5)}MB ` +
66+
`arrayBuffers=${String(snapshot.arrayBuffers).padStart(5)}MB ` +
67+
`sysFree=${String(snapshot.sysFree).padStart(6)}MB`
68+
);
69+
}
70+
71+
/**
72+
* Prints a summary table of all memory snapshots.
73+
*/
74+
function printSummary() {
75+
console.log("\n=== Memory Summary ===\n");
76+
const header =
77+
"Entries".padStart(7) +
78+
" " +
79+
"RSS(MB)".padStart(8) +
80+
" " +
81+
"Heap(MB)".padStart(9) +
82+
" " +
83+
"External(MB)".padStart(13) +
84+
" " +
85+
"ArrBuf(MB)".padStart(11) +
86+
" " +
87+
"SysFree(MB)".padStart(12);
88+
console.log(header);
89+
console.log("-".repeat(header.length));
90+
91+
for (const s of memorySnapshots) {
92+
console.log(
93+
String(s.entries).padStart(7) +
94+
" " +
95+
String(s.rss).padStart(8) +
96+
" " +
97+
String(s.heapUsed).padStart(9) +
98+
" " +
99+
String(s.external).padStart(13) +
100+
" " +
101+
String(s.arrayBuffers).padStart(11) +
102+
" " +
103+
String(s.sysFree).padStart(12)
104+
);
105+
}
106+
107+
if (memorySnapshots.length >= 2) {
108+
const first = memorySnapshots[0];
109+
const last = memorySnapshots[memorySnapshots.length - 1];
110+
console.log("-".repeat(header.length));
111+
console.log(
112+
"Delta".padStart(7) +
113+
" " +
114+
String(last.rss - first.rss).padStart(7) +
115+
" " +
116+
String(last.heapUsed - first.heapUsed).padStart(8) +
117+
" " +
118+
String(last.external - first.external).padStart(12) +
119+
" " +
120+
String(last.arrayBuffers - first.arrayBuffers).padStart(10) +
121+
" " +
122+
String(last.sysFree - first.sysFree).padStart(11)
123+
);
124+
}
125+
}
126+
127+
// --- Send a single entry to the worker (mirrors sendEntryToR2Worker) ---
128+
129+
/**
130+
* Sends a single cache entry to the R2 worker via POST /populate with FormData.
131+
*
132+
* @param {string} workerUrl - The URL of the worker's /populate endpoint.
133+
* @param {string} key - The R2 object key.
134+
* @param {string} value - The value to store.
135+
* @throws {Error} If the worker reports a failure.
136+
*/
137+
async function sendEntry(workerUrl, key, value) {
138+
const formData = new FormData();
139+
formData.set("key", key);
140+
formData.set("value", value);
141+
142+
const start = performance.now();
143+
const response = await fetch(workerUrl, {
144+
method: "POST",
145+
body: formData,
146+
});
147+
148+
const result = await response.json();
149+
const elapsed = Math.round(performance.now() - start);
150+
console.log(`[request] ${key} ${elapsed}ms`);
151+
152+
if (!result.success) {
153+
throw new Error(`Failed to write "${key}": ${result.error}`);
154+
}
155+
}
156+
157+
// --- Main ---
158+
159+
async function main() {
160+
console.log(`Bucket: ${bucketName}`);
161+
console.log(`Entries: ${TOTAL_ENTRIES}`);
162+
console.log(`Concurrency: ${CONCURRENCY}`);
163+
console.log(`Value size: ${VALUE.length} chars`);
164+
console.log(
165+
`System RAM: ${Math.round(os.totalmem() / 1024 / 1024)}MB (${Math.round(os.freemem() / 1024 / 1024)}MB free)`
166+
);
167+
console.log(`GC exposed: ${!!globalThis.gc}`);
168+
console.log();
169+
170+
if (!globalThis.gc) {
171+
console.warn("WARNING: --expose-gc not set. Memory snapshots will be less accurate.\n");
172+
}
173+
174+
// Resolve the worker entrypoint (the compiled r2-cache.js)
175+
const currentDir = path.dirname(fileURLToPath(import.meta.url));
176+
const handlerPath = path.join(currentDir, "../dist/cli/workers/r2-cache.js");
177+
178+
console.log(`Starting worker with remote R2 binding (bucket: ${bucketName})...`);
179+
180+
const worker = await unstable_startWorker({
181+
name: "debug-r2-memory",
182+
entrypoint: handlerPath,
183+
compatibilityDate: "2026-01-01",
184+
bindings: {
185+
R2: {
186+
type: "r2_bucket",
187+
bucket_name: bucketName,
188+
remote: true,
189+
},
190+
},
191+
dev: {
192+
server: { port: 0 },
193+
inspector: false,
194+
watch: false,
195+
liveReload: false,
196+
logLevel: "debug",
197+
},
198+
});
199+
200+
try {
201+
await worker.ready;
202+
const baseUrl = await worker.url;
203+
const workerUrl = new URL("/populate", baseUrl).href;
204+
205+
console.log(`Worker ready at ${baseUrl}\n`);
206+
207+
// Log initial memory before sending anything.
208+
logMemory(0);
209+
210+
// Concurrency-limited send loop (mirrors sendEntriesToR2Worker).
211+
let completed = 0;
212+
const pending = new Set();
213+
214+
for (let i = 0; i < TOTAL_ENTRIES; i++) {
215+
// If we've reached the concurrency limit, wait for one to finish.
216+
if (pending.size >= CONCURRENCY) {
217+
await Promise.race(pending);
218+
}
219+
220+
const key = `key-${i}`;
221+
const task = sendEntry(workerUrl, key, VALUE)
222+
.then(() => {
223+
completed++;
224+
225+
// Log memory every MEMORY_LOG_INTERVAL completed entries.
226+
if (completed % MEMORY_LOG_INTERVAL === 0) {
227+
logMemory(completed);
228+
}
229+
})
230+
.finally(() => pending.delete(task));
231+
pending.add(task);
232+
}
233+
234+
// Wait for all remaining in-flight requests.
235+
await Promise.all(pending);
236+
237+
// Final memory snapshot if not already logged at TOTAL_ENTRIES.
238+
if (completed % MEMORY_LOG_INTERVAL !== 0) {
239+
logMemory(completed);
240+
}
241+
242+
console.log(`\nAll ${TOTAL_ENTRIES} entries written successfully.`);
243+
printSummary();
244+
} finally {
245+
await worker.dispose();
246+
console.log("\nWorker disposed.");
247+
}
248+
}
249+
250+
main().catch((err) => {
251+
console.error("Fatal error:", err);
252+
process.exit(1);
253+
});

‎packages/cloudflare/src/cli/workers/r2-cache.ts‎

Lines changed: 10 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -21,8 +21,8 @@ import {
2121

2222
// Maximum number of write attempts before giving up.
2323
const MAX_RETRIES = 5;
24-
// Backoff starts at 200ms and doubles with each retry.
25-
const RETRY_DELAY_MS = 200;
24+
// Base backoff delay.
25+
const RETRY_DELAY_MS = 100;
2626

2727
/**
2828
* Worker fetch handler.
@@ -89,15 +89,22 @@ export default {
8989
// Write the entry to R2 with retry logic.
9090
for (let remainingAttempts = MAX_RETRIES - 1; remainingAttempts >= 0; remainingAttempts--) {
9191
try {
92+
const putStart = Date.now();
9293
await r2.put(key, value);
94+
console.log(`[r2.put] ${key} ${Date.now() - putStart}ms`);
9395
return Response.json({ success: true }, { status: 200 });
9496
} catch (e) {
9597
if (remainingAttempts > 0) {
98+
console.error(
99+
`Write to R2 failed for key "${key}", retrying... (${remainingAttempts} attempts left)`,
100+
e
101+
);
96102
await new Promise((resolve) =>
97-
setTimeout(resolve, RETRY_DELAY_MS * Math.pow(2, MAX_RETRIES - 1 - remainingAttempts))
103+
setTimeout(resolve, RETRY_DELAY_MS * Math.pow(1.2, MAX_RETRIES - 1 - remainingAttempts))
98104
);
99105
continue;
100106
}
107+
console.error(`Failed to write key "${key}" to R2 after ${MAX_RETRIES} attempts:`, e);
101108
const detail = e instanceof Error ? e.message : String(e);
102109
return Response.json(
103110
{

0 commit comments

Comments
 (0)