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

pull kevkevinpal wants to merge 2 commits into bitcoin:master from kevkevinpal:dumpmempoollogsfeb2024 changing 1 files +13 −10
  1. kevkevinpal commented at 1:07 pm on February 7, 2024: contributor

    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

    02024-02-09T23:41:52Z DumpAnchors: Flush 2 outbound block-relay-only peer addresses to anchors.dat completed (0.02s)
12024-02-09T23:41:52Z scheduler thread exit
22024-02-09T23:41:52Z Writing 29 mempool transactions to file...
32024-02-09T23:41:52Z Writing 0 unbroadcast transactions to file.
42024-02-09T23:41:52Z Dumped mempool: 0.000s to copy, 0.022s to dump, 0.015 MB dumped to file
52024-02-09T23:41:52Z Flushed fee estimates to fee_estimates.dat.
62024-02-09T23:41:53Z Shutdown: done
  2. DrahtBot commented at 1:07 pm on February 7, 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 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.

  3. DrahtBot added the label Mempool on Feb 7, 2024
  4. maflcko commented at 1:18 pm on February 7, 2024: member
    Why is this needed? A progress log for something that takes less than a second does not sound useful
  5. kevkevinpal commented at 1:41 pm on February 7, 2024: contributor

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

  6. kevkevinpal force-pushed on Feb 7, 2024
  7. DrahtBot added the label CI failed on Feb 7, 2024
  8. maflcko commented at 1:47 pm on February 7, 2024: member
    The delay is probably from leveldb, but it would be good to first check
  9. theStack commented at 2:39 pm on February 7, 2024: contributor

    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. maflcko commented at 2:57 pm on February 7, 2024: member

    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.

  11. epiccurious commented at 2:58 pm on February 7, 2024: none

    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.

  12. DrahtBot removed the label CI failed on Feb 7, 2024
  13. kevkevinpal force-pushed on Feb 7, 2024
  14. kevkevinpal renamed this:
    mempool: Loading progress added for dumping mempool transactions to disk
    mempool: Log added for dumping mempool transactions to disk
    on Feb 7, 2024
  15. kevkevinpal commented at 3:15 pm on February 7, 2024: contributor

    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

  16. in src/kernel/mempool_persist.cpp:187 in 33153b0236 outdated 
    183@@ -184,7 +184,9 @@ bool DumpMempool(const CTxMemPool& pool, const fs::path& dump_path, FopenFn mock
184         }
185         file.SetXor(xor_key);
186 
187-        file << (uint64_t)vinfo.size();
188+        uint64_t mempool_transactions_to_write = (uint64_t)vinfo.size();
    maflcko commented at 3:35 pm on February 7, 2024: 
    0        uint64_t mempool_transactions_to_write(vinfo.size());

    nit: No need to repeat the type

    kevkevinpal commented at 4:00 pm on February 7, 2024:
    fix in 6312513
  17. in src/kernel/mempool_persist.cpp:189 in 33153b0236 outdated 
    183@@ -184,7 +184,9 @@ bool DumpMempool(const CTxMemPool& pool, const fs::path& dump_path, FopenFn mock
184         }
185         file.SetXor(xor_key);
186 
187-        file << (uint64_t)vinfo.size();
188+        uint64_t mempool_transactions_to_write = (uint64_t)vinfo.size();
189+        file << mempool_transactions_to_write;
190+        LogInfo("Writing %u mempool transactions to disk...\n", mempool_transactions_to_write);
    maflcko commented at 3:36 pm on February 7, 2024:
    nit: Could add the mempool size in MB, if it is easy to add?
    maflcko commented at 3:38 pm on February 7, 2024:
    unrelated: In this file, I think it would be clearer to replace “disk” with “file”, because the transactions are not dumped to separate files on disk, but to a single file.
    kevkevinpal commented at 4:00 pm on February 7, 2024:

    updated in 6312513 I just used sizeof() on vinfo to get this amount in bytes then divided by 1000000 to get MB

    It will say 0 though if the size in bytes is small

    kevkevinpal commented at 4:27 pm on February 7, 2024:
    should I update disk to file in this PR? I was trying to write the logs similar to the other ones in this file
    maflcko commented at 9:36 am on February 8, 2024:
    Up to you. It is an unrelated comment, so you can add another commit to this pull to change all in this file, or not.
    kevkevinpal commented at 2:17 pm on February 8, 2024:
    added this commit 9f57a2e to change the wording from disk to file, disk is used in the file once still but I think it makes sense as it is “opened mempool file from disk”
  18. maflcko approved
  19. maflcko commented at 3:38 pm on February 7, 2024: member
    lgtm
  20. kevkevinpal force-pushed on Feb 7, 2024
  21. kevkevinpal force-pushed on Feb 7, 2024
  22. kevkevinpal force-pushed on Feb 7, 2024
  23. kevkevinpal force-pushed on Feb 7, 2024
  24. epiccurious approved
  25. epiccurious commented at 10:55 pm on February 7, 2024: none
    utACK 6312513b5074f160971ffec0b093b58b9d3cdaae. Planning to test as well.
  26. epiccurious commented at 2:16 pm on February 9, 2024: none

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

    0user1@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
1{
2  "transactions": 2529,
3  "memory_usage_in_mb": 6.061648
4}
5Bitcoin Core stopping
62024-02-09T14:11:49Z Writing 2529 mempool transactions to file 0 MB...
72024-02-09T14:11:49Z Writing 0 unbroadcast transactions to file.
  27. in src/kernel/mempool_persist.cpp:189 in 9f57a2ec49 outdated 
    183@@ -184,7 +184,9 @@ bool DumpMempool(const CTxMemPool& pool, const fs::path& dump_path, FopenFn mock
184         }
185         file.SetXor(xor_key);
186 
187-        file << (uint64_t)vinfo.size();
188+        uint64_t mempool_transactions_to_write(vinfo.size());
189+        file << mempool_transactions_to_write;
190+        LogInfo("Writing %u mempool transactions to file %u MB...\n", mempool_transactions_to_write, sizeof(vinfo)/1000000);
    epiccurious commented at 2:20 pm on February 9, 2024:

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

    So it displays as:

    0Writing xx mempool transactions to file, xx MB...
  28. kevkevinpal commented at 10:25 pm on February 9, 2024: contributor

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

    0user1@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
1{
2  "transactions": 2529,
3  "memory_usage_in_mb": 6.061648
4}
5Bitcoin Core stopping
62024-02-09T14:11:49Z Writing 2529 mempool transactions to file 0 MB...
72024-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()

    0    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

  29. epiccurious commented at 10:29 pm on February 9, 2024: none

    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.

  30. kevkevinpal force-pushed on Feb 9, 2024
  31. kevkevinpal force-pushed on Feb 9, 2024
  32. kevkevinpal force-pushed on Feb 9, 2024
  33. kevkevinpal force-pushed on Feb 9, 2024
  34. kevkevinpal commented at 11:43 pm on February 9, 2024: contributor

    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

    02024-02-09T23:41:52Z DumpAnchors: Flush 2 outbound block-relay-only peer addresses to anchors.dat completed (0.02s)
12024-02-09T23:41:52Z scheduler thread exit
22024-02-09T23:41:52Z Writing 29 mempool transactions to file...
32024-02-09T23:41:52Z Writing 0 unbroadcast transactions to file.
42024-02-09T23:41:52Z Dumped mempool: 0.000s to copy, 0.022s to dump, 0.015 MB dumped to file
52024-02-09T23:41:52Z Flushed fee estimates to fee_estimates.dat.
62024-02-09T23:41:53Z Shutdown: done
  35. kevkevinpal force-pushed on Feb 9, 2024
  36. DrahtBot commented at 11:46 pm on February 9, 2024: contributor

    🚧 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

  37. DrahtBot added the label CI failed on Feb 9, 2024
  38. kevkevinpal force-pushed on Feb 9, 2024
  39. DrahtBot removed the label CI failed on Feb 10, 2024
  40. kevkevinpal requested review from epiccurious on Feb 10, 2024
  41. kevkevinpal requested review from maflcko on Feb 10, 2024
  42. epiccurious commented at 8:47 pm on February 10, 2024: none

    Tested ACK 25482b5aea6fb910b74666414a6330ec53f6a4c9.

    This output is clean. Solid approach piggy-backing on the Dumped mempool: line that already exists.

    02024-02-10T20:36:10Z Writing 5364 mempool transactions to file...
12024-02-10T20:36:10Z Writing 0 unbroadcast transactions to file.
22024-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.

    0user1@comp1:~$ ls -l .bitcoin/mempool.dat 
1-rw------- 1 user1 user1 7865003 Feb 10 15:36 .bitcoin/mempool.dat
  43. DrahtBot removed review request from epiccurious on Feb 10, 2024
  44. epiccurious approved
  45. in src/kernel/mempool_persist.cpp:213 in 25482b5aea outdated 
    206@@ -205,9 +207,11 @@ bool DumpMempool(const CTxMemPool& pool, const fs::path& dump_path, FopenFn mock
207         }
208         auto last = SteadyClock::now();
209 
210-        LogPrintf("Dumped mempool: %.3fs to copy, %.3fs to dump\n",
211+        LogPrintf("Dumped mempool: %.3fs to copy, %.3fs to dump, %.3f MB dumped to file\n",
212                   Ticks<SecondsDouble>(mid - start),
213-                  Ticks<SecondsDouble>(last - mid));
214+                  Ticks<SecondsDouble>(last - mid),
215+                  (float)file_size(dump_path)/1000000);
    maflcko commented at 10:09 am on February 12, 2024:

    Not sure about the argument dependent lookup here. Why not simply fix it the way the CI has instructed? (Add the include and use the fs namespace)?

    If the CI error was unclear, suggestions to make it clearer are welcome.

    kevkevinpal commented at 5:26 am on February 14, 2024:

    I think this is what you are talking about unless I’m getting confused b9f449b

    the <util/fs.h> includes is already imported but I added fs:: before file_size

  46. in src/kernel/mempool_persist.cpp:199 in 25482b5aea outdated 
    195@@ -194,7 +196,7 @@ bool DumpMempool(const CTxMemPool& pool, const fs::path& dump_path, FopenFn mock
196 
197         file << mapDeltas;
198 
199-        LogPrintf("Writing %d unbroadcast transactions to disk.\n", unbroadcast_txids.size());
200+        LogPrintf("Writing %d unbroadcast transactions to file.\n", unbroadcast_txids.size());
    maflcko commented at 10:09 am on February 12, 2024:
    nit: While touching this, could switch to LogInfo in this file, to avoid having to touch it yet again?
    epiccurious commented at 1:02 pm on February 12, 2024:
    +1
    kevkevinpal commented at 5:24 am on February 14, 2024:
    updated in this commit b9f449b
    maflcko commented at 8:32 am on February 14, 2024:
    No, I don’t think this was addressed?
    kevkevinpal commented at 2:03 pm on February 15, 2024:

    sorry I got confused by the comment and thought you meant that I changed the log line to include disk first and then in the second commit changed it to file

    I updated LogPrintf -> LogInfo in 27251e8

  47. maflcko approved
  48. maflcko commented at 10:09 am on February 12, 2024: member
    lgtm
  49. kevkevinpal force-pushed on Feb 14, 2024
  50. kevkevinpal force-pushed on Feb 14, 2024
  51. in src/kernel/mempool_persist.cpp:213 in a4ed80f5d4 outdated 
    206@@ -205,9 +207,11 @@ bool DumpMempool(const CTxMemPool& pool, const fs::path& dump_path, FopenFn mock
207         }
208         auto last = SteadyClock::now();
209 
210-        LogPrintf("Dumped mempool: %.3fs to copy, %.3fs to dump\n",
211+        LogPrintf("Dumped mempool: %.3fs to copy, %.3fs to dump, %.3f MB dumped to file\n",
212                   Ticks<SecondsDouble>(mid - start),
213-                  Ticks<SecondsDouble>(last - mid));
214+                  Ticks<SecondsDouble>(last - mid),
215+                  (float)fs::file_size(dump_path)/1000000);
    maflcko commented at 10:38 am on February 14, 2024:
    nit: Instead of c-style casts, you can use non-narrowing C++11 casts like float{thing}, or float(thing), if narrowing is required.
    kevkevinpal commented at 2:06 pm on February 15, 2024:
    instead, I opted not to cast the value and instead print out the number of bytes, let me know if MB is strongly preferred and I can find a solution.
  52. kevkevinpal force-pushed on Feb 15, 2024
  53. kevkevinpal force-pushed on Feb 15, 2024
  54. kevkevinpal force-pushed on Feb 15, 2024
  55. maflcko commented at 3:56 pm on February 16, 2024: member

    lgtm ACK dbdb7320252fd68415e8b76bad5a2169bd7da241

    Seems fine to log when starting to dump the mempool.

  56. DrahtBot requested review from epiccurious on Feb 16, 2024
  57. in src/kernel/mempool_persist.cpp:47 in dbdb732025 outdated 
    43@@ -44,7 +44,7 @@ bool LoadMempool(CTxMemPool& pool, const fs::path& load_path, Chainstate& active
44 
45     AutoFile file{opts.mockable_fopen_function(load_path, "rb")};
46     if (file.IsNull()) {
47-        LogPrintf("Failed to open mempool file from disk. Continuing anyway.\n");
48+        LogInfo("Failed to open mempool file from disk. Continuing anyway.\n");
    ajtowns commented at 4:30 am on February 21, 2024:
    Remove “from disk” here, if dropping “disk” mentions elsewhere?
    kevkevinpal commented at 1:24 am on February 23, 2024:
    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
    kevkevinpal commented at 1:25 am on February 23, 2024:
    updated in 34b6a8dadfb9a279f38fc828d6dff73209928f5d
  58. ajtowns commented at 4:32 am on February 21, 2024: contributor
    utACK dbdb7320252fd68415e8b76bad5a2169bd7da241
  59. DrahtBot removed review request from epiccurious on Feb 21, 2024
  60. DrahtBot requested review from epiccurious on Feb 21, 2024
  61. DrahtBot removed review request from epiccurious on Feb 21, 2024
  62. DrahtBot requested review from epiccurious on Feb 21, 2024
  63. DrahtBot removed review request from epiccurious on Feb 23, 2024
  64. DrahtBot requested review from epiccurious on Feb 23, 2024
  65. kevkevinpal force-pushed on Feb 23, 2024
  66. maflcko commented at 8:32 am on February 23, 2024: member
    ACK 34b6a8dadfb9a279f38fc828d6dff73209928f5d
  67. DrahtBot removed review request from epiccurious on Feb 23, 2024
  68. DrahtBot requested review from epiccurious on Feb 23, 2024
  69. DrahtBot requested review from ajtowns on Feb 23, 2024
  70. in src/kernel/mempool_persist.cpp:199 in 27251e89b6 outdated 
    195@@ -194,7 +196,7 @@ bool DumpMempool(const CTxMemPool& pool, const fs::path& dump_path, FopenFn mock
196 
197         file << mapDeltas;
198 
199-        LogPrintf("Writing %d unbroadcast transactions to disk.\n", unbroadcast_txids.size());
200+        LogInfo("Writing %d unbroadcast transactions to file.\n", unbroadcast_txids.size());
    glozow commented at 9:39 am on March 27, 2024:
    nit: this seems to be in the wrong commit
    kevkevinpal commented at 12:21 pm on March 27, 2024:
    Updated it is now in 4d5b55735bcf82847d748d24da5dbdbd1de8ef41
  71. glozow commented at 9:40 am on March 27, 2024: member
    utACK 34b6a8dadfb9a279f38fc828d6dff73209928f5d
  72. mempool: Log added for dumping mempool transactions to disk b9f04be870
  73. log: renamed disk to file so wording was more accurate 4d5b55735b
  74. kevkevinpal force-pushed on Mar 27, 2024
  75. maflcko commented at 6:54 pm on March 27, 2024: member
    cr-ACK 4d5b55735bcf82847d748d24da5dbdbd1de8ef41
  76. DrahtBot requested review from glozow on Mar 27, 2024
  77. glozow commented at 11:16 am on March 28, 2024: member
    reACK 4d5b557
  78. tdb3 commented at 11:24 am on March 28, 2024: contributor
    crACK. Will test shortly
  79. glozow merged this on Mar 28, 2024
  80. glozow closed this on Mar 28, 2024
  81. tdb3 commented at 2:41 pm on March 28, 2024: contributor

    Tested from master after merge. lgtm.

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

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


kevkevinpal DrahtBot maflcko theStack epiccurious ajtowns glozow tdb3


ajtowns epiccurious

Labels
Mempool

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2024-12-21 15:12 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me