Merge bitcoin/bitcoin#22902: tracing: utxocache tracepoints

15b8ba5 [tracing] tracepoints to utxocache add, spent and uncache (Arnab Sen)
56f0a04 [tracing] tracepoint for utxocache flushes (Arnab Sen)

Pull request description:

  This PR adds some of the UTXO set cache tracepoints proposed in bitcoin/bitcoin#20981 (comment). The first tracepoints were added in bitcoin#22006.

  tracepoint | description
  -- | --
  `utxocache:flush` | Is called after the caches and indexes are flushed
  `utxocache:add` | when a new coin is added to the UTXO cache
  `utxocache:spent` | when a coin is spent
  `utxocache:uncache` | when coin is removed from the UTXO cache

  The tracepoints are further documented in `docs/tracing.md` and the usage is shown via the two newly added example scripts in `contrib/tracing/`.

Top commit has no ACKs.

Tree-SHA512: 53ba6c2811c7fed08aa608a888bff83214e754b0f50621e83e4f81e95bc22d21f7f956096d12858d8e85240aa226431845995682eaaf55e93016c5b8f4c9282b

contrib/tracing/log_utxocache_flush.py

@@ -0,0 +1,107 @@
+#!/usr/bin/env python3
+
+import sys
+import ctypes
+from bcc import BPF, USDT
+
+"""Example logging Bitcoin Core utxo set cache flushes utilizing
+    the utxocache:flush tracepoint."""
+
+# USAGE:  ./contrib/tracing/log_utxocache_flush.py path/to/bitcoind
+
+# BCC: The C program to be compiled to an eBPF program (by BCC) and loaded into
+# 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_full_flush;
+};
+
+// BPF perf buffer to push the data to user space.
+BPF_PERF_OUTPUT(flush);
+
+int trace_flush(struct pt_regs *ctx) {
+  struct data_t data = {};
+  bpf_usdt_readarg(1, ctx, &data.duration);
+  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_full_flush);
+  flush.perf_submit(ctx, &data, sizeof(data));
+  return 0;
+}
+"""
+
+FLUSH_MODES = [
+    'NONE',
+    'IF_NEEDED',
+    'PERIODIC',
+    'ALWAYS'
+]
+
+
+class Data(ctypes.Structure):
+    # define output data structure corresponding to struct data_t
+    _fields_ = [
+        ("duration", ctypes.c_uint64),
+        ("mode", ctypes.c_uint32),
+        ("coins_count", ctypes.c_uint64),
+        ("coins_mem_usage", ctypes.c_uint64),
+        ("is_flush_prune", ctypes.c_bool),
+        ("is_full_flush", ctypes.c_bool)
+    ]
+
+
+def print_event(event):
+    print("%-15d %-10s %-15d %-15s %-8s %-8s" % (
+        event.duration,
+        FLUSH_MODES[event.mode],
+        event.coins_count,
+        "%.2f kB" % (event.coins_mem_usage/1000),
+        event.is_flush_prune,
+        event.is_full_flush
+    ))
+
+
+def main(bitcoind_path):
+    bitcoind_with_usdts = USDT(path=str(bitcoind_path))
+
+    # attaching the trace functions defined in the BPF program
+    # to the tracepoints
+    bitcoind_with_usdts.enable_probe(
+        probe="flush", fn_name="trace_flush")
+    b = BPF(text=program, usdt_contexts=[bitcoind_with_usdts])
+
+    def handle_flush(_, data, size):
+        """ Coins Flush handler.
+          Called each time coin caches and indexes are flushed."""
+        event = ctypes.cast(data, ctypes.POINTER(Data)).contents
+        print_event(event)
+
+    b["flush"].open_perf_buffer(handle_flush)
+    print("Logging utxocache flushes. Ctrl-C to end...")
+    print("%-15s %-10s %-15s %-15s %-8s %-8s" % ("Duration (µs)", "Mode",
+                                                 "Coins Count", "Memory Usage",
+                                                 "Prune", "Full Flush"))
+
+    while True:
+        try:
+            b.perf_buffer_poll()
+        except KeyboardInterrupt:
+            exit(0)
+
+
+if __name__ == "__main__":
+    if len(sys.argv) < 2:
+        print("USAGE: ", sys.argv[0], "path/to/bitcoind")
+        exit(1)
+
+    path = sys.argv[1]
+    main(path)

contrib/tracing/log_utxos.py

@@ -0,0 +1,145 @@
+#!/usr/bin/env python3
+
+import sys
+import ctypes
+from bcc import BPF, USDT
+
+""" Example logging Bitcoin Core utxo set add/spend/uncache coin events.
+utilizing USDT probes and the utxocache:add, utxocache:spent,
+utxocache:uncache tracepoint."""
+
+# USAGE:  ./contrib/tracing/log_utxos.py path/to/bitcoind
+
+program = """
+# include <uapi/linux/ptrace.h>
+#define MAX_HASH_SIZE 64
+struct coin_data
+{
+  char hash[MAX_HASH_SIZE];
+  u32 index;
+  u32 height;
+  long value;
+  u64 usage;
+  u64 cachedCoinsCount;
+  bool isCoinBase;
+};
+
+BPF_PERF_OUTPUT(add);
+BPF_PERF_OUTPUT(spent);
+BPF_PERF_OUTPUT(uncache);
+
+int trace_add_coin(struct pt_regs *ctx) {
+    struct coin_data data = {};
+    bpf_usdt_readarg_p(1, ctx, &data.hash, MAX_HASH_SIZE);
+    bpf_usdt_readarg(2, ctx, &data.index);
+    bpf_usdt_readarg(3, ctx, &data.height);
+    bpf_usdt_readarg(4, ctx, &data.value);
+    bpf_usdt_readarg(5, ctx, &data.usage);
+    bpf_usdt_readarg(6, ctx, &data.cachedCoinsCount);
+    bpf_usdt_readarg(7, ctx, &data.isCoinBase);
+    add.perf_submit(ctx, &data, sizeof(data));
+    return 0;
+}
+
+int trace_spend_coin(struct pt_regs *ctx) {
+    struct coin_data data = {};
+    bpf_usdt_readarg_p(1, ctx, &data.hash, MAX_HASH_SIZE);
+    bpf_usdt_readarg(2, ctx, &data.index);
+    bpf_usdt_readarg(3, ctx, &data.height);
+    bpf_usdt_readarg(4, ctx, &data.value);
+    bpf_usdt_readarg(5, ctx, &data.usage);
+    bpf_usdt_readarg(6, ctx, &data.cachedCoinsCount);
+    bpf_usdt_readarg(7, ctx, &data.isCoinBase);
+    spent.perf_submit(ctx, &data, sizeof(data));
+    return 0;
+}
+
+int trace_uncached_coin(struct pt_regs *ctx) {
+    struct coin_data data = {};
+    bpf_usdt_readarg_p(1, ctx, &data.hash, MAX_HASH_SIZE);
+    bpf_usdt_readarg(2, ctx, &data.index);
+    bpf_usdt_readarg(3, ctx, &data.height);
+    bpf_usdt_readarg(4, ctx, &data.value);
+    bpf_usdt_readarg(5, ctx, &data.usage);
+    bpf_usdt_readarg(6, ctx, &data.cachedCoinsCount);
+    bpf_usdt_readarg(7, ctx, &data.isCoinBase);
+    uncache.perf_submit(ctx, &data, sizeof(data));
+    return 0;
+}
+"""
+
+
+class Data(ctypes.Structure):
+    # define output data structure corresponding to struct data_t
+    _fields_ = [
+        ("hash", ctypes.c_char * 64),
+        ("index", ctypes.c_uint32),
+        ("height", ctypes.c_uint32),
+        ("value", ctypes.c_uint64),
+        ("usage", ctypes.c_uint64),
+        ("cachedCoinsCount", ctypes.c_uint64),
+        ("isCoinBase", ctypes.c_bool),
+    ]
+
+
+def print_event(event, action):
+    print("%-70s %-10s %-10d %-15d %-10s %-15d %d" %
+          (f"{event.hash.decode('ASCII')}:{str(event.index)}",
+           action, event.height,
+           event.value,
+           "YES" if event.isCoinBase else "NO",
+           event.usage,
+           event.cachedCoinsCount))
+
+
+def main(bitcoind_path):
+    bitcoind_with_usdts = USDT(path=str(bitcoind_path))
+    bitcoind_with_usdts.enable_probe(
+        probe="add", fn_name="trace_add_coin")
+    bitcoind_with_usdts.enable_probe(
+        probe="spent", fn_name="trace_spend_coin")
+    bitcoind_with_usdts.enable_probe(
+        probe="uncache", fn_name="trace_uncached_coin")
+
+    b = BPF(text=program, usdt_contexts=[bitcoind_with_usdts])
+
+    def handle_coins_added(_, data, size):
+        event = ctypes.cast(data, ctypes.POINTER(Data)).contents
+        print_event(event, "Add")
+
+    def handle_coins_spent(_, data, size):
+        event = ctypes.cast(data, ctypes.POINTER(Data)).contents
+        print_event(event, "Spent")
+
+    def handle_coins_uncached(_, data, size):
+        event = ctypes.cast(data, ctypes.POINTER(Data)).contents
+        print_event(event, "Uncache")
+
+    b["add"].open_perf_buffer(handle_coins_added)
+    b["spent"].open_perf_buffer(handle_coins_spent)
+    b["uncache"].open_perf_buffer(handle_coins_uncached)
+
+    print("Logging Add, Spend and Uncache in the UTXO set. Ctrl-C to end...")
+    print("%-70s %-10s %-10s %-15s %-10s %-15s %s" %
+          ("Outpoint",
+           "Action",
+           "Height",
+           "Value",
+           "Coinbase",
+           "Memory Usage",
+           "Cached Coins"))
+
+    while True:
+        try:
+            b.perf_buffer_poll()
+        except KeyboardInterrupt:
+            exit(0)
+
+
+if __name__ == "__main__":
+    if len(sys.argv) < 2:
+        print("USAGE: ", sys.argv[0], "path/to/bitcoind")
+        exit(1)
+
+    path = sys.argv[1]
+    main(path)

doc/tracing.md

@@ -115,6 +115,64 @@ details.
 
 [bpftrace argument limit]: #bpftrace-argument-limit
 
+### Context `utxocache`
+
+#### Tracepoint `utxocache:flush`
+
+Is called *after* the caches and indexes are flushed depending on the mode
+`CChainState::FlushStateToDisk` is called with.
+
+Arguments passed:
+1. Duration in 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`
+6. If it was full flush as `bool`
+
+#### Tracepoint `utxocache:add`
+
+It is called when a new coin is added to the UTXO cache.
+
+Arguments passed:
+1. Transaction ID (hash) as `pointer to C-style String` (64 characters)
+2. Output index as `uint32`
+3. Block height the coin was added to the UTXO-set as  `uint32`
+4. Value of the coin as `int64`
+5. Cached coins usage as `uint64`
+6. Cached coins count as `uint64`
+7. If the coin is a coinbase as `bool`
+8. Transaction hash as `pointer to unsigned chars` (i.e. 32 bytes in little-endian)
+
+#### Tracepoint `utxocache:spent`
+
+It is called when a coin is spent from the UTXO cache.
+
+Arguments passed:
+1. Transaction ID (hash) as `pointer to C-style String` (64 characters)
+2. Output index as `uint32`
+3. Block height the coin was spent, as `uint32`
+4. Value of the coin as `int64`
+5. Cached coins usage as `uint64`
+6. Cached coins count as `uint64`
+7. If the coin is a coinbase as `bool`
+8. Transaction hash as `pointer to unsigned chars` (i.e. 32 bytes in little-endian)
+
+#### Tracepoint `utxocache:uncache`
+
+It is called when the UTXO with the given outpoint is removed from the cache.
+
+Arguments passed:
+1. Transaction ID (hash) as `pointer to C-style String` (64 characters)
+2. Output index as `uint32`
+3. Block height the coin was uncached, as `uint32`
+4. Value of the coin as `int64`
+5. Cached coins usage as `uint64`
+6. Cached coins count as `uint64`
+7. If the coin is a coinbase as `bool`
+8. Transaction hash as `pointer to unsigned chars` (i.e. 32 bytes in little-endian)
+
 ## Adding tracepoints to Bitcoin Core
 
 To add a new tracepoint, `#include <util/trace.h>` in the compilation unit where

src/coins.cpp

@@ -7,6 +7,7 @@
 #include <consensus/consensus.h>
 #include <logging.h>
 #include <random.h>
+#include <util/trace.h>
 #include <version.h>
 
 bool CCoinsView::GetCoin(const COutPoint &outpoint, Coin &coin) const { return false; }
@@ -95,6 +96,15 @@ void CCoinsViewCache::AddCoin(const COutPoint &outpoint, Coin&& coin, bool possi
     it->second.coin = std::move(coin);
     it->second.flags |= CCoinsCacheEntry::DIRTY | (fresh ? CCoinsCacheEntry::FRESH : 0);
     cachedCoinsUsage += it->second.coin.DynamicMemoryUsage();
+    TRACE8(utxocache, add,
+           outpoint.hash.ToString().c_str(),
+           (uint32_t)outpoint.n,
+           (uint32_t)coin.nHeight,
+           (int64_t)coin.out.nValue,
+           (uint64_t)cachedCoinsUsage,
+           (uint64_t)cacheCoins.size(),
+           (bool)coin.IsCoinBase(),
+           outpoint.hash.data());
 }
 
 void CCoinsViewCache::EmplaceCoinInternalDANGER(COutPoint&& outpoint, Coin&& coin) {
@@ -120,6 +130,15 @@ bool CCoinsViewCache::SpendCoin(const COutPoint &outpoint, Coin* moveout) {
     CCoinsMap::iterator it = FetchCoin(outpoint);
     if (it == cacheCoins.end()) return false;
     cachedCoinsUsage -= it->second.coin.DynamicMemoryUsage();
+    TRACE8(utxocache, spent,
+           outpoint.hash.ToString().c_str(),
+           (uint32_t)outpoint.n,
+           (uint32_t)it->second.coin.nHeight,
+           (int64_t)it->second.coin.out.nValue,
+           (uint64_t)cachedCoinsUsage,
+           (uint64_t)cacheCoins.size(),
+           (bool)it->second.coin.IsCoinBase(),
+           outpoint.hash.data());
     if (moveout) {
         *moveout = std::move(it->second.coin);
     }
@@ -231,6 +250,15 @@ void CCoinsViewCache::Uncache(const COutPoint& hash)
     CCoinsMap::iterator it = cacheCoins.find(hash);
     if (it != cacheCoins.end() && it->second.flags == 0) {
         cachedCoinsUsage -= it->second.coin.DynamicMemoryUsage();
+        TRACE8(utxocache, uncache,
+               hash.hash.ToString().c_str(),
+               (uint32_t)hash.n,
+               (uint32_t)it->second.coin.nHeight,
+               (int64_t)it->second.coin.out.nValue,
+               (uint64_t)cachedCoinsUsage,
+               (uint64_t)cacheCoins.size(),
+               (bool)it->second.coin.IsCoinBase(),
+               hash.hash.data());
         cacheCoins.erase(it);
     }
 }

src/validation.cpp

@@ -2120,6 +2120,13 @@ bool CChainState::FlushStateToDisk(
             nLastFlush = nNow;
             full_flush_completed = true;
         }
+        TRACE6(utxocache, flush,
+               (int64_t)(GetTimeMicros() - nNow.count()), // in microseconds (µs)
+               (u_int32_t)mode,
+               (u_int64_t)coins_count,
+               (u_int64_t)coins_mem_usage,
+               (bool)fFlushForPrune,
+               (bool)fDoFullFlush);
     }
     if (full_flush_completed) {
         // Update best block in wallet (so we can detect restored wallets).