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

kevkevinpal · 2024-02-07T13:07:33Z

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

DrahtBot · 2024-02-07T13:07:36Z

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	maflcko, glozow
Concept ACK	tdb3
Stale ACK	epiccurious, ajtowns

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

Conflicts

Reviewers, this pull request conflicts with the following ones:

#29700 (kernel, refactor: return error status on all fatal errors by ryanofsky)
#29642 (kernel: Handle fatal errors through return values by TheCharlatan)
#29641 (scripted-diff: Use LogInfo/LogDebug over LogPrintf/LogPrint by maflcko)

If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

maflcko · 2024-02-07T13:18:33Z

Why is this needed? A progress log for something that takes less than a second does not sound useful

kevkevinpal · 2024-02-07T13:41:45Z

Why is this needed? A progress log for something that takes less than a second does not sound useful

This is in response to this comment #29227 (review)
the logs I posted in the description are from testnet I can run this on mainnet to get the time it takes on shutdown there

maflcko · 2024-02-07T13:47:27Z

The delay is probably from leveldb, but it would be good to first check

theStack · 2024-02-07T14:39:17Z

Why is this needed? A progress log for something that takes less than a second does not sound useful

I agree that logging the detailed progress in % is a bit overkill, but IMHO a single line "Dumping xyz mempool transactions to disk..." would still make sense. The "less than a second" data point seems to be closer to best-case, I have one machine here where dumping a full default-sized mempool takes more than 10 seconds.

maflcko · 2024-02-07T14:57:52Z

10 seconds.

Sure, it may take longer than one second, depending on the hardware and its size. However,

Loading a mempool can take hours, depending on the hardware and its size.
Loading is done in a background thread, so other stuff is going on and logged at the same time.

Shutdown should be single-threaded, so the debug log should contain the last timestamp, which is enough to derive how long it took to dump the mempool, or whether it is still ongoing. I don't expect anyone to poll the debug log every second to see an update on the progress.

IMHO a single line "Dumping xyz mempool transactions to disk..." would still make sense.

Agree, if there isn't such a log line right now, it could make sense to add it.

epiccurious · 2024-02-07T14:58:19Z

epiccurious commented

Feb 7, 2024

logging the detailed progress in % is a bit overkill

+1 to @theStack's comment. Logging the start and end would be sufficient, no need for the 10% increments.

kevkevinpal · 2024-02-07T15:15:34Z

force pushed 33153b0

This removes the 10% increments and now logs a single line with the amount of mempool transactions being written to the disk

maflcko

lgtm

src/kernel/mempool_persist.cpp

epiccurious · 2024-02-07T22:55:26Z

utACK 6312513. Planning to test as well.

epiccurious · 2024-02-09T14:16:05Z

I'm seeing an issue during testing. The debug log incorrectly reports 0 MB. Are others able to reproduce my result?

user1@comp1:~/Documents/GitHub/btc29402$ src/bitcoin-cli --rpcwait getmempoolinfo | jq -c '{ transactions: (.size), memory_usage_in_mb: (.usage/1000000) }' | jq; src/bitcoin-cli --rpcwait stop; sleep 10; grep -a Writing ~/.bitcoin/debug.log | tail -2
{
  "transactions": 2529,
  "memory_usage_in_mb": 6.061648
}
Bitcoin Core stopping
2024-02-09T14:11:49Z Writing 2529 mempool transactions to file 0 MB...
2024-02-09T14:11:49Z Writing 0 unbroadcast transactions to file.

epiccurious · 2024-02-09T14:20:49Z

src/kernel/mempool_persist.cpp

-        file << (uint64_t)vinfo.size();
+        uint64_t mempool_transactions_to_write(vinfo.size());
+        file << mempool_transactions_to_write;
+        LogInfo("Writing %u mempool transactions to file %u MB...\n", mempool_transactions_to_write, sizeof(vinfo)/1000000);


very minor nit - To make the log more readable, can you please add a comma after 'file'?

So it displays as:

Writing xx mempool transactions to file, xx MB...

kevkevinpal · 2024-02-09T22:25:35Z

I'm seeing an issue during testing. The debug log incorrectly reports 0 MB. Are others able to reproduce my result?

user1@comp1:~/Documents/GitHub/btc29402$ src/bitcoin-cli --rpcwait getmempoolinfo | jq -c '{ transactions: (.size), memory_usage_in_mb: (.usage/1000000) }' | jq; src/bitcoin-cli --rpcwait stop; sleep 10; grep -a Writing ~/.bitcoin/debug.log | tail -2
{
  "transactions": 2529,
  "memory_usage_in_mb": 6.061648
}
Bitcoin Core stopping
2024-02-09T14:11:49Z Writing 2529 mempool transactions to file 0 MB...
2024-02-09T14:11:49Z Writing 0 unbroadcast transactions to file.

It looks like usage from getmempoolinfo is coming from DynamicMemoryUsage in txmempool.cpp
Where I'm calculating sizeof(vinfo) which comes from infoAll in txmempool.cpp. infoAll allocates only mapTx.size()

DynamicMemoryUsage computes like this which includes mapTx.size()

    return memusage::MallocUsage(sizeof(CTxMemPoolEntry) + 15 * sizeof(void*)) * mapTx.size() + memusage::DynamicUsage(mapNextTx) + memusage::DynamicUsage(mapDeltas) + memusage::DynamicUsage(txns_randomized) + cachedInnerUsage;

I think it might make more sense to not have a MB amount on vinfo and print it out for the file size at the end of the creating the mempool file so users are not confused when they see xx amounts in MB and their file actually a different size

epiccurious · 2024-02-09T22:29:47Z

it might make more sense to not have a MB amount on vinfo and print it out for the file size at the end of the creating the mempool file so users are not confused when they see xx amounts in MB and their file actually a different size

Approach ACK.

maflcko · 2024-02-16T15:56:10Z

lgtm ACK dbdb732

Seems fine to log when starting to dump the mempool.

ajtowns

utACK dbdb732

ajtowns · 2024-02-21T04:30:04Z

src/kernel/mempool_persist.cpp

@@ -44,7 +44,7 @@ bool LoadMempool(CTxMemPool& pool, const fs::path& load_path, Chainstate& active

    AutoFile file{opts.mockable_fopen_function(load_path, "rb")};
    if (file.IsNull()) {
-        LogPrintf("Failed to open mempool file from disk. Continuing anyway.\n");
+        LogInfo("Failed to open mempool file from disk. Continuing anyway.\n");


Remove "from disk" here, if dropping "disk" mentions elsewhere?

I didn't modify this line because opening the file from disk is accurate but I can change this to Failed to open mempool file. Continuing anyway

updated in 34b6a8d

maflcko · 2024-02-23T08:32:19Z

ACK 34b6a8d

glozow

utACK 34b6a8d

src/kernel/mempool_persist.cpp

maflcko · 2024-03-27T18:54:12Z

cr-ACK 4d5b557

glozow

reACK 4d5b557

tdb3

crACK. Will test shortly

tdb3 · 2024-03-28T14:41:15Z

Tested from master after merge. lgtm.

2024-03-28T14:37:40Z Writing 21 mempool transactions to file...
2024-03-28T14:37:40Z Writing 0 unbroadcast transactions to file.
2024-03-28T14:37:40Z Dumped mempool: 0.000s to copy, 0.006s to dump, 5795 bytes dumped to file

2024-03-28T14:37:59Z Loading 21 mempool transactions from file...
...
2024-03-28T14:37:59Z Progress loading mempool transactions from file: 14% (tried 3, 18 remaining)
2024-03-28T14:37:59Z msghand thread start
2024-03-28T14:37:59Z init message: Done loading
2024-03-28T14:37:59Z Progress loading mempool transactions from file: 23% (tried 5, 16 remaining)
2024-03-28T14:37:59Z Progress loading mempool transactions from file: 33% (tried 7, 14 remaining)
2024-03-28T14:37:59Z Progress loading mempool transactions from file: 42% (tried 9, 12 remaining)
2024-03-28T14:37:59Z Progress loading mempool transactions from file: 52% (tried 11, 10 remaining)
2024-03-28T14:37:59Z Progress loading mempool transactions from file: 61% (tried 13, 8 remaining)
2024-03-28T14:37:59Z Progress loading mempool transactions from file: 71% (tried 15, 6 remaining)
2024-03-28T14:37:59Z Progress loading mempool transactions from file: 80% (tried 17, 4 remaining)
2024-03-28T14:37:59Z Progress loading mempool transactions from file: 90% (tried 19, 2 remaining)
2024-03-28T14:37:59Z Imported mempool transactions from file: 21 succeeded, 0 failed, 0 expired, 0 already there, 0 waiting for initial broadcast

DrahtBot added the Mempool label Feb 7, 2024

kevkevinpal force-pushed the dumpmempoollogsfeb2024 branch from 7b2092f to 9534383 Compare February 7, 2024 13:44

DrahtBot added the CI failed label Feb 7, 2024

DrahtBot removed the CI failed label Feb 7, 2024

kevkevinpal force-pushed the dumpmempoollogsfeb2024 branch from 9534383 to 33153b0 Compare February 7, 2024 15:12

kevkevinpal changed the title ~~mempool: Loading progress added for dumping mempool transactions to disk~~ mempool: Log added for dumping mempool transactions to disk Feb 7, 2024

maflcko approved these changes Feb 7, 2024

View reviewed changes

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

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

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

kevkevinpal force-pushed the dumpmempoollogsfeb2024 branch 4 times, most recently from c23f5be to 6312513 Compare February 7, 2024 16:37

epiccurious approved these changes Feb 7, 2024

View reviewed changes

DrahtBot mentioned this pull request Feb 8, 2024

log, refactor: Allow log macros to accept context arguments #29256

Open

epiccurious reviewed Feb 9, 2024

View reviewed changes

kevkevinpal force-pushed the dumpmempoollogsfeb2024 branch 4 times, most recently from 616f798 to 4218460 Compare February 9, 2024 23:42

kevkevinpal force-pushed the dumpmempoollogsfeb2024 branch 2 times, most recently from d161129 to dbdb732 Compare February 15, 2024 14:01

DrahtBot requested a review from epiccurious February 16, 2024 15:56

ajtowns reviewed Feb 21, 2024

View reviewed changes

DrahtBot requested review from epiccurious and removed request for epiccurious February 21, 2024 04:32

kevkevinpal force-pushed the dumpmempoollogsfeb2024 branch from dbdb732 to 34b6a8d Compare February 23, 2024 01:25

DrahtBot requested review from epiccurious and ajtowns and removed request for epiccurious February 23, 2024 08:32

This was referenced Mar 13, 2024

kernel: Handle fatal errors through return values #29642

Draft

scripted-diff: Use LogInfo over LogPrintf [WIP, NOMERGE, DRAFT] #29641

Draft

DrahtBot mentioned this pull request Mar 22, 2024

kernel, refactor: return error status on all fatal errors #29700

Draft

glozow reviewed Mar 27, 2024

View reviewed changes

src/kernel/mempool_persist.cpp Show resolved Hide resolved

kevkevinpal added 2 commits March 27, 2024 07:18

mempool: Log added for dumping mempool transactions to disk

b9f04be

log: renamed disk to file so wording was more accurate

4d5b557

kevkevinpal force-pushed the dumpmempoollogsfeb2024 branch from 34b6a8d to 4d5b557 Compare March 27, 2024 12:20

DrahtBot requested a review from glozow March 27, 2024 18:54

glozow reviewed Mar 28, 2024

View reviewed changes

tdb3 reviewed Mar 28, 2024

View reviewed changes

glozow merged commit d1e9a02 into bitcoin:master Mar 28, 2024

bitcoin locked and limited conversation to collaborators Mar 28, 2025

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

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

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

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

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

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

Uh oh!

Conversation

Uh oh!

Uh oh!

Uh oh!

Code Coverage

Reviews

Conflicts

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!