log mempool loading progress #29227

glozow · 2024-01-11T11:50:31Z

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:

2024-01-11T11:36:30.410726Z Loading 401 mempool transactions from disk... 
2024-01-11T11:36:30.423374Z Progress loading mempool transactions from disk: 10% (tried 41, 360 remaining) 
2024-01-11T11:36:30.435539Z Progress loading mempool transactions from disk: 20% (tried 81, 320 remaining) 
2024-01-11T11:36:30.447874Z Progress loading mempool transactions from disk: 30% (tried 121, 280 remaining) 
2024-01-11T11:36:30.460474Z Progress loading mempool transactions from disk: 40% (tried 161, 240 remaining) 
2024-01-11T11:36:30.473731Z Progress loading mempool transactions from disk: 50% (tried 201, 200 remaining) 
2024-01-11T11:36:30.487806Z Progress loading mempool transactions from disk: 60% (tried 241, 160 remaining) 
2024-01-11T11:36:30.501739Z Progress loading mempool transactions from disk: 70% (tried 281, 120 remaining) 
2024-01-11T11:36:30.516334Z Progress loading mempool transactions from disk: 80% (tried 321, 80 remaining) 
2024-01-11T11:36:30.531309Z Progress loading mempool transactions from disk: 90% (tried 361, 40 remaining) 
2024-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.

DrahtBot · 2024-01-11T11:50:34Z

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.

dergoegge · 2024-01-11T13:34:11Z

Concept ACK

alfonsoromanz

Code Review ACK 6c3ca0c

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

theStack · 2024-01-11T16:44:50Z

Concept ACK

mzumsande · 2024-01-11T18:38:22Z

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

theStack

ACK 6c3ca0c

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.

dergoegge

Code review ACK 6c3ca0c

src/kernel/mempool_persist.cpp

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

glozow · 2024-01-12T14:29:57Z

CI failure is unrelated, #29234

ismaelsadeeq

ACK eb78ea4

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

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

Shutdown logs will be like

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

ismaelsadeeq · 2024-01-12T14:36:52Z

src/kernel/mempool_persist.cpp

+        while (txns_tried < total_txns_to_load) {
+            const int percentage_done(100.0 * txns_tried / total_txns_to_load);
+            if (next_tenth_to_report < percentage_done / 10) {
+                LogInfo("Progress loading mempool transactions from disk: %d%% (tried %u, %u remaining)\n",


nit

Suggested change

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

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

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

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

would make sense? (completely untested)

dergoegge

Code review ACK eb78ea4

theStack

re-ACK eb78ea4

kristapsk · 2024-01-12T16:55:02Z

Concept ACK

mzumsande

tested ACK eb78ea4

kevkevinpal · 2024-01-13T17:10:35Z

Concept ACK eb78ea4

ajtowns · 2024-01-15T08:04:51Z

"I wonder why Bitcoin Core takes so long to shutdown sometimes?" repeatedly from users.

I don't think that's due to dumping the mempool, but rather spinning on locks elsewhere in the code. I've seen very slow shutdowns myself, but been unable to nail it down precisely.

glozow · 2024-01-16T09:34:51Z

Leaving gui notifications (#29227 (comment)) and dumping logs (#29227 (review)) up for grabs

Log at the top before incrementing so that this log isn't printed when there's only 1 tx. Github-Pull: bitcoin#29227 Rebased-From: eb78ea4

glozow · 2024-01-16T09:45:51Z

26.x backport in #29209

Log at the top before incrementing so that this log isn't printed when there's only 1 tx. Github-Pull: bitcoin#29227 Rebased-From: eb78ea4

11f3a7e Use hardened runtime on macOS release builds. (Mark Friedenbach) ac1b9a5 [test] import descriptor wallet with reorged parent + IsFromMe child in mempool (glozow) ecb8ebc [test] rescan legacy wallet with reorged parent + IsFromMe child in mempool (Gloria Zhao) 438ac29 snapshots: don't core dump when running -checkblockindex after `loadtxoutset` (Mark Friedenbach) 7ec3455 [log] mempool loading (glozow) fe0f8fe net: create I2P sessions with both ECIES-X25519 and ElGamal encryption (Jon Atack) fc62271 [refactor] Add helper for iterating through mempool entries (stickies-v) Pull request description: Backports for 26.x. Includes: - 453b481 from #28391 - #29179 - #29200 - #29227 - #28791 - #29127 ACKs for top commit: stickies-v: ACK 11f3a7e Tree-SHA512: 20ef871ec768f2328056d83f958e595b36ae9b8baa8a6e8b0e1f02c3df4b16965a8e05dcb4323afbcc9ecc4bdde10931232512022c39ee7e12baf9795bf25bf1

…disk 4d5b557 log: renamed disk to file so wording was more accurate (kevkevin) b9f04be mempool: Log added for dumping mempool transactions to disk (kevkevin) Pull request description: Sometimes when shutting off bitcoind it can take a while to dump the mempool transaction onto the disk so this change adds additional logging to the `DumpMempool` method in `kernel/mempool_persist.cpp` Motivated by #29227 this change - adds a single new line for the amount of transactions being dumped and the amount of memory being dumped to file This is in response to #29227 (comment) The logs will now look like this ``` 2024-02-09T23:41:52Z DumpAnchors: Flush 2 outbound block-relay-only peer addresses to anchors.dat completed (0.02s) 2024-02-09T23:41:52Z scheduler thread exit 2024-02-09T23:41:52Z Writing 29 mempool transactions to file... 2024-02-09T23:41:52Z Writing 0 unbroadcast transactions to file. 2024-02-09T23:41:52Z Dumped mempool: 0.000s to copy, 0.022s to dump, 0.015 MB dumped to file 2024-02-09T23:41:52Z Flushed fee estimates to fee_estimates.dat. 2024-02-09T23:41:53Z Shutdown: done ``` ACKs for top commit: maflcko: cr-ACK 4d5b557 glozow: reACK 4d5b557 Tree-SHA512: 049191e140d00c1ea57debe0138f1c9eb0f9bb0ef8138e2568e6d89e64f45a5d5853ce3b9cc0b28566aab97555b47ddfb0f9199fc8cea6b81e53f50592d5ae6a

glozow added Mempool Utils/log/libs labels Jan 11, 2024

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

alfonsoromanz approved these changes Jan 11, 2024

View reviewed changes

DrahtBot requested a review from dergoegge January 11, 2024 14:22

theStack approved these changes Jan 12, 2024

View reviewed changes

DrahtBot requested a review from mzumsande January 12, 2024 00:29

dergoegge approved these changes Jan 12, 2024

View reviewed changes

src/kernel/mempool_persist.cpp Outdated Show resolved Hide resolved

[log] mempool loading

eb78ea4

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

glozow force-pushed the 2024-01-mempool-load-logs branch from 6c3ca0c to eb78ea4 Compare January 12, 2024 13:49

ismaelsadeeq approved these changes Jan 12, 2024

View reviewed changes

DrahtBot requested review from theStack, alfonsoromanz and dergoegge and removed request for alfonsoromanz January 12, 2024 14:45

dergoegge approved these changes Jan 12, 2024

View reviewed changes

DrahtBot requested review from alfonsoromanz and removed request for alfonsoromanz January 12, 2024 14:53

theStack approved these changes Jan 12, 2024

View reviewed changes

DrahtBot requested review from alfonsoromanz and removed request for alfonsoromanz January 12, 2024 14:56

DrahtBot requested review from alfonsoromanz and removed request for alfonsoromanz January 12, 2024 16:55

mzumsande reviewed Jan 12, 2024

View reviewed changes

DrahtBot requested review from alfonsoromanz and removed request for alfonsoromanz January 12, 2024 19:18

DrahtBot requested review from alfonsoromanz and removed request for alfonsoromanz January 13, 2024 17:10

DrahtBot requested review from alfonsoromanz and removed request for alfonsoromanz January 15, 2024 08:04

fanquake merged commit 05c4c5a into bitcoin:master Jan 15, 2024

glozow deleted the 2024-01-mempool-load-logs branch January 16, 2024 09:28

glozow added a commit to glozow/bitcoin that referenced this pull request Jan 16, 2024

[log] mempool loading

234f328

Log at the top before incrementing so that this log isn't printed when there's only 1 tx. Github-Pull: bitcoin#29227 Rebased-From: eb78ea4

glozow mentioned this pull request Jan 16, 2024

[26.x] more backports #29209

Merged

glozow removed the Needs backport (26.x) label Jan 16, 2024

willcl-ark mentioned this pull request Jan 17, 2024

Failed loading mempool when restarting bitcoind #29193

Closed

1 task

glozow added a commit to glozow/bitcoin that referenced this pull request Jan 18, 2024

[log] mempool loading

5c7e109

Log at the top before incrementing so that this log isn't printed when there's only 1 tx. Github-Pull: bitcoin#29227 Rebased-From: eb78ea4

glozow added a commit to glozow/bitcoin that referenced this pull request Jan 19, 2024

[log] mempool loading

7ec3455

Log at the top before incrementing so that this log isn't printed when there's only 1 tx. Github-Pull: bitcoin#29227 Rebased-From: eb78ea4

kevkevinpal mentioned this pull request Feb 7, 2024

mempool: Log added for dumping mempool transactions to disk #29402

Merged

stickies-v mentioned this pull request Mar 25, 2024

[26.x] final changes for 26.1 #29719

Merged

haarp mentioned this pull request May 22, 2024

Bug: Failure when bitcoind has not yet loaded mempool romanz/electrs#1040

Closed

bitcoin locked and limited conversation to collaborators Jan 15, 2025

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

log mempool loading progress #29227

log mempool loading progress #29227

Uh oh!

Conversation

glozow commented Jan 11, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

DrahtBot commented Jan 11, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Code Coverage

Reviews

Uh oh!

dergoegge commented Jan 11, 2024

Uh oh!

alfonsoromanz left a comment

Choose a reason for hiding this comment

Uh oh!

theStack commented Jan 11, 2024

Uh oh!

mzumsande commented Jan 11, 2024

Uh oh!

theStack left a comment

Choose a reason for hiding this comment

Uh oh!

dergoegge left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

glozow commented Jan 12, 2024

Uh oh!

ismaelsadeeq left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ismaelsadeeq Jan 12, 2024

Choose a reason for hiding this comment

Uh oh!

ajtowns Jan 15, 2024

Choose a reason for hiding this comment

Uh oh!

dergoegge left a comment

Choose a reason for hiding this comment

Uh oh!

theStack left a comment

Choose a reason for hiding this comment

Uh oh!

kristapsk commented Jan 12, 2024

Uh oh!

mzumsande left a comment

Choose a reason for hiding this comment

Uh oh!

kevkevinpal commented Jan 13, 2024

Uh oh!

ajtowns commented Jan 15, 2024

Uh oh!

glozow commented Jan 16, 2024

Uh oh!

glozow commented Jan 16, 2024

Uh oh!

Uh oh!

glozow commented Jan 11, 2024 •

edited

Loading

DrahtBot commented Jan 11, 2024 •

edited

Loading

ismaelsadeeq left a comment •

edited

Loading