tracing: misc follow-ups to 22902

- mention 'Lost X events' workaround
- clarify flush tracepoint docs
- fix typo in tracepoint context
- clarify flush for prune
    The documentation and examples for the `fFlushForPrune` argument
    of the utxocache flush tracepoint weren't clear without looking
    at the code.

    See these comments: https://github.com/bitcoin/bitcoin/pull/22902#issuecomment-987094612

- doc: note that there can be temporary UTXO caches
    Bitcoin Core uses temporary clones of it's _main_ UTXO cache in some
    places. The utxocache:add and :spent tracepoints are triggered when
    temporary caches are changed too. This is documented.

4 files changed, 36 insertions, 17 deletions

diff --git a/contrib/tracing/README.md b/contrib/tracing/README.md
index 05d2c8f9cf..a409a23ef8 100644
--- a/contrib/tracing/README.md
+++ b/contrib/tracing/README.md
@@ -262,7 +262,13 @@ uncached from the UTXO set. Based on the `utxocache:add`, `utxocache:spend` and
 $ bpftrace contrib/tracing/log_utxos.bt
 ```
 
-It should produce an output similar to the following.
+This should produce an output similar to the following. If you see bpftrace
+warnings like `Lost 24 events`, the eBPF perf ring-buffer is filled faster
+than it is being read. You can increase the ring-buffer size by setting the
+ENV variable `BPFTRACE_PERF_RB_PAGES` (default 64) at a cost of higher
+memory usage. See the [bpftrace reference guide] for more information.
+
+[bpftrace reference guide]: https://github.com/iovisor/bpftrace/blob/master/docs/reference_guide.md#98-bpftrace_perf_rb_pages
 
 ```bash
 Attaching 4 probes...
diff --git a/contrib/tracing/log_utxocache_flush.py b/contrib/tracing/log_utxocache_flush.py
index 3326346b50..24ede0fe14 100755
--- a/contrib/tracing/log_utxocache_flush.py
+++ b/contrib/tracing/log_utxocache_flush.py
@@ -13,13 +13,14 @@ from bcc import BPF, USDT
 # a sandboxed Linux kernel VM.
 program = """
 # include <uapi/linux/ptrace.h>
+
 struct data_t
 {
   u64 duration;
   u32 mode;
   u64 coins_count;
   u64 coins_mem_usage;
-  bool is_flush_prune;
+  bool is_flush_for_prune;
 };
 
 // BPF perf buffer to push the data to user space.
@@ -31,7 +32,7 @@ int trace_flush(struct pt_regs *ctx) {
   bpf_usdt_readarg(2, ctx, &data.mode);
   bpf_usdt_readarg(3, ctx, &data.coins_count);
   bpf_usdt_readarg(4, ctx, &data.coins_mem_usage);
-  bpf_usdt_readarg(5, ctx, &data.is_flush_prune);
+  bpf_usdt_readarg(5, ctx, &data.is_flush_for_prune);
   flush.perf_submit(ctx, &data, sizeof(data));
   return 0;
 }
@@ -52,7 +53,7 @@ class Data(ctypes.Structure):
         ("mode", ctypes.c_uint32),
         ("coins_count", ctypes.c_uint64),
         ("coins_mem_usage", ctypes.c_uint64),
-        ("is_flush_prune", ctypes.c_bool),
+        ("is_flush_for_prune", ctypes.c_bool)
     ]
 
 
@@ -62,7 +63,7 @@ def print_event(event):
         FLUSH_MODES[event.mode],
         event.coins_count,
         "%.2f kB" % (event.coins_mem_usage/1000),
-        event.is_flush_prune,
+        event.is_flush_for_prune
     ))
 
 
@@ -85,7 +86,7 @@ def main(bitcoind_path):
     print("Logging utxocache flushes. Ctrl-C to end...")
     print("%-15s %-10s %-15s %-15s %-8s" % ("Duration (µs)", "Mode",
                                             "Coins Count", "Memory Usage",
-                                            "Prune"))
+                                            "Flush for Prune"))
 
     while True:
         try:
diff --git a/contrib/tracing/log_utxos.bt b/contrib/tracing/log_utxos.bt
index 0d47f3d62b..54d5010f82 100755
--- a/contrib/tracing/log_utxos.bt
+++ b/contrib/tracing/log_utxos.bt
@@ -7,7 +7,7 @@
   bpftrace contrib/tracing/log_utxos.bt
 
   This script requires a 'bitcoind' binary compiled with eBPF support and the
-  'utxochache' tracepoints. By default, it's assumed that 'bitcoind' is
+  'utxocache' tracepoints. By default, it's assumed that 'bitcoind' is
   located in './src/bitcoind'. This can be modified in the script below.
 
   NOTE: requires bpftrace v0.12.0 or above.
diff --git a/doc/tracing.md b/doc/tracing.md
index 68de376043..6ec6a6c218 100644
--- a/doc/tracing.md
+++ b/doc/tracing.md
@@ -110,22 +110,31 @@ Arguments passed:
 
 ### Context `utxocache`
 
+The following tracepoints cover the in-memory UTXO cache. UTXOs are, for example,
+added to and removed (spent) from the cache when we connect a new block.
+**Note**: Bitcoin Core uses temporary clones of the _main_ UTXO cache
+(`chainstate.CoinsTip()`). For example, the RPCs `generateblock` and
+`getblocktemplate` call `TestBlockValidity()`, which applies the UTXO set
+changes to a temporary cache. Similarly, mempool consistency checks, which are
+frequent on regtest, also apply the the UTXO set changes to a temporary cache.
+Changes to the _main_ UTXO cache and to temporary caches trigger the tracepoints.
+We can't tell if a temporary cache or the _main_ cache was changed.
+
 #### Tracepoint `utxocache:flush`
 
-Is called *after* the caches are flushed depending on the mode
-`CChainState::FlushStateToDisk` is called with.
+Is called *after* the in-memory UTXO cache is flushed.
 
 Arguments passed:
-1. Duration in microseconds as `int64`
+1. Time it took to flush the cache microseconds as `int64`
 2. Flush state mode as `uint32`. It's an enumerator class with values `0`
    (`NONE`), `1` (`IF_NEEDED`), `2` (`PERIODIC`), `3` (`ALWAYS`)
-3. Number of coins flushed as `uint64`
-4. Memory usage in bytes as `uint64`
-5. If the flush was pruned as `bool`
+3. Cache size (number of coins) before the flush as `uint64`
+4. Cache memory usage in bytes as `uint64`
+5. If pruning caused the flush as `bool`
 
 #### Tracepoint `utxocache:add`
 
-It is called when a new coin is added to the UTXO cache.
+Is called when a coin is added to a UTXO cache. This can be a temporary UTXO cache too.
 
 Arguments passed:
 1. Transaction ID (hash) as `pointer to unsigned chars` (i.e. 32 bytes in little-endian)
@@ -136,7 +145,7 @@ Arguments passed:
 
 #### Tracepoint `utxocache:spent`
 
-It is called when a coin is spent from the UTXO cache.
+Is called when a coin is spent from a UTXO cache. This can be a temporary UTXO cache too.
 
 Arguments passed:
 1. Transaction ID (hash) as `pointer to unsigned chars` (i.e. 32 bytes in little-endian)
@@ -147,14 +156,17 @@ Arguments passed:
 
 #### Tracepoint `utxocache:uncache`
 
-It is called when the UTXO with the given outpoint is removed from the cache.
+Is called when a coin is purposefully unloaded from a UTXO cache. This
+happens, for example, when we load an UTXO into a cache when trying to accept
+a transaction that turns out to be invalid. The loaded UTXO is uncached to avoid
+filling our UTXO cache up with irrelevant UTXOs.
 
 Arguments passed:
 1. Transaction ID (hash) as `pointer to unsigned chars` (i.e. 32 bytes in little-endian)
 2. Output index as `uint32`
 3. Block height the coin was uncached, as `uint32`
 4. Value of the coin as `int64`
-. If the coin is a coinbase as `bool`
+5. If the coin is a coinbase as `bool`
 
 ## Adding tracepoints to Bitcoin Core