clockworklabs / clockworklabs/SpacetimeDB
Repeated reducer execution seems to be delayed by few `ms`
@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:
- 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,
});
}
- 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
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Assessment
This issue has not been assessed yet.