Skip to content

Repeated reducer execution seems to be delayed by few ms #2648

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
Shubham8287 opened this issue Apr 20, 2025 · 1 comment
Open

Repeated reducer execution seems to be delayed by few ms #2648

Shubham8287 opened this issue Apr 20, 2025 · 1 comment
Assignees

Comments

@Shubham8287
Copy link
Contributor

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.

@gefjon
Copy link
Contributor

gefjon commented Apr 20, 2025

Reported specifically on Windows. Reporter said that on Maincloud (hosted on Linux), the variance was significantly less pronounced.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants