bitcoin
mempool: Log added for dumping mempool transactions to disk
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 https://github.com/bitcoin/bitcoin/pull/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 https://github.com/bitcoin/bitcoin/pull/29227#issuecomment-1893375082
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
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.
Why is this needed? A progress log for something that takes less than a second does not sound useful
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 https://github.com/bitcoin/bitcoin/pull/29227#pullrequestreview-1817064507 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
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.
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.
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.
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
utACK 6312513b5074f160971ffec0b093b58b9d3cdaae. Planning to test as well.
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.
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
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.
rebased and also updated code to get the size of the file after saving
logs now look like such and I tested to see that the mempool.dat file was the correct size by going to my data dir and doing ls -alh and they matched in sizes
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
🚧 At least one of the CI tasks failed. Make sure to run all tests locally, according to the documentation.
Possibly this is 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.
Leave a comment here, if you need help tracking down a confusing failure.
Debug: https://github.com/bitcoin/bitcoin/runs/21427000553
Tested ACK 25482b5aea6fb910b74666414a6330ec53f6a4c9.
This output is clean. Solid approach piggy-backing on the Dumped mempool: line that already exists.
2024-02-10T20:36:10Z Writing 5364 mempool transactions to file...
2024-02-10T20:36:10Z Writing 0 unbroadcast transactions to file.
2024-02-10T20:36:10Z Dumped mempool: 0.005s to copy, 0.101s to dump, 7.865 MB dumped to file
they matched in sizes
ACK.
user1@comp1:~$ ls -l .bitcoin/mempool.dat
-rw------- 1 user1 user1 7865003 Feb 10 15:36 .bitcoin/mempool.dat
lgtm ACK dbdb7320252fd68415e8b76bad5a2169bd7da241
Seems fine to log when starting to dump the mempool.
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
