log: Additional compact block logging #32582

1. 
   davidgumberg commented at 2:00 am on May 22, 2025: contributor

   This PR adds some additional logging to help measure performance of compact block reconstruction.

   1. Adds a message to the beginning of PartiallyDownloadedBlock::InitData() so that that the logs indicate the amount of time it takes to populate a compact block from mempool transactions.
   2. Logs the size of the transactions which a node did not have in its mempool and was forced to request.
   3. Logs the size and number of transactions that a node sends to it’s peer in a BLOCKTXN to fulfill a compact block GETBLOCKTXN request.

   Relevant to this discussion on delving bitcoin: https://delvingbitcoin.org/t/stats-on-compact-block-reconstructions/1052

2. 
   DrahtBot commented at 2:00 am on May 22, 2025: contributor

   The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

   Code Coverage & Benchmarks

   For details see: https://corecheck.dev/bitcoin/bitcoin/pulls/32582.

   Reviews

   See the guideline for information on the review process.

   Type	Reviewers
   Concept ACK	1440000bytes, instagibbs

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

3. DrahtBot added the label Utils/log/libs on May 22, 2025
4. 
   1440000bytes commented at 12:30 pm on May 22, 2025: none

   Concept ACK
5. 
   fanquake commented at 5:15 pm on May 22, 2025: member

   cc @instagibbs
6. in src/blockencodings.cpp:49 in d83e3eecde outdated

   44@@ -45,9 +45,8 @@ uint64_t CBlockHeaderAndShortTxIDs::GetShortID(const Wtxid& wtxid) const {
   45     return SipHashUint256(shorttxidk0, shorttxidk1, wtxid) & 0xffffffffffffL;
   46 }
   47 
   48-
   49-
   50 ReadStatus PartiallyDownloadedBlock::InitData(const CBlockHeaderAndShortTxIDs& cmpctblock, const std::vector<CTransactionRef>& extra_txn) {
   51+    LogDebug(BCLog::CMPCTBLOCK, "Initializing PartiallyDownloadedBlock for block %s using a cmpctblock of size %lu\n", cmpctblock.header.GetHash().ToString(), GetSerializeSize(cmpctblock));
   

   ---

   ---

   

   instagibbs commented at 5:38 pm on May 22, 2025:

   to make it more explicit it’s not a tx count thing

   0    LogDebug(BCLog::CMPCTBLOCK, "Initializing PartiallyDownloadedBlock for block %s using a cmpctblock of %lu bytes\n", cmpctblock.header.GetHash().ToString(), GetSerializeSize(cmpctblock));
   

   ---

   

   davidgumberg commented at 8:26 pm on May 22, 2025:

   Made it this way to match the log line below, I applied your suggestion here and below.
7. in src/blockencodings.cpp:49 in fb4d154cef outdated

   45@@ -46,7 +46,7 @@ uint64_t CBlockHeaderAndShortTxIDs::GetShortID(const Wtxid& wtxid) const {
   46 }
   47 
   48 ReadStatus PartiallyDownloadedBlock::InitData(const CBlockHeaderAndShortTxIDs& cmpctblock, const std::vector<CTransactionRef>& extra_txn) {
   49-    LogDebug(BCLog::CMPCTBLOCK, "Initializing PartiallyDownloadedBlock for block %s using a cmpctblock of size %lu\n", cmpctblock.header.GetHash().ToString(), GetSerializeSize(cmpctblock));
   50+    LogDebug(BCLog::CMPCTBLOCK, "Initializing PartiallyDownloadedBlock for block %s.", cmpctblock.header.GetHash().ToString());
   

   ---

   ---

   

   instagibbs commented at 5:39 pm on May 22, 2025:

   seems odd to add it then modify it immediately next commit, can be one commit?

   ---

   

   davidgumberg commented at 8:26 pm on May 22, 2025:

   Borked a fixup commit, thanks.
8. in src/net_processing.cpp:2507 in dbb9a76d7c outdated

   2503@@ -2503,6 +2504,7 @@ void PeerManagerImpl::SendBlockTransactions(CNode& pfrom, Peer& peer, const CBlo
   2504         resp.txn[i] = block.vtx[req.indexes[i]];
   2505     }
   2506 
   2507+    LogDebug(BCLog::CMPCTBLOCK, "Peer was missing transactions in block %s, sending a BLOCKTXN with %u txns. (size: %u bytes)\n", block.GetHash().ToString(), resp.txn.size(), tx_missing_size);
   

   ---

   ---

   

   instagibbs commented at 5:40 pm on May 22, 2025:

   we don’t know they were missing them really, just mention they asked for them for the specific block?

   ---

   

   davidgumberg commented at 8:32 pm on May 22, 2025:

   Thanks, fixed.
9. 
   instagibbs commented at 5:42 pm on May 22, 2025: member

   concept ACK

   seem like sensible things to be reporting

10. log: Log start of compact block initialization. 36bcee05dc
11. davidgumberg force-pushed on May 22, 2025
12. log: Size of missing tx'es from compact block 0323b0ddb4
13. log: Add message when we fulfill GETBLOCKTXN d2426b716b
14. davidgumberg force-pushed on May 22, 2025

Contributors
davidgumberg DrahtBot 1440000bytes fanquake instagibbs

Labels
Utils/log/libs