Skip to content

Refactors logging for startup accounts verification #7327

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

Merged
brooksprumo merged 2 commits into from
Aug 6, 2025
Merged

Refactors logging for startup accounts verification #7327

Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
2641992
Refactors logging for startup accounts verification
brooksprumo Aug 5, 2025
69f5bb0
pr: put back log when skipped
brooksprumo Aug 6, 2025
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
20 changes: 10 additions & 10 deletions runtime/src/bank.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4607,7 +4607,7 @@ impl Bank {
Builder::new()
.name("solBgHashVerify".into())
.spawn(move || {
info!("Initial background accounts hash verification has started");
info!("Verifying accounts in background...");
let start = Instant::now();
let thread_pool = {
let num_threads = accounts_db_
Expand Down Expand Up @@ -4643,16 +4643,15 @@ impl Bank {
i64
),
);
info!(
"Initial background accounts hash verification has stopped \
in {total_time:?}",
);
info!("Verifying accounts in background... Done in {total_time:?}");
is_ok
})
.unwrap()
});
true // initial result is true. We haven't failed yet. If verification fails, we'll panic from bg thread.
} else {
info!("Verifying accounts in foreground...");
let start = Instant::now();
let calculated_accounts_lt_hash = if let Some(duplicates_lt_hash) = duplicates_lt_hash {
accounts_db.calculate_accounts_lt_hash_at_startup_from_storages(
snapshot_storages.0.as_slice(),
Expand All @@ -4664,6 +4663,10 @@ impl Bank {
};
let is_ok = check_lt_hash(&expected_accounts_lt_hash, &calculated_accounts_lt_hash);
self.set_initial_accounts_hash_verification_completed();
info!(
Copy link
Copy Markdown

@roryharr roryharr Aug 5, 2025

Choose a reason for hiding this comment

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

Just for consistency what about let total_time = start.elapsed();

I would guess logging the timing is not useful in this case?

Copy link
Copy Markdown
Author

@brooksprumo brooksprumo Aug 5, 2025

Choose a reason for hiding this comment

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

I could add a variable, but it seemed unnecessary. We do log the timing here.

Copy link
Copy Markdown

@roryharr roryharr Aug 6, 2025

Choose a reason for hiding this comment

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

I mean in the metrics as above.

Copy link
Copy Markdown
Author

@brooksprumo brooksprumo Aug 6, 2025 •
edited
Loading

Choose a reason for hiding this comment

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

Verifying accounts in the foreground will always be for testing/debugging usages, so I don't think we need to submit metrics in this case.

Copy link
Copy Markdown

@roryharr roryharr Aug 6, 2025

Choose a reason for hiding this comment

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

Makes sense!

"Verifying accounts in foreground... Done in {:?}",
start.elapsed(),
);
is_ok
}
}
Expand Down Expand Up @@ -4836,16 +4839,13 @@ impl Bank {
let (verified_accounts, verify_accounts_time_us) = measure_us!({
let should_verify_accounts = !self.rc.accounts.accounts_db.skip_initial_hash_calc;
if should_verify_accounts {
info!("Verifying accounts...");
let verified = self.verify_accounts_hash(
self.verify_accounts_hash(
VerifyAccountsHashConfig {
require_rooted_bank: false,
run_in_background: true,
},
duplicates_lt_hash,
);
info!("Verifying accounts... In background.");
verified
)
} else {
info!("Verifying accounts... Skipped.");
Copy link
Copy Markdown

@roryharr roryharr Aug 5, 2025

Choose a reason for hiding this comment

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

Is this comment redundant or incorrect? Seems useful to know that it was skipped.

Copy link
Copy Markdown
Author

@brooksprumo brooksprumo Aug 5, 2025

Choose a reason for hiding this comment

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

Before we had it because we always logged:

                info!("Verifying accounts...");

a few lines up, so it was needed to be clear. Now, we only log what we're actually doing. So the absence of any "verifying accounts" logs indicates it was skipped. Wdyt?

Copy link
Copy Markdown

@roryharr roryharr Aug 6, 2025

Choose a reason for hiding this comment

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

I find it can still be useful to know it was skipped. For example when searching through logs of multiple startup cycles trying to figure out why one was failing and another passed.

Copy link
Copy Markdown
Author

@brooksprumo brooksprumo Aug 6, 2025

Choose a reason for hiding this comment

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

Done. I've put the "skipped" log back in 69f5bb0.

self.set_initial_accounts_hash_verification_completed();
Expand Down
Loading