diff --git a/contrib/tracing/README.md b/contrib/tracing/README.md index 99901f62b6..581fb95863 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/dashd +``` + +``` +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..b602c21f1c --- /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 Dash Core utxo set cache flushes utilizing + the utxocache:flush tracepoint.""" + +# USAGE: ./contrib/tracing/log_utxocache_flush.py path/to/dashd + +# BCC: The C program to be compiled to an eBPF program (by BCC) and loaded into +# a sandboxed Linux kernel VM. +program = """ +# include +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/dashd") + 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..cf2ba00a4d --- /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 'dashd' binary compiled with eBPF support and the + 'utxochache' tracepoints. By default, it's assumed that 'dashd' is + located in './src/dashd'. 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/dashd: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/dashd: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/dashd: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 f8cce5c93f..5b25eb3816 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 Dash Core To add a new tracepoint, `#include ` in the compilation unit where diff --git a/src/coins.cpp b/src/coins.cpp index 4a1cccd0ab..e0e455d632 100644 --- a/src/coins.cpp +++ b/src/coins.cpp @@ -7,6 +7,7 @@ #include #include #include +#include #include bool CCoinsView::GetCoin(const COutPoint &outpoint, Coin &coin) const { return false; } @@ -98,6 +99,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) { @@ -123,6 +130,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); } @@ -273,6 +286,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 78333db21b..5ba14db708 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -2472,6 +2472,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).