aboutsummaryrefslogtreecommitdiff
diff options
context:
space:
mode:
Diffstat
-rw-r--r--contrib/tracing/README.md59
-rwxr-xr-xcontrib/tracing/log_utxocache_flush.py107
-rwxr-xr-xcontrib/tracing/log_utxos.bt86
-rw-r--r--doc/tracing.md49
-rw-r--r--src/coins.cpp19
-rw-r--r--src/validation.cpp7
6 files changed, 327 insertions, 0 deletions
diff --git a/contrib/tracing/README.md b/contrib/tracing/README.md
index 1f93474fa0..b71ce2f34b 100644
--- a/contrib/tracing/README.md
+++ b/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
+```
diff --git a/contrib/tracing/log_utxocache_flush.py b/contrib/tracing/log_utxocache_flush.py
new file mode 100755
index 0000000000..df27dc193a
--- /dev/null
+++ b/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)
diff --git a/contrib/tracing/log_utxos.bt b/contrib/tracing/log_utxos.bt
new file mode 100755
index 0000000000..0d47f3d62b
--- /dev/null
+++ b/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" ));
+}
diff --git a/doc/tracing.md b/doc/tracing.md
index 57104c43a0..5b9ba09c2f 100644
--- a/doc/tracing.md
+++ b/doc/tracing.md
@@ -108,6 +108,55 @@ Arguments passed:
5. SigOps in the Block (excluding coinbase SigOps) `uint64`
6. Time it took to connect the Block in microseconds (µs) as `uint64`
+### 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 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
diff --git a/src/coins.cpp b/src/coins.cpp
index ce0b131de6..daead6055e 100644
--- a/src/coins.cpp
+++ b/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);
}
}
diff --git a/src/validation.cpp b/src/validation.cpp
index c96adb77ff..86d2ae7577 100644
--- a/src/validation.cpp
+++ b/src/validation.cpp
@@ -2101,6 +2101,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).
generated by cgit v1.2.3 (git 2.26.2) at 2024-11-14 05:37:17 +0000