merge bitcoin#23907: utxocache tracepoints follow up

This commit is contained in:
Kittywhiskers Van Gogh 2021-12-22 11:57:44 +05:30
parent c3d7e3a192
commit 5b10a5a2fd
No known key found for this signature in database
GPG Key ID: 30CD0C065E5C4AAD
5 changed files with 50 additions and 50 deletions

View File

@ -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...

View File

@ -13,14 +13,14 @@ from bcc import BPF, USDT
# 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;
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",
print("%-15s %-10s %-15s %-15s %-8s" % ("Duration (µs)", "Mode",
"Coins Count", "Memory Usage",
"Prune", "Full Flush"))
"Flush for Prune"))
while True:
try:

View File

@ -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.

View File

@ -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

View File

@ -2471,14 +2471,13 @@ bool CChainState::FlushStateToDisk(
}
nLastFlush = nNow;
full_flush_completed = true;
}
TRACE6(utxocache, flush,
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,
(bool)fDoFullFlush);
(bool)fFlushForPrune);
}
}
if (full_flush_completed) {
// Update best block in wallet (so we can detect restored wallets).