Skip to content

fix: Always log snapshot succession #2535

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.

Sign up for GitHub

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

Closed
sergerad wants to merge 1 commit into from
Closed

fix: Always log snapshot succession #2535

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
22 changes: 12 additions & 10 deletions crates/store/src/state/view/snapshot.rs
View file
Open in desktop

@Mirko-von-Leipzig Mirko-von-Leipzig Aug 31, 2026

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think this should be logged on info.

I think the way to think about this, is that we shouldn't be logging this at all - this should be information attached to the query span. But the problem is that this is tracked within the object itself, and not within the query so this is difficult to now do correctly.

Could we instead drop this tracking entirely, and instead simply use the RPC queries/handlers durations directly?

@sergerad sergerad Aug 31, 2026 •
edited
Loading

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would like to know how long snapshots are alive for in a manner that takes into account whether a new snapshot has been created or not.

Yea refactoring this into a span field is the right idea. But I might need to impl that as part of #2452 for per-block build metrics.

Original file line number Diff line number Diff line change
Expand Up @@ -12,7 +12,7 @@ use std::sync::atomic::{AtomicUsize, Ordering};
use std::sync::{Arc, OnceLock, Weak};
use std::time::{Duration, Instant};

use miden_node_utils::tracing::{debug, warn};
use miden_node_utils::tracing::{info, warn};
use miden_protocol::block::nullifier_tree::NullifierTree;
use miden_protocol::block::{BlockNumber, Blockchain};
use miden_protocol::crypto::merkle::smt::LargeSmt;
Expand Down Expand Up @@ -123,9 +123,10 @@ impl<T> PublishedGenerations<T> {
/// generation also holds back SQLite history pruning (see [`PublishedGenerations::prune_tip`]).
///
/// Readers are expected to be request-scoped, so a superseded generation should be released well
/// within a block interval. Outliving supersession by more than
/// [`SNAPSHOT_SUPERSEDED_WARN_THRESHOLD`] is logged at warn level; a generation that is never
/// superseded (the latest at shutdown) is released silently regardless of age.
/// within a block interval. Every release is logged at info level with the time held past
/// supersession, so the field is always present for alerting; outliving supersession by more than
/// [`SNAPSHOT_SUPERSEDED_WARN_THRESHOLD`] escalates the event to warn level. A generation that is
/// never superseded (the latest at shutdown) reports zero regardless of age.
Comment on lines +126 to +129

@Mirko-von-Leipzig Mirko-von-Leipzig Aug 31, 2026

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Similarly, I'm not sure why we care about the snapshot being superseded specifically. We care about it being held for a long time in general - whether or not the chain kept going or not is somewhat irrelevant?

@sergerad sergerad Aug 31, 2026 •
edited
Loading

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Because its at least theoretically possible that a snapshot is around for too long because a new snapshot has not been created. Thats why we take into account whether it was succeeded or not.

Granted we should have other alerts that relate to that slowdown - in block building. I would still rather have this duration as a span field.

@sergerad sergerad Aug 31, 2026

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it would be fine to close this PR and integrate a relevant span field in #2452

pub(in crate::state) struct SnapshotGuard {
live: Arc<AtomicUsize>,
created_at: Instant,
Expand Down Expand Up @@ -157,11 +158,11 @@ impl Drop for SnapshotGuard {
let remaining = self.live.fetch_sub(1, Ordering::Relaxed) - 1;
let lifetime_ms = u64::try_from(self.created_at.elapsed().as_millis()).unwrap_or(u64::MAX);
let block_num = self.block_num.as_u32();
let superseded_for = self.superseded_at.get().map(Instant::elapsed);
if let Some(superseded_for) =
superseded_for.filter(|held| *held > SNAPSHOT_SUPERSEDED_WARN_THRESHOLD)
{
let superseded_for_ms = u64::try_from(superseded_for.as_millis()).unwrap_or(u64::MAX);
// A never-superseded snapshot (the latest at shutdown) reports zero time held past
// supersession.
let superseded_for = self.superseded_at.get().map_or(Duration::ZERO, Instant::elapsed);
let superseded_for_ms = u64::try_from(superseded_for.as_millis()).unwrap_or(u64::MAX);
if superseded_for > SNAPSHOT_SUPERSEDED_WARN_THRESHOLD {
warn!(
target: COMPONENT,
"State snapshot held for excessive time after supersession",
Expand All @@ -171,11 +172,12 @@ impl Drop for SnapshotGuard {
snapshots.live = remaining
);
} else {
debug!(
info!(
target: COMPONENT,
"State snapshot released",
block.number = block_num,
snapshot.lifetime_ms = lifetime_ms,
snapshot.superseded_for_ms = superseded_for_ms,
snapshots.live = remaining
);
}
Expand Down
Loading