Skip to content

Commit 2a49e97

Browse files
authored
fix: enforce minimum iteration delay in df.loop() to prevent busy-spin (#141)
The loop iteration's actual elapsed time is observed; if it falls below LOOP_MIN_ITER_DURATION (1s), a compensating timer is scheduled before continue_as_new. Also add an E2E regression test that verifies a df.sleep(0) loop completes at most 15 iterations in ~3 seconds (would be hundreds without the fix).
1 parent d31e6b7 commit 2a49e97

2 files changed

Lines changed: 102 additions & 0 deletions

File tree

src/orchestrations/execute_function_graph.rs

Lines changed: 31 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -418,6 +418,12 @@ async fn execute_wait_schedule_node(
418418
/// Sentinel key used to signal a break from within a loop
419419
const BREAK_SENTINEL: &str = "__break__";
420420

421+
/// Minimum wall-clock duration that every loop iteration must take before
422+
/// `continue_as_new` is called. If the body (plus any while-condition
423+
/// evaluation) completes faster than this, a compensating timer makes up the
424+
/// deficit so an empty-bodied loop can't busy-spin via continue_as_new.
425+
const LOOP_MIN_ITER_DURATION: Duration = Duration::from_secs(1);
426+
421427
/// Check if a result contains a break signal
422428
fn is_break_signal(result: &str) -> bool {
423429
serde_json::from_str::<serde_json::Value>(result)
@@ -451,6 +457,11 @@ async fn execute_loop_node(
451457
.as_ref()
452458
.ok_or_else(|| format!("LOOP node {node_id} has no body"))?;
453459

460+
// Capture the iteration start time so we can rate-limit `continue_as_new`
461+
// below. `utc_now()` is duroxide's deterministic clock (recorded in
462+
// history and replayed verbatim), so this remains replay-safe.
463+
let iter_started = ctx.utc_now().await.ok();
464+
454465
ctx.trace_info("Executing loop iteration");
455466
let body_result = Box::pin(execute_function_node_with_vars(
456467
ctx, graph, body_id, results, exec_ctx,
@@ -495,6 +506,26 @@ async fn execute_loop_node(
495506
}
496507

497508
ctx.trace_info("Continuing as new for next loop iteration");
509+
510+
// Enforce a minimum per-iteration wall-clock duration to prevent
511+
// busy-looping (e.g. `df.loop(df.sleep(0))`). Compute the elapsed time
512+
// from the deterministic clock; if the iteration finished faster than
513+
// LOOP_MIN_ITER_DURATION, schedule a timer for the deficit so the next
514+
// continue_as_new is gated by at least that much real-clock time.
515+
if let Some(started) = iter_started {
516+
if let Ok(now) = ctx.utc_now().await {
517+
let elapsed = now.duration_since(started).unwrap_or(Duration::ZERO);
518+
if elapsed < LOOP_MIN_ITER_DURATION {
519+
let deficit = LOOP_MIN_ITER_DURATION - elapsed;
520+
ctx.trace_info(format!(
521+
"Loop iteration took {elapsed:?} (< {LOOP_MIN_ITER_DURATION:?}); \
522+
adding {deficit:?} rate-limit delay"
523+
));
524+
ctx.schedule_timer(deficit).await;
525+
}
526+
}
527+
}
528+
498529
// Preserve vars in continue_as_new input
499530
let new_input = FunctionInput {
500531
instance_id: graph.instance_id.clone(),

tests/e2e/sql/03_loops.sql

Lines changed: 71 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -254,5 +254,76 @@ END $$;
254254
DROP TABLE _test_running_state;
255255
DROP TABLE test_running_status_log;
256256

257+
-- === Test: zero_sleep_loop_rate_limited ===
258+
-- Regression test for: df.loop(df.sleep(0)) busy-spin (issue #13).
259+
-- A loop whose body contains only a zero-duration sleep must NOT spin at full
260+
-- CPU speed. With the 1-second minimum-iteration delay enforced by the loop
261+
-- handler, at most a handful of iterations should complete in 3 seconds.
262+
263+
DROP TABLE IF EXISTS test_zero_sleep_log;
264+
CREATE TABLE test_zero_sleep_log (id SERIAL, ts TIMESTAMP DEFAULT now());
265+
266+
CREATE TEMP TABLE _test_zero_sleep_state AS
267+
SELECT df.start(
268+
df.loop(
269+
'INSERT INTO test_zero_sleep_log DEFAULT VALUES'
270+
~> df.sleep(0)
271+
),
272+
'test-loop-zero-sleep'
273+
) AS instance_id;
274+
275+
DO $$
276+
DECLARE
277+
v_instance_id TEXT;
278+
v_status TEXT;
279+
v_cnt INT;
280+
attempts INT := 0;
281+
BEGIN
282+
SELECT instance_id INTO v_instance_id FROM _test_zero_sleep_state;
283+
RAISE NOTICE 'Test zero_sleep_loop_rate_limited: instance %', v_instance_id;
284+
285+
-- Wait until at least 1 iteration has run so the loop is clearly started.
286+
LOOP
287+
SELECT COUNT(*) INTO v_cnt FROM test_zero_sleep_log;
288+
EXIT WHEN v_cnt >= 1 OR attempts > 100;
289+
PERFORM pg_sleep(0.1);
290+
attempts := attempts + 1;
291+
END LOOP;
292+
293+
IF v_cnt < 1 THEN
294+
RAISE EXCEPTION 'TEST FAILED [zero-sleep]: loop body never executed';
295+
END IF;
296+
297+
-- Confirm the loop is still running (not failed/errored after the first iteration).
298+
SELECT s INTO v_status FROM df.status(v_instance_id) s;
299+
IF lower(v_status) != 'running' THEN
300+
RAISE EXCEPTION 'TEST FAILED [zero-sleep]: expected running before observation window, got %', v_status;
301+
END IF;
302+
303+
-- Let it run for ~3 more seconds and count iterations.
304+
PERFORM pg_sleep(3);
305+
SELECT COUNT(*) INTO v_cnt FROM test_zero_sleep_log;
306+
307+
-- Lower bound: the loop must have made meaningful progress.
308+
IF v_cnt < 2 THEN
309+
RAISE EXCEPTION 'TEST FAILED [zero-sleep]: only % iterations in ~3s; rate-limit may be too aggressive', v_cnt;
310+
END IF;
311+
312+
-- With a 1-second minimum delay per continue_as_new, the loop cannot
313+
-- complete more than ~4 iterations in 3 seconds (generous upper bound of
314+
-- 15 to accommodate slow CI environments). Without the fix it would run
315+
-- hundreds of times in the same window.
316+
IF v_cnt > 15 THEN
317+
RAISE EXCEPTION 'TEST FAILED [zero-sleep]: % iterations in ~3s (expected <= 15); minimum rate-limit may not be working', v_cnt;
318+
END IF;
319+
320+
RAISE NOTICE 'PASSED: zero_sleep_loop_rate_limited - % iterations in ~3s (within expected range)', v_cnt;
321+
322+
PERFORM df.cancel(v_instance_id, 'Test complete');
323+
END $$;
324+
325+
DROP TABLE _test_zero_sleep_state;
326+
DROP TABLE test_zero_sleep_log;
327+
257328
RESET SESSION AUTHORIZATION;
258329
SELECT 'TEST PASSED' AS result;

0 commit comments

Comments
 (0)