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. TheCharlatan referenced this in commit f236a50dc1 on Jun 14, 2025
34. yuvicc referenced this in commit 069643f094 on Jul 6, 2025

Contributors

davidgumbergDrahtBot1440000bytesfanquakeinstagibbsw0xlt0xB10C

Review Requested
instagibbs