log mempool loading progress

glozow commented at 11:50 am on January 11, 2024: member

Motivated by #29193. Currently, we only log something (non-debug) when we fail to load the file and at the end of importing all the transactions. That means it’s hard to tell what’s happening if it’s taking a long time to load.

This PR adds a maximum of 10 new unconditional log lines:

When we start to load transactions.
Our progress percentage when it advances by at least 10% from the last time we logged. Percentage is based on the number of transactions.

If there are lots of transactions in the mempool, the logs will look like this:

 02024-01-11T11:36:30.410726Z Loading 401 mempool transactions from disk... 
 12024-01-11T11:36:30.423374Z Progress loading mempool transactions from disk: 10% (tried 41, 360 remaining) 
 22024-01-11T11:36:30.435539Z Progress loading mempool transactions from disk: 20% (tried 81, 320 remaining) 
 32024-01-11T11:36:30.447874Z Progress loading mempool transactions from disk: 30% (tried 121, 280 remaining) 
 42024-01-11T11:36:30.460474Z Progress loading mempool transactions from disk: 40% (tried 161, 240 remaining) 
 52024-01-11T11:36:30.473731Z Progress loading mempool transactions from disk: 50% (tried 201, 200 remaining) 
 62024-01-11T11:36:30.487806Z Progress loading mempool transactions from disk: 60% (tried 241, 160 remaining) 
 72024-01-11T11:36:30.501739Z Progress loading mempool transactions from disk: 70% (tried 281, 120 remaining) 
 82024-01-11T11:36:30.516334Z Progress loading mempool transactions from disk: 80% (tried 321, 80 remaining) 
 92024-01-11T11:36:30.531309Z Progress loading mempool transactions from disk: 90% (tried 361, 40 remaining) 
102024-01-11T11:36:30.549019Z  Imported mempool transactions from disk: 401 succeeded, 0 failed, 0 expired, 0 already there, 400 waiting for initial broadcast

If there are 0 or 1 transactions, progress logs aren’t printed.

glozow added the label Mempool on Jan 11, 2024

glozow added the label Utils/log/libs on Jan 11, 2024

DrahtBot commented at 11:50 am on January 11, 2024: contributor

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

Code Coverage

For detailed information about the code coverage, see the test coverage report.

Reviews

See the guideline for information on the review process.

Type	Reviewers
ACK	ismaelsadeeq, dergoegge, theStack, mzumsande
Concept ACK	kristapsk, kevkevinpal
Stale ACK	alfonsoromanz

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

fanquake added the label Needs backport (26.x) on Jan 11, 2024

dergoegge commented at 1:34 pm on January 11, 2024: member

Concept ACK

alfonsoromanz approved

alfonsoromanz commented at 2:22 pm on January 11, 2024: none

Code Review ACK https://github.com/bitcoin/bitcoin/pull/29227/commits/6c3ca0cac38f3b9e307cd0522ba9e3b7a2bd05a5

I have not executed the code but I spent time reviewing the loop and the conditions within it, using your example provided in the PR description (401 txs). Looks good to me

DrahtBot requested review from dergoegge on Jan 11, 2024

theStack commented at 4:44 pm on January 11, 2024: contributor

Concept ACK

mzumsande commented at 6:38 pm on January 11, 2024: contributor

Concept ACK. I remember being surprised in the past that >5 minutes after starting up the node, my mempool was still loading.

theStack approved

theStack commented at 0:29 am on January 12, 2024: contributor

ACK 6c3ca0cac38f3b9e307cd0522ba9e3b7a2bd05a5

Reviewed the code and tested locally (mempool with ~26k txs), LGTM. Probably less important, but I think it would be nice to have more verbose logging also for dumping the mempool. I’ve heard sentences like “I wonder why Bitcoin Core takes so long to shutdown sometimes?” repeatedly from users.

DrahtBot requested review from mzumsande on Jan 12, 2024

in src/kernel/mempool_persist.cpp:76 in 6c3ca0cac3 outdated

75+        file >> total_txns_to_load;
76+        uint64_t txns_tried = 0;
77+        LogInfo("Loading %u mempool transactions from disk...\n", total_txns_to_load);
78+        int next_tenth_to_report = 0;
79+        while (txns_tried < total_txns_to_load) {
80+            const int percentage_done{static_cast<int>((static_cast<double>(100 * (txns_tried))) / static_cast<double>(total_txns_to_load))};

dergoegge commented at 1:34 pm on January 12, 2024:

nit:

0            const int percentage_done{(int)(100.0 * txns_tried / total_txns_to_load)};

glozow commented at 1:42 pm on January 12, 2024:

I thought we didn’t like c-style casts?

maflcko commented at 1:43 pm on January 12, 2024:

nitting the nit:

0-const int percentage_done{(int)(100.0 * txns_tried / total_txns_to_load)};
1+const int percentage_done(100.0 * txns_tried / total_txns_to_load);

glozow commented at 1:49 pm on January 12, 2024:

@maflcko knows best, changed.

dergoegge approved

dergoegge commented at 1:36 pm on January 12, 2024: member

Code review ACK 6c3ca0cac38f3b9e307cd0522ba9e3b7a2bd05a5

[log] mempool loading

Log at the top before incrementing so that this log isn't printed when
there's only 1 tx.

eb78ea4eeb

glozow force-pushed on Jan 12, 2024

glozow commented at 2:29 pm on January 12, 2024: member

CI failure is unrelated, #29234

in src/kernel/mempool_persist.cpp:78 in eb78ea4eeb

77+        LogInfo("Loading %u mempool transactions from disk...\n", total_txns_to_load);
78+        int next_tenth_to_report = 0;
79+        while (txns_tried < total_txns_to_load) {
80+            const int percentage_done(100.0 * txns_tried / total_txns_to_load);
81+            if (next_tenth_to_report < percentage_done / 10) {
82+                LogInfo("Progress loading mempool transactions from disk: %d%% (tried %u, %u remaining)\n",

ismaelsadeeq commented at 2:36 pm on January 12, 2024:

nit

0                LogInfo("Progress loading mempool transactions from disk: %d%% completed (tried %u txs, %u txs remaining)\n",

ajtowns commented at 8:02 am on January 15, 2024:

Might be better if this information were also exposed to the gui? Perhaps something along the lines of:

0    auto& cm = active_chainstate.m_chainman;
1    if (!cm.IsInitialBlockDownload()) {
2        cm.GetNotifications().progress("Loading mempool...", percentage_done, false);
3    }

would make sense? (completely untested)

ismaelsadeeq approved

ismaelsadeeq commented at 2:44 pm on January 12, 2024: member

ACK eb78ea4eebfe150bc1746282bfdad6eb0f764e3c

It will be nice to also log how many transactions were dumped not just unbroadcast set

 0diff --git a/src/kernel/mempool_persist.cpp b/src/kernel/mempool_persist.cpp
 1index cae4b04bf65..404f23b21a9 100644
 2--- a/src/kernel/mempool_persist.cpp
 3+++ b/src/kernel/mempool_persist.cpp
 4@@ -194,7 +194,6 @@ bool DumpMempool(const CTxMemPool& pool, const fs::path& dump_path, FopenFn mock
 5 
 6         file << mapDeltas;
 7 
 8-        LogPrintf("Writing %d unbroadcast transactions to disk.\n", unbroadcast_txids.size());
 9         file << unbroadcast_txids;
10 
11         if (!skip_file_commit && !FileCommit(file.Get()))
12@@ -203,6 +202,7 @@ bool DumpMempool(const CTxMemPool& pool, const fs::path& dump_path, FopenFn mock
13         if (!RenameOver(dump_path + ".new", dump_path)) {
14             throw std::runtime_error("Rename failed");
15         }
16+        LogInfo("Written %d mempool transactions to disk, %d are unbroadcasted transactions.\n", vinfo.size(
17), unbroadcast_txids.size());
18         auto last = SteadyClock::now();
19 
20         LogPrintf("Dumped mempool: %gs to copy, %gs to dump\n",

Shutdown logs will be like

 02024-01-12T14:43:49Z Shutdown: In progress...
 12024-01-12T14:43:49Z torcontrol thread exit
 22024-01-12T14:43:49Z addcon thread exit
 32024-01-12T14:43:49Z opencon thread exit
 42024-01-12T14:43:49Z net thread exit
 52024-01-12T14:43:49Z msghand thread exit
 62024-01-12T14:43:49Z DumpAnchors: Flush 0 outbound block-relay-only peer addresses to anchors.dat started
 72024-01-12T14:43:49Z DumpAnchors: Flush 0 outbound block-relay-only peer addresses to anchors.dat completed (0.00s)
 82024-01-12T14:43:49Z scheduler thread exit
 92024-01-12T14:43:49Z Written 51 mempool transactions to disk, 51 are unbroadcasted transactions.
102024-01-12T14:43:49Z Dumped mempool: 3.0667e-05s to copy, 0.00451417s to dump

DrahtBot requested review from theStack on Jan 12, 2024