[tracing] tracepoints to utxocache add, spent and uncache

Signed-off-by: Arnab Sen <arnabsen1729@gmail.com>

contrib/tracing/README.md

@@ -234,3 +234,62 @@ Histogram of block connection times in milliseconds (ms).
 [16, 32)               9 |                                                    |
 [32, 64)               4 |                                                    |
 ```
+
+### log_utxocache_flush.py
+
+A BCC Python script to log the cache and index flushes. Based on the
+`utxocache:flush` tracepoint.
+
+```bash
+$ python3 contrib/tracing/log_utxocache_flush.py ./src/bitcoind
+```
+
+```
+Logging utxocache flushes. Ctrl-C to end...
+Duration (µs)   Mode       Coins Count     Memory Usage    Prune    Full Flush
+0               PERIODIC   28484           3929.87 kB      False    False
+1               PERIODIC   28485           3930.00 kB      False    False
+0               PERIODIC   28489           3930.51 kB      False    False
+1               PERIODIC   28490           3930.64 kB      False    False
+0               PERIODIC   28491           3930.77 kB      False    False
+0               PERIODIC   28491           3930.77 kB      False    False
+0               PERIODIC   28496           3931.41 kB      False    False
+1               PERIODIC   28496           3931.41 kB      False    False
+0               PERIODIC   28497           3931.54 kB      False    False
+1               PERIODIC   28497           3931.54 kB      False    False
+1               PERIODIC   28499           3931.79 kB      False    False
+.
+.
+.
+53788           ALWAYS     30076           4136.27 kB      False    False
+7463            ALWAYS     0               245.84 kB       False    False
+```
+
+### log_utxos.bt
+
+A `bpftrace` script to log information about the coins that are added, spent, or
+uncached from the UTXO set. Based on the `utxocache:add`, `utxocache:spend` and
+`utxocache:uncache` tracepoints.
+
+```bash
+$ bpftrace contrib/tracing/log_utxos.bt
+```
+
+It should produce an output similar to the following.
+
+```bash
+Attaching 4 probes...
+OP      Outpoint                                                                           Value  Height Coinbase
+Added   6ba9ad857e1ef2eb2a2c94f06813c414c7ab273e3d6bd7ad64e000315a887e7c:1                 10000 2094512 No
+Spent   fa7dc4db56637a151f6649d8f26732956d1c5424c82aae400a83d02b2cc2c87b:0             182264897 2094512 No
+Added   eeb2f099b1af6a2a12e6ddd2eeb16fc5968582241d7f08ba202d28b60ac264c7:0                 10000 2094512 No
+Added   eeb2f099b1af6a2a12e6ddd2eeb16fc5968582241d7f08ba202d28b60ac264c7:1             182254756 2094512 No
+Added   a0c7f4ec9cccef2d89672a624a4e6c8237a17572efdd4679eea9e9ee70d2db04:0              10072679 2094513 Yes
+Spent   25e0df5cc1aeb1b78e6056bf403e5e8b7e41f138060ca0a50a50134df0549a5e:2                   540 2094508 No
+Spent   42f383c04e09c26a2378272ec33aa0c1bf4883ca5ab739e8b7e06be5a5787d61:1               3848399 2007724 No
+Added   f85e3b4b89270863a389395cc9a4123e417ab19384cef96533c6649abd6b0561:0               3788399 2094513 No
+Added   f85e3b4b89270863a389395cc9a4123e417ab19384cef96533c6649abd6b0561:2                   540 2094513 No
+Spent   a05880b8c77971ed0b9f73062c7c4cdb0ff3856ab14cbf8bc481ed571cd34b83:1            5591281046 2094511 No
+Added   eb689865f7d957938978d6207918748f74e6aa074f47874724327089445b0960:0            5589696005 2094513 No
+Added   eb689865f7d957938978d6207918748f74e6aa074f47874724327089445b0960:1               1565556 2094513 No
+```

contrib/tracing/log_utxocache_flush.py

@@ -4,8 +4,8 @@ import sys
 import ctypes
 from bcc import BPF, USDT
 
-""" Example script to log details about coins flushed by the Bitcoin client
-utilizing USDT probes and the flush:flush tracepoint. """
+"""Example logging Bitcoin Core utxo set cache flushes utilizing
+    the utxocache:flush tracepoint."""
 
 # USAGE:  ./contrib/tracing/log_utxocache_flush.py path/to/bitcoind
 
@@ -22,8 +22,10 @@ struct data_t
   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);
@@ -45,8 +47,8 @@ FLUSH_MODES = [
 ]
 
 
-# define output data structure
 class Data(ctypes.Structure):
+    # define output data structure corresponding to struct data_t
     _fields_ = [
         ("duration", ctypes.c_uint64),
         ("mode", ctypes.c_uint32),

contrib/tracing/log_utxos.bt

@@ -0,0 +1,86 @@
+#!/usr/bin/env bpftrace
+
+/*
+
+  USAGE:
+
+  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
+  located in './src/bitcoind'. This can be modified in the script below.
+
+  NOTE: requires bpftrace v0.12.0 or above.
+*/
+
+BEGIN
+{
+    printf("%-7s %-71s %16s %7s %8s\n",
+          "OP", "Outpoint", "Value", "Height", "Coinbase");
+}
+
+/*
+  Attaches to the 'utxocache:add' tracepoint and prints additions to the UTXO set cache.
+*/
+usdt:./src/bitcoind:utxocache:add
+{
+  $txid = arg0;
+  $index = (uint32)arg1;
+  $height = (uint32)arg2;
+  $value = (int64)arg3;
+  $isCoinbase = arg4;
+
+  printf("Added   ");
+  $p = $txid + 31;
+  unroll(32) {
+    $b = *(uint8*)$p;
+    printf("%02x", $b);
+    $p-=1;
+  }
+
+  printf(":%-6d %16ld %7d %s\n", $index, $value, $height, ($isCoinbase ? "Yes" : "No" ));
+}
+
+/*
+  Attaches to the 'utxocache:spent' tracepoint and prints spents from the UTXO set cache.
+*/
+usdt:./src/bitcoind:utxocache:spent
+{
+  $txid = arg0;
+  $index = (uint32)arg1;
+  $height = (uint32)arg2;
+  $value = (int64)arg3;
+  $isCoinbase = arg4;
+
+  printf("Spent   ");
+  $p = $txid + 31;
+  unroll(32) {
+    $b = *(uint8*)$p;
+    printf("%02x", $b);
+    $p-=1;
+  }
+
+  printf(":%-6d %16ld %7d %s\n", $index, $value, $height, ($isCoinbase ? "Yes" : "No" ));
+}
+
+/*
+  Attaches to the 'utxocache:uncache' tracepoint and uncache UTXOs from the UTXO set cache.
+*/
+usdt:./src/bitcoind:utxocache:uncache
+{
+  $txid = arg0;
+  $index = (uint32)arg1;
+  $height = (uint32)arg2;
+  $value = (int64)arg3;
+  $isCoinbase = arg4;
+
+  printf("Uncache ");
+  $p = $txid + 31;
+  unroll(32) {
+    $b = *(uint8*)$p;
+    printf("%02x", $b);
+    $p-=1;
+  }
+
+  printf(":%-6d %16ld %7d %s\n", $index, $value, $height, ($isCoinbase ? "Yes" : "No" ));
+}

doc/tracing.md

@@ -124,6 +124,39 @@ Arguments passed:
 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 unsigned chars` (i.e. 32 bytes in little-endian)
+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. If the coin is a coinbase as `bool`
+
+#### Tracepoint `utxocache:spent`
+
+It is called when a coin is spent from the UTXO cache.
+
+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 spent, as `uint32`
+4. Value of the coin as `int64`
+5. If the coin is a coinbase as `bool`
+
+#### 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 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`
+
 ## 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,12 @@ 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();
+    TRACE5(utxocache, add,
+           outpoint.hash.data(),
+           (uint32_t)outpoint.n,
+           (uint32_t)coin.nHeight,
+           (int64_t)coin.out.nValue,
+           (bool)coin.IsCoinBase());
 }
 
 void CCoinsViewCache::EmplaceCoinInternalDANGER(COutPoint&& outpoint, Coin&& coin) {
@@ -120,6 +127,12 @@ bool CCoinsViewCache::SpendCoin(const COutPoint &outpoint, Coin* moveout) {
     CCoinsMap::iterator it = FetchCoin(outpoint);
     if (it == cacheCoins.end()) return false;
     cachedCoinsUsage -= it->second.coin.DynamicMemoryUsage();
+    TRACE5(utxocache, spent,
+           outpoint.hash.data(),
+           (uint32_t)outpoint.n,
+           (uint32_t)it->second.coin.nHeight,
+           (int64_t)it->second.coin.out.nValue,
+           (bool)it->second.coin.IsCoinBase());
     if (moveout) {
         *moveout = std::move(it->second.coin);
     }
@@ -231,6 +244,12 @@ 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();
+        TRACE5(utxocache, uncache,
+               hash.hash.data(),
+               (uint32_t)hash.n,
+               (uint32_t)it->second.coin.nHeight,
+               (int64_t)it->second.coin.out.nValue,
+               (bool)it->second.coin.IsCoinBase());
         cacheCoins.erase(it);
     }
 }

src/validation.cpp

@@ -2102,13 +2102,12 @@ bool CChainState::FlushStateToDisk(
             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
-        );
+               (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).