highperfocused/bitcoin
1
0
Fork 0
mirror of https://github.com/bitcoin/bitcoin.git synced 2025-04-09 04:39:08 +02:00
Code Issues Packages Projects Releases Wiki Activity

Merge bitcoin/bitcoin#23907: tracing: utxocache tracepoints follow up for #22902

Browse Source 
799968e8b38833dc7fd7b6d488a66a14580ef674 tracing: misc follow-ups to 22902 (0xb10c)
36a65847033540cf2203252c7baf42bc5ec97579 tracing: correctly scope utxocache:flush tracepoint (Arnab Sen)

Pull request description:

  This PR is a follow-up to the [#22902](https://github.com/bitcoin/bitcoin/pull/22902).

  Previously, the tracepoint `utxocache:flush` was called, even when it was not flushing. So, the tracepoint is now scoped to write only when coins cache to disk.

ACKs for top commit:
  0xB10C:
    ACK 799968e8b38833dc7fd7b6d488a66a14580ef674

Tree-SHA512: ebb096cbf991c551c81e4339821f10d9768c14cf3d8cb14d0ad851acff5980962228a1c746914c6aba3bdb27e8be53b33349c41efe8bab5542f639916e437b5f
This commit is contained in:
fanquake 2022-02-20 11:25:56 +00:00
commit 2b0735d183
No known key found for this signature in database
GPG Key ID: 2EEB9F5CC09526C1
5 changed files with 50 additions and 50 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

31
contrib/tracing/README.md
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/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
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...

21
contrib/tracing/log_utxocache_flush.py
View File

@ -16,14 +16,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.
@ -35,8 +35,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;
}
@ -57,19 +56,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
))
@ -90,9 +87,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:

2
contrib/tracing/log_utxos.bt
View File

@ -7,7 +7,7 @@
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
'utxocache' 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.

33
doc/tracing.md
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**: Bitcoin 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 Bitcoin Core

13
src/validation.cpp
View File

@ -2373,14 +2373,13 @@ bool CChainState::FlushStateToDisk(
return AbortNode(state, "Failed to write to coin database");
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).