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

   <!--e57a25ab6845829454e8d69fc972939a-->

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

   <!--006a51241073e994b41acfe9ec718e94-->

   Code Coverage & Benchmarks

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

   <!--021abf342d371248e50ceaed478a90ca-->

   Reviews

   See the guideline for information on the review process.

   Type	Reviewers
   ACK	w0xlt, instagibbs, 1440000bytes

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

   <!--5faf32d7da4f0f540f40219e4f7537a3-->

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

       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. davidgumberg force-pushed on May 22, 2025
13. in src/net_processing.cpp:2498 in d2426b716b outdated

    2494 | @@ -2495,6 +2495,7 @@ uint32_t PeerManagerImpl::GetFetchFlags(const Peer& peer) const
    2495 |  void PeerManagerImpl::SendBlockTransactions(CNode& pfrom, Peer& peer, const CBlock& block, const BlockTransactionsRequest& req)
    2496 |  {
    2497 |      BlockTransactions resp(req);
    2498 | +    unsigned int tx_missing_size = 0;
    

    ---

    ---

    

    w0xlt commented at 6:36 PM on May 28, 2025:

    Is this variable being used ?

    ---

    

    davidgumberg commented at 6:42 PM on May 28, 2025:

    Thanks for catching this, it's printed below in the added LogDebug() message but I forgot to increment this.

14. 
    w0xlt commented at 6:39 PM on May 28, 2025: contributor

    Approach ACK.

    The first item "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." could be improved by adding another message to the end of PartiallyDownloadedBlock::InitData indicating that execution has completed and how long it took.

15. log: Size of missing tx'es when reconstructing compact block 3733ed2dae
16. davidgumberg force-pushed on May 28, 2025
17. 
    davidgumberg commented at 6:48 PM on May 28, 2025: contributor

    Rebased to address @w0xlt feedback.

18. 
    w0xlt commented at 6:51 PM on May 28, 2025: contributor

    ACK https://github.com/bitcoin/bitcoin/pull/32582/commits/2ff3a05fda11563fed303ef7a171f8edaeac111a

19. DrahtBot requested review from instagibbs on May 28, 2025
20. in src/net_processing.cpp:2498 in 2ff3a05fda outdated

    2494 | @@ -2495,14 +2495,17 @@ uint32_t PeerManagerImpl::GetFetchFlags(const Peer& peer) const
    2495 |  void PeerManagerImpl::SendBlockTransactions(CNode& pfrom, Peer& peer, const CBlock& block, const BlockTransactionsRequest& req)
    2496 |  {
    2497 |      BlockTransactions resp(req);
    2498 | +    unsigned int tx_missing_size = 0;
    

    ---

    ---

    

    instagibbs commented at 6:58 PM on May 28, 2025:

    nit

        unsigned int tx_requested_size = 0;
    

    ---

    

    davidgumberg commented at 8:33 PM on May 28, 2025:

    Fixed, thanks.

21. instagibbs approved
22. 
    instagibbs commented at 6:58 PM on May 28, 2025: member

    ACK 2ff3a05fda11563fed303ef7a171f8edaeac111a

23. log: Stats when fulfilling GETBLOCKTXN 83df64d749
24. davidgumberg force-pushed on May 28, 2025
25. 
    davidgumberg commented at 8:33 PM on May 28, 2025: contributor

    Rebased to address @instagibbs feedback.

26. 
    w0xlt commented at 8:45 PM on May 28, 2025: contributor

    reACK https://github.com/bitcoin/bitcoin/pull/32582/commits/83df64d7491b8271f7dfa2aea30f055102e3ff39

27. DrahtBot requested review from instagibbs on May 28, 2025
28. 
    instagibbs commented at 8:46 PM on May 28, 2025: member

    reACK https://github.com/bitcoin/bitcoin/pull/32582/commits/83df64d7491b8271f7dfa2aea30f055102e3ff39

29. 
    1440000bytes commented at 12:08 AM on May 29, 2025: none

    ACK 83df64d7491b8271f7dfa2aea30f055102e3ff39

    <details> <summary>Signature</summary>

    <pre> -----BEGIN PGP SIGNED MESSAGE----- Hash: SHA512 ACK 83df64d7491b8271f7dfa2aea30f055102e3ff39 -----BEGIN PGP SIGNATURE----- iHUEARYKAB0WIQSSUwYqT5LWNFkIXKYtIwUgISpZAQUCaDekrAAKCRAtIwUgISpZ Aa86AP0cOFEVIMWCd7bhNekXwpmdgIVlMV9LdU2YQ40r6TdZJQEA8hVtCHmD2sMN pkHDM0gALAeez7FyJQplX2HYYqh/tgU= =ldiS -----END PGP SIGNATURE----- </pre>

    </details>

30. fanquake merged this on May 29, 2025
31. fanquake closed this on May 29, 2025

    ---

32. 
    0xB10C commented at 10:50 AM on June 3, 2025: contributor

    LGTM post-merge ACK. Will run this with compact block logging enabled on a few of my nodes.

33. sedited referenced this in commit f236a50dc1 on Jun 14, 2025
34. yuvicc referenced this in commit 069643f094 on Jul 6, 2025
35. yuvicc referenced this in commit 22f55cf11d on Aug 26, 2025
36. ajtowns referenced this in commit d9c3da1b17 on Sep 3, 2025
37. bug-castercv502 referenced this in commit cfdba67027 on Sep 28, 2025
38. stickies-v referenced this in commit a19c56cd7c on Nov 4, 2025
39. achow101 referenced this in commit a365c9fe1f on Jan 20, 2026
40. Kino1994 referenced this in commit 2a30f225b1 on Jun 28, 2026
41. Kino1994 referenced this in commit 7be848cb77 on Jun 28, 2026
42. BigcoinBGC referenced this in commit 2ec112b3a5 on Jun 30, 2026
43. BigcoinBGC referenced this in commit 1926717c0c on Jun 30, 2026
44. bitcoin locked this on Jul 31, 2026

Contributors

davidgumbergDrahtBot1440000bytesfanquakeinstagibbsw0xlt0xB10C

Review Requested
instagibbs