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

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 6312513b5074f160971ffec0b093b58b9d3cdaae. 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

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 dbdb7320252fd68415e8b76bad5a2169bd7da241

Seems fine to log when starting to dump the mempool.

ajtowns

utACK dbdb7320252fd68415e8b76bad5a2169bd7da241

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

src/kernel/mempool_persist.cpp

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 34b6a8dadfb9a279f38fc828d6dff73209928f5d

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

ACK 34b6a8dadfb9a279f38fc828d6dff73209928f5d

glozow

utACK 34b6a8dadfb9a279f38fc828d6dff73209928f5d

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 ajtowns and epiccurious 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 #29641

Merged

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 Outdated 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

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

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

Uh oh!

Conversation

kevkevinpal commented Feb 7, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

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

Uh oh!

Code Coverage

Reviews

Conflicts

Uh oh!

maflcko commented Feb 7, 2024

Uh oh!

kevkevinpal commented Feb 7, 2024

Uh oh!

maflcko commented Feb 7, 2024

Uh oh!

theStack commented Feb 7, 2024

Uh oh!

maflcko commented Feb 7, 2024

Uh oh!

epiccurious commented Feb 7, 2024

Uh oh!

kevkevinpal commented Feb 7, 2024

Uh oh!

maflcko left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

epiccurious commented Feb 7, 2024

Uh oh!

epiccurious commented Feb 9, 2024

Uh oh!

epiccurious Feb 9, 2024 • 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!

kevkevinpal commented Feb 9, 2024

Uh oh!

epiccurious commented Feb 9, 2024

Uh oh!

maflcko commented Feb 16, 2024

Uh oh!

ajtowns left a comment

Choose a reason for hiding this comment

Uh oh!

ajtowns Feb 21, 2024

Choose a reason for hiding this comment

Uh oh!

kevkevinpal Feb 23, 2024

Choose a reason for hiding this comment

Uh oh!

kevkevinpal Feb 23, 2024

Choose a reason for hiding this comment

Uh oh!

maflcko commented Feb 23, 2024

Uh oh!

glozow left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

maflcko commented Mar 27, 2024

Uh oh!

glozow left a comment

Choose a reason for hiding this comment

Uh oh!

tdb3 left a comment

Choose a reason for hiding this comment

Uh oh!

tdb3 commented Mar 28, 2024

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

kevkevinpal commented Feb 7, 2024 •

edited

Loading

DrahtBot commented Feb 7, 2024 •

edited

Loading

epiccurious Feb 9, 2024 •

edited

Loading