From 5b10a5a2fd2e0d4506f87268f1559f1d8f11adff Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Wed, 22 Dec 2021 11:57:44 +0530 Subject: [PATCH] merge bitcoin#23907: utxocache tracepoints follow up --- contrib/tracing/README.md | 31 ++++++++++-------------- contrib/tracing/log_utxocache_flush.py | 21 +++++++--------- contrib/tracing/log_utxos.bt | 2 +- doc/tracing.md | 33 +++++++++++++++++--------- src/validation.cpp | 13 +++++----- 5 files changed, 50 insertions(+), 50 deletions(-) diff --git a/contrib/tracing/README.md b/contrib/tracing/README.md index 581fb95863..063ba2b140 100644 --- a/contrib/tracing/README.md +++ b/contrib/tracing/README.md @@ -237,7 +237,7 @@ Histogram of block connection times in milliseconds (ms). ### log_utxocache_flush.py -A BCC Python script to log the cache and index flushes. Based on the +A BCC Python script to log the UTXO cache flushes. Based on the `utxocache:flush` tracepoint. ```bash @@ -246,23 +246,10 @@ $ 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 +Duration (µs) Mode Coins Count Memory Usage Prune +730451 IF_NEEDED 22990 3323.54 kB True +637657 ALWAYS 122320 17124.80 kB False +81349 ALWAYS 0 1383.49 kB False ``` ### log_utxos.bt @@ -275,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 b602c21f1c..8985d8fa73 100755 --- a/contrib/tracing/log_utxocache_flush.py +++ b/contrib/tracing/log_utxocache_flush.py @@ -13,14 +13,14 @@ from bcc import BPF, USDT # 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; + bool is_flush_for_prune; }; // BPF perf buffer to push the data to user space. @@ -32,8 +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_full_flush); + bpf_usdt_readarg(5, ctx, &data.is_flush_for_prune); flush.perf_submit(ctx, &data, sizeof(data)); return 0; } @@ -54,19 +53,17 @@ 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_full_flush", ctypes.c_bool) + ("is_flush_for_prune", ctypes.c_bool) ] def print_event(event): - print("%-15d %-10s %-15d %-15s %-8s %-8s" % ( + print("%-15d %-10s %-15d %-15s %-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 + event.is_flush_for_prune )) @@ -87,9 +84,9 @@ def main(bitcoind_path): 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")) + print("%-15s %-10s %-15s %-15s %-8s" % ("Duration (µs)", "Mode", + "Coins Count", "Memory Usage", + "Flush for Prune")) while True: try: diff --git a/contrib/tracing/log_utxos.bt b/contrib/tracing/log_utxos.bt index cf2ba00a4d..8be17a0771 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 'dashd' binary compiled with eBPF support and the - 'utxochache' tracepoints. By default, it's assumed that 'dashd' is + 'utxocache' 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. diff --git a/doc/tracing.md b/doc/tracing.md index 5b25eb3816..c8cfa0a7d6 100644 --- a/doc/tracing.md +++ b/doc/tracing.md @@ -110,23 +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**: Dash 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 and indexes 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` -6. If it was full flush 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) @@ -137,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) @@ -148,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 Dash Core diff --git a/src/validation.cpp b/src/validation.cpp index 5ba14db708..bc2498ce5a 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -2471,14 +2471,13 @@ bool CChainState::FlushStateToDisk( } nLastFlush = nNow; full_flush_completed = true; + TRACE5(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); } - 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).