log: print reason when writing chainstate

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

This PR addresses a few leftover nits 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] FlushStateToDisk write: flush mode=PERIODIC, prune=0, cache_large=0, cache_critical=0, periodic=1
12025-05-03T09:26:52Z [coindb] FlushStateToDisk write: flush mode=PERIODIC, prune=0, cache_large=0, cache_critical=0, periodic=1
22025-05-03T10:27:58Z [coindb] FlushStateToDisk write: flush mode=PERIODIC, prune=0, cache_large=0, cache_critical=0, periodic=1
32025-05-03T11:39:20Z [coindb] FlushStateToDisk write: flush mode=PERIODIC, prune=0, cache_large=0, cache_critical=0, periodic=1
42025-05-03T12:41:48Z [coindb] FlushStateToDisk write: flush mode=PERIODIC, prune=0, cache_large=0, cache_critical=0, periodic=1
52025-05-03T13:40:08Z [coindb] FlushStateToDisk write: flush mode=PERIODIC, prune=0, cache_large=0, cache_critical=0, periodic=1
62025-05-03T14:49:16Z [coindb] FlushStateToDisk write: flush mode=PERIODIC, prune=0, cache_large=0, cache_critical=0, periodic=1
72025-05-03T15:14:37Z [coindb] FlushStateToDisk write: flush mode=ALWAYS, prune=0, cache_large=0, cache_critical=0, periodic=0
82025-05-03T15:17:28Z [coindb] FlushStateToDisk write: flush mode=ALWAYS, prune=0, cache_large=0, cache_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. A summary of reviews will appear here.

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

fuzz: assert `FastRandomContext` range boundaries dd31eccc38

refactor: unify flag naming in FlushStateToDisk

Besides unifying the names, the const flags were also marked as such (to obviate the difference compared to e.g. `flush_for_prune`).
And to avoid the `=` vs `==` confusions these flags were switched to use brace inits.

2d41180a57

refactor: obviate boundaries when assigning `m_next_write`

Added `randrange` method generating a random value in an interval.
Also used it in `mapport.cpp` which had a similar situation.
Shortened `DATABASE_WRITE_INTERVAL_*` to make their usages fit on a single line.

d415f242a6

refactor: first flush always schedules the next write 930f493d5d

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

l0rinc force-pushed on May 4, 2025

log: print reason when writing chainstate #32404

Code Coverage & Benchmarks

Reviews