log: Additional compact block logging

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.

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.
Logs the size of the transactions which a node did not have in its mempool and was forced to request.
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

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

DrahtBot added the label Utils/log/libs on May 22, 2025

1440000bytes commented at 12:30 pm on May 22, 2025: none

Concept ACK

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

cc @instagibbs

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.

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.

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.

instagibbs commented at 5:42 pm on May 22, 2025: member

concept ACK

seem like sensible things to be reporting

log: Log start of compact block initialization. 36bcee05dc

davidgumberg force-pushed on May 22, 2025

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.

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.

log: Size of missing tx'es when reconstructing compact block 3733ed2dae

davidgumberg force-pushed on May 28, 2025

davidgumberg commented at 6:48 pm on May 28, 2025: contributor

Rebased to address @w0xlt feedback.

w0xlt commented at 6:51 pm on May 28, 2025: contributor

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

DrahtBot requested review from instagibbs on May 28, 2025

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

0    unsigned int tx_requested_size = 0;

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

Fixed, thanks.

instagibbs approved

instagibbs commented at 6:58 pm on May 28, 2025: member

ACK 2ff3a05fda11563fed303ef7a171f8edaeac111a

log: Stats when fulfilling GETBLOCKTXN 83df64d749

davidgumberg force-pushed on May 28, 2025

davidgumberg commented at 8:33 pm on May 28, 2025: contributor

Rebased to address @instagibbs feedback.

w0xlt commented at 8:45 pm on May 28, 2025: contributor

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

DrahtBot requested review from instagibbs on May 28, 2025

instagibbs commented at 8:46 pm on May 28, 2025: member

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

1440000bytes commented at 0:08 am on May 29, 2025: none

ACK 83df64d7491b8271f7dfa2aea30f055102e3ff39

fanquake merged this on May 29, 2025

fanquake closed this on May 29, 2025

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.

log: Additional compact block logging #32582

Code Coverage & Benchmarks

Reviews