log: print reason when writing chainstate

l0rinc commented at 2:27 pm on May 2, 2025: contributor

This PR addresses a leftover logging nit found while reviewing #30611#pullrequestreview-2809508852. This was also needed to validate its behavior properly, because currently there’s no way to visualize how often (and why) we’re flushing/syncing.

Starting with -debug=coindb will now add log lines such as

02025-05-03T08:34:57Z [coindb] Writing chainstate to disk: flush mode=PERIODIC, prune=0, large=0, critical=0, periodic=1
12025-05-03T09:26:52Z [coindb] Writing chainstate to disk: flush mode=PERIODIC, prune=0, large=0, critical=0, periodic=1
22025-05-03T10:27:58Z [coindb] Writing chainstate to disk: flush mode=PERIODIC, prune=0, large=0, critical=0, periodic=1
32025-05-03T11:39:20Z [coindb] Writing chainstate to disk: flush mode=PERIODIC, prune=0, large=0, critical=0, periodic=1
42025-05-03T12:41:48Z [coindb] Writing chainstate to disk: flush mode=PERIODIC, prune=0, large=0, critical=0, periodic=1
52025-05-03T13:40:08Z [coindb] Writing chainstate to disk: flush mode=PERIODIC, prune=0, large=0, critical=0, periodic=1
62025-05-03T14:49:16Z [coindb] Writing chainstate to disk: flush mode=PERIODIC, prune=0, large=0, critical=0, periodic=1
72025-05-03T15:14:37Z [coindb] Writing chainstate to disk: flush mode=ALWAYS, prune=0, large=0, critical=0, periodic=0
82025-05-03T15:17:28Z [coindb] Writing chainstate to disk: flush mode=ALWAYS, prune=0, large=0, critical=0, periodic=0

DrahtBot commented at 2:27 pm on May 2, 2025: contributor

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Code Coverage & Benchmarks

For details see: https://corecheck.dev/bitcoin/bitcoin/pulls/32404.

Reviews

See the guideline for information on the review process.

Type	Reviewers
ACK	davidgumberg, andrewtoth
Concept ACK	laanwj
Stale ACK	jonatack

If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

DrahtBot added the label Tests on May 2, 2025

l0rinc renamed this:
~~fuzz: assert FastRandomContext range boundaries~~
log: print reason when writing chainstate
on May 2, 2025

l0rinc force-pushed on May 2, 2025

DrahtBot added the label CI failed on May 2, 2025

DrahtBot commented at 2:34 pm on May 2, 2025: contributor

🚧 At least one of the CI tasks failed. Task multiprocess, i686, DEBUG: https://github.com/bitcoin/bitcoin/runs/41547005783 LLM reason (✨ experimental): The CI failure is caused by a compilation error in validation.cpp due to an undeclared identifier ’nNow’.

Try to run the tests locally, according to the documentation. However, a CI failure may still happen due to a number of reasons, for example:

Possibly due to a silent merge conflict (the changes in this pull request being incompatible with the current code in the target branch). If so, make sure to rebase on the latest commit of the target branch.
A sanitizer issue, which can only be found by compiling with the sanitizer and running the affected test.
An intermittent issue.

Leave a comment here, if you need help tracking down a confusing failure.

l0rinc force-pushed on May 2, 2025

DrahtBot removed the label CI failed on May 2, 2025

l0rinc force-pushed on May 2, 2025

DrahtBot added the label CI failed on May 2, 2025

DrahtBot commented at 9:44 pm on May 2, 2025: contributor

🚧 At least one of the CI tasks failed. Task previous releases, depends DEBUG: https://github.com/bitcoin/bitcoin/runs/41567587934 LLM reason (✨ experimental): The CI failure is caused by compilation being halted due to treating warnings as errors, specifically an unused variable warning that was promoted to an error.

Try to run the tests locally, according to the documentation. However, a CI failure may still happen due to a number of reasons, for example:

Possibly due to a silent merge conflict (the changes in this pull request being incompatible with the current code in the target branch). If so, make sure to rebase on the latest commit of the target branch.
A sanitizer issue, which can only be found by compiling with the sanitizer and running the affected test.
An intermittent issue.

Leave a comment here, if you need help tracking down a confusing failure.

DrahtBot removed the label CI failed on May 2, 2025

l0rinc marked this as ready for review on May 3, 2025

l0rinc commented at 3:54 pm on May 3, 2025: contributor

The new logs can help visualize the flush times and reasons during IBD now - reindex-chainstate periodic flushes require #32414

Cached coins over time: cache_coins_vs_time

It’s less obvious for used cache size (most likely since we cannot shrink the cache pool): cache_vs_time

in src/random.h:348 in ac922a4fbe outdated

342@@ -343,6 +343,14 @@ class RandomMixin
343         return Dur{Impl().randrange(range.count())};
344     }
345 
346+    /** Generate a uniform random duration in the half‑open interval [min,max). */
347+    template <StdChronoDuration Dur>
348+    Dur rand_uniform_range(Dur min, Dur max) noexcept

maflcko commented at 11:31 am on May 4, 2025:

the function args are missing std::common_type_t, as explained in the function immediately above.

l0rinc commented at 1:43 pm on May 4, 2025:

Is this only needed when we’re using different durations for the parameters such as ctx.randrange<std::chrono::seconds>(2s, 2min)?

The result is a bit ugly now, but I’ve changed it.

maflcko commented at 2:58 pm on May 4, 2025:

Is this only needed when we’re using different durations for the parameters such as

No. The function above only takes one parameter. The reason is explained in the comment of the function immediately above. (Line 338)

maflcko commented at 4:30 pm on May 4, 2025:

I guess it could make sense to add a comment to say that the same rationale as above applies. Otherwise, someone could remove it with the rationale that it isn’t needed. But no strong opinion.

l0rinc commented at 4:32 pm on May 4, 2025:

I have added a test which uses different durations, it would fail if reverted

in src/test/fuzz/random.cpp:82 in ac922a4fbe outdated

80+        const auto base{std::chrono::steady_clock::now()};
81+        const auto range{std::chrono::seconds{fuzzed_data_provider.ConsumeIntegralInRange<int>(0, 3'600)}};
82+        const auto tp{fast_random_context.rand_uniform_delay(base, range)};
83+        assert(tp >= base && tp <= base + range);
84+    }
85+}

maflcko commented at 11:32 am on May 4, 2025:

any reason to remove the trailing whitespace?

l0rinc commented at 1:43 pm on May 4, 2025:

I’m still not sure why we’re adding them, but made sure the IDE adds newlines to the end now.

maflcko commented at 2:57 pm on May 4, 2025:

I’m still not sure why we’re adding them, but made sure the IDE adds newlines to the end now.

They are already present, so removing them is just pointless churn
It is documented in .editorconfig and most editors add them by default, if missing. Which will cause churn in the future if they are removed on some files.
This repo is using git as content management system, which complains about this. Also GitHub web and GitHub diff warn about this. E.g. see the tail of https://github.com/bitcoin/bitcoin/commit/ba063a39aa0af194b19e30a3944f63bbe2268b13.diff

l0rinc commented at 4:12 pm on May 4, 2025:

Yeah, I know these, but it still doesn’t explain why - metaphorically speaking - we need a comma after the last element in a list. But I’ve configured my IDE now to add it, I don’t have to agree to accept it :)

maflcko commented at 4:28 pm on May 4, 2025:

Yeah, I know these, but it still doesn’t explain why - metaphorically speaking - we need a comma after the last element in a list.

The reason is the same: If there weren’t a comma (newline) after the last element (line) in a list (file), a diff would be verbose when a new element (line) is added after the last. Also, the verbose diff breaks git blame. Finally, tools may misbehave when the tool or the user assumes a newline is present.

l0rinc commented at 4:30 pm on May 4, 2025:

Thanks for explaining

l0rinc force-pushed on May 4, 2025

laanwj commented at 12:42 pm on May 6, 2025: member

Concept ACK

laanwj added the label Utils/log/libs on May 6, 2025

andrewtoth commented at 4:28 pm on May 18, 2025: contributor

Concept ACK on the last commit.

It’s not clear to me how the other commits are related to the PR description though. It would probably be easier to review with only the last commit.

maflcko removed the label Tests on May 19, 2025

maflcko removed the label Utils/log/libs on May 19, 2025

DrahtBot added the label Utils/log/libs on May 19, 2025

l0rinc force-pushed on May 21, 2025

l0rinc commented at 1:55 pm on May 21, 2025: contributor

It’s not clear to me how the other commits are related to the PR description though

They were addressing the review comments I added to the mentioned PR, unifying naming (e.g. fCacheCritical vs should_write), extracting boolean to named symbol (bool first_flush{m_next_write == NodeClock::time_point::max()), adding helper for interval random generation. Not sure what the exact objections were, but I’ve removed them to keep only the logging now.

DrahtBot added the label CI failed on May 21, 2025

DrahtBot removed the label CI failed on May 22, 2025

in src/validation.cpp:2867 in cfc8056c31 outdated

2863@@ -2864,6 +2864,9 @@ bool Chainstate::FlushStateToDisk(
2864         bool should_write = (mode == FlushStateMode::ALWAYS) || fCacheLarge || fCacheCritical || fPeriodicWrite || fFlushForPrune;
2865         // Write blocks, block index and best chain related state to disk.
2866         if (should_write) {
2867+            LogDebug(BCLog::COINDB, "FlushStateToDisk write: flush mode=%s, prune=%d, cache_large=%d, cache_critical=%d, periodic=%d",

jonatack commented at 6:04 pm on May 23, 2025:

nit, “FlushStateToDisk” might be redundant here, as here is the log with -logsourcelocations=1

02025-05-23T17:59:04.348160Z [validation.cpp:2868] [FlushStateToDisk] [coindb] FlushStateToDisk write: flush mode=PERIODIC, prune=0, cache_large=1, cache_critical=0, periodic=0

l0rinc commented at 6:27 pm on May 23, 2025:

Would this be more descriptive?

0            LogDebug(BCLog::COINDB, "Writing chainstate to disk: flush mode=%s, prune=%d, cache_large=%d, cache_critical=%d, periodic=%d",

jonatack commented at 6:40 pm on May 23, 2025:

That does seem nicer.

l0rinc commented at 7:17 pm on May 23, 2025:

Good call, changed, rebased, updated PR description, added you as co-author.

jonatack commented at 6:10 pm on May 23, 2025: member

ACK cfc8056c316be4742938d64ea5207b90d10d1e28

DrahtBot requested review from laanwj on May 23, 2025

DrahtBot requested review from andrewtoth on May 23, 2025

l0rinc force-pushed on May 23, 2025

log: print reason for why should_write was triggered in `FlushStateToDisk`

Co-authored-by: Jon Atack <jon@atack.com>

53e9b71b2f

l0rinc force-pushed on May 23, 2025

davidgumberg commented at 10:29 pm on May 23, 2025: contributor

ACK https://github.com/bitcoin/bitcoin/pull/32404/commits/53e9b71b2fd59c18b75e45e3a24c39182c20a59e

DrahtBot requested review from jonatack on May 23, 2025

in src/validation.h:441 in 53e9b71b2f

436@@ -437,7 +437,8 @@ enum DisconnectResult
437 class ConnectTrace;
438 
439 /** @see Chainstate::FlushStateToDisk */
440-enum class FlushStateMode {
441+inline constexpr std::array FlushStateModeNames{"NONE", "IF_NEEDED", "PERIODIC", "ALWAYS"};
442+enum class FlushStateMode: uint8_t {

davidgumberg commented at 10:30 pm on May 23, 2025:

non-blocking nit: uint8_t here seems unnecessary

andrewtoth approved

andrewtoth commented at 7:45 pm on May 25, 2025: contributor

utACK 53e9b71b2fd59c18b75e45e3a24c39182c20a59e

log: print reason when writing chainstate #32404

Code Coverage & Benchmarks

Reviews