clockworklabs / clockworklabs/SpacetimeDB

Repeated reducer execution seems to be delayed by few `ms`

Open
#2,648 3 comments 0 reactions 1 assignee View on GitHub

@coolreader18 is already working on this.

Since Apr 20, 2025.

Dominant language
Rust
Stars
25.2k
Forks
1.1k
Avg merge
2d 7h
Merged PRs (30d)
46

Description

Reported on public discord - https://discord.com/channels/1037340874172014652/1363060408285532253.

A few milliseconds of delay can be expected when the module is busy with other tasks, but this should be investigated if the module isn't doing anything else.

Repro steps:
  1. Publish this module
use spacetimedb::{duration, rand::seq::index, reducer, table, ReducerContext, ScheduleAt, Table, TimeDuration, Timestamp};

#[reducer]
fn test_reducer(ctx: &ReducerContext, test: Timer) {
    let now = ctx.timestamp;
    let last_timestamp = ctx.db.timer_tracker().iter().find(|t| t.scheduled_id == test.scheduled_id).map(|t| t.last_timestamp).expect("No last timestamp found");

    let elapsed = now
        .duration_since(last_timestamp)
        .unwrap_or_default()
        .as_millis();

    log::info!("Scheduled Reducer delay: {}ms", elapsed);
    ctx.db.timer_tracker().scheduled_id().update(TimerTracker {
        scheduled_id: test.scheduled_id,
        last_timestamp: ctx.timestamp,
    });
}

#[table(name = timer, public, scheduled(test_reducer))]
pub struct Timer {
    #[primary_key]
    #[auto_inc]
    scheduled_id: u64,
    scheduled_at: ScheduleAt,
}

#[table(name = timer_tracker)]
pub struct TimerTracker {
    #[primary_key]
    pub scheduled_id: u64,
    pub last_timestamp: Timestamp,
}

#[spacetimedb::reducer(init)]
pub fn init(ctx: &ReducerContext) {
    log::info!("Start Invoke");
    let loop_duration: TimeDuration = TimeDuration::from_micros(100_000); //20 ms

    let timer = ctx.db.timer().insert(Timer {
        scheduled_id: 0,
        scheduled_at: loop_duration.into(),
    });


    ctx.db.timer_tracker().insert(TimerTracker {
        scheduled_id: timer.scheduled_id,
        last_timestamp: ctx.timestamp,
    });
}
  1. check module logs, you will find consistenly 2-5ms delay between consecutive occurence of repeated reducer.
Investigation:

After running a scheduled reducer, SchedulerActor uses a follow-up internal transaction to delete row entry or Schedule a reducer again incase of repeated reducer

handle_repeated_reducer gets called in this second transaction, Entry made to queue here will yeild back after dur from "now" instead of last scheduled reducer transaction's time.

Duration here should be adjusted to be reduced by the gap between these two transactons.

Contributor guide

No contributing guide indexed for this repository

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.