cmpctblock: Improve logging of `cmpctblock` message reconstruction statistics [part of prefill series] #35724

If I understand correctly, removing this decrement assumes that the existing candidate came from the extrapool. However, it may have been inserted during the earlier mempool scan. Would it make sense to track the candidate’s source and decrement the corresponding counter?

Seems tangentially related to https://github.com/bitcoin/bitcoin/pull/35727

yeah, thanks for catching @w0xlt, I'll fix this after #35727, as that will make this change easier to make correct, marking this pr as draft for now

marking as resolvesed since #35727 was merged and I've updated this PR based on that.

The code has contradictory logging levels:

  if (ShouldTraceLog(...)) {
      LogDebug(...);
  }

Suggestion:

diff --git a/src/net_processing.cpp b/src/net_processing.cpp
index 1512a10c58..0117616314 100644
--- a/src/net_processing.cpp
+++ b/src/net_processing.cpp
@@ -2850,7 +2850,7 @@ void PeerManagerImpl::SendBlockTransactions(CNode& pfrom, Peer& peer, const CBlo
         LogDebug(BCLog::CMPCTBLOCK, "%s sent us a GETBLOCKTXN for block %s, sending a BLOCKTXN with %u txns. (%u bytes)", pfrom.LogPeer(), block.GetHash().ToString(), resp.txn.size(), tx_requested_size);
         if (util::log::ShouldTraceLog(BCLog::CMPCTBLOCK)) {
             for(const auto& txn : resp.txn) {
-                LogDebug(BCLog::CMPCTBLOCK, "    - txid: %s", txn->GetHash().ToString());
+                LogTrace(BCLog::CMPCTBLOCK, "    - txid: %s", txn->GetHash().ToString());
             }
         }
     }

Good catch @w0xlt. In addition to that, I fear the current log will be hard to analyze automatically or even grep for. It might make sense to include slightly more information than - txid: 4a5e1e4baab89f3a32518a88c31bc87f618f76673e2cc77ab2127b7afdeda33b in the line, similar to the reconstruction logging you changed above. How about:

"Sending {txid} to {peer} in BLOCKTXN"?

Alternatively, does it make sense to put all txids, maybe comma separated, into a single line?

Thanks, I've made it one log line instead.

nit: tiny preference for redundant_prefilled_mempool_count instead of redundant_prefilled_mp_count (and similar) here for readability. Not sure if saving the 5 characters is worth it.

Thanks, fixed

I'm not sure I agree with the approach of 78715aab9475b25bb10c82d2e8c1c827560b76ed. Incrementing the counts inline is very cheap. I can't see it be worth the code complexity to move these out. The next commit where the size of transactions are computed only for debug logging would make sense to do.

I moved the count inc/dec out because I thought it made the code easier to read, not for performance.

The problem is tracking the states, e.g. when decrementing because of a collision, we will have to check whether the tx_source is mempool or extra. it is definitely possible to do it inline, but IMO it's logic that is unrelated to compactblock reconstruction right in the middle of critical and subtle code, it's nice to scope all the logging code, and even though it's ~7 lines longer as-is, I think it makes it easier to read the function.

I could shorten the current thing to something like

if (util::log::ShouldDebugLog(BCLog::CMPCTBLOCK)) {
    for (size_t i = 0; i < txn_available.size(); i++) {
        if (tx_source[i] == TxSource::MEMPOOL) ++mempool_count;
        else if (tx_source[i] == TxSource::EXTRA) ++extra_count;
    }
}

but I think it is clearer as a switch.

nit: prefer prefixing ++ and --.

Thanks, fixed

We should have a comment here that these will only be set if debug logging is enabled.

Thanks, fixed.

I'm not sure this is the right data structure here. I think we can do this more cleanly with a std::map<Wtxid, size_t> and populate it below in the for (size_t i = 0; i < cmpctblock.prefilledtxn.size(); i++) { loop. Instead of calling pool->exists for each prefill (which takes the pool lock each time), we can take call GetIter after we take the pool lock later. This lets us avoid sorting the vector as well.

<details><summary>A quick example of how it could look</summary>

diff --git a/src/blockencodings.cpp b/src/blockencodings.cpp
index e2522f8781..7765353da1 100644
--- a/src/blockencodings.cpp
+++ b/src/blockencodings.cpp
@@ -16,6 +16,7 @@
 #include <util/log.h>
 #include <validation.h>
 
+#include <map>
 #include <unordered_map>
 
 CBlockHeaderAndShortTxIDs::CBlockHeaderAndShortTxIDs(const CBlock& block, uint64_t nonce)
@@ -70,21 +71,9 @@ ReadStatus PartiallyDownloadedBlock::InitData(const CBlockHeaderAndShortTxIDs& c
     header = cmpctblock.header;
     txn_available.resize(cmpctblock.BlockTxCount());
 
-    std::vector<Wtxid> extra_wtxids{};
-
-    bool debug_log = util::log::ShouldDebugLog(BCLog::CMPCTBLOCK);
-
-    if (debug_log) {
-        prefilled_count = cmpctblock.prefilledtxn.size();
-
-        // A sorted vec of extra_txn's for cheaply checking if prefills
-        // were redundant with the extrapool.
-        for (const auto& [id, tx] : extra_txn) {
-            extra_wtxids.push_back(id);
-        }
-        std::sort(extra_wtxids.begin(), extra_wtxids.end());
-    }
-
+    const bool debug_log{util::log::ShouldDebugLog(BCLog::CMPCTBLOCK)};
+    // Prefills not already in the mempool, used to check extra-pool redundancy.
+    std::map<Wtxid, size_t> leftover_prefills;
 
     int32_t lastprefilledindex = -1;
     for (size_t i = 0; i < cmpctblock.prefilledtxn.size(); i++) {
@@ -102,20 +91,14 @@ ReadStatus PartiallyDownloadedBlock::InitData(const CBlockHeaderAndShortTxIDs& c
         }
 
         if (debug_log) {
-            size_t tx_size = cmpctblock.prefilledtxn[i].tx->ComputeTotalSize();
+            const CTransactionRef& tx{cmpctblock.prefilledtxn[i].tx};
+            const size_t tx_size{tx->ComputeTotalSize()};
             prefilled_size += tx_size;
-
-            auto tx_wtxid =  cmpctblock.prefilledtxn[i].tx->GetWitnessHash();
-            if (pool->exists(tx_wtxid)) {
-                redundant_prefilled_mp_count++;
-                redundant_prefilled_mp_size += tx_size;
-            } else if (std::binary_search(extra_wtxids.begin(), extra_wtxids.end(), tx_wtxid)) {
-                redundant_prefilled_ep_count++;
-                redundant_prefilled_ep_size += tx_size;
-            }
+            leftover_prefills.emplace(tx->GetWitnessHash(), tx_size);
         }
         txn_available[lastprefilledindex] = cmpctblock.prefilledtxn[i].tx;
     }
+    if (debug_log) prefilled_count = cmpctblock.prefilledtxn.size();
 
     // Calculate map of txids -> positions and check mempool to see what we have (or don't)
     // Because well-formed cmpctblock messages will have a (relatively) uniform distribution
@@ -148,6 +131,17 @@ ReadStatus PartiallyDownloadedBlock::InitData(const CBlockHeaderAndShortTxIDs& c
     size_t available_count = 0;
     {
     LOCK(pool->cs);
+    if (debug_log) {
+        for (auto it{leftover_prefills.begin()}; it != leftover_prefills.end();) {
+            if (pool->GetIter(it->first)) {
+                ++redundant_prefilled_mp_count;
+                redundant_prefilled_mp_size += it->second;
+                it = leftover_prefills.erase(it);
+            } else {
+                ++it;
+            }
+        }
+    }
     for (const auto& [wtxid, txit] : pool->txns_randomized) {
         uint64_t shortid = cmpctblock.GetShortID(wtxid);
         std::unordered_map<uint64_t, uint16_t>::iterator idit = shorttxids.find(shortid);
@@ -201,7 +195,16 @@ ReadStatus PartiallyDownloadedBlock::InitData(const CBlockHeaderAndShortTxIDs& c
             break;
     }
 
-    if (util::log::ShouldDebugLog(BCLog::CMPCTBLOCK)) {
+    if (debug_log) {
+        for (const auto& [id, tx] : extra_txn) {
+            if (!tx) continue;
+            const auto it{leftover_prefills.find(id)};
+            if (it == leftover_prefills.end()) continue;
+            ++redundant_prefilled_ep_count;
+            redundant_prefilled_ep_size += it->second;
+            leftover_prefills.erase(it);
+        }
+
         Assume(txn_available.size() == tx_source.size());
         for (size_t i = 0; i < txn_available.size(); i++) {
             switch (tx_source[i]) {

</details>