Skip to content

Commit

Permalink
tracing: misc follow-ups to 22902
Browse files Browse the repository at this point in the history
- mention 'Lost X events' workaround
- clarify flush tracepoint docs
- fix typo in tracepoint context
- clarify flush for prune
    The documentation and examples for the `fFlushForPrune` argument
    of the utxocache flush tracepoint weren't clear without looking
    at the code.

    See these comments: bitcoin#22902 (comment)

- doc: note that there can be temporary UTXO caches
    Bitcoin Core uses temporary clones of it's _main_ UTXO cache in some
    places. The utxocache:add and :spent tracepoints are triggered when
    temporary caches are changed too. This is documented.
  • Loading branch information
0xB10C authored and arnabsen1729 committed Feb 18, 2022
1 parent 36a6584 commit 799968e
Show file tree
Hide file tree
Showing 4 changed files with 36 additions and 17 deletions.
8 changes: 7 additions & 1 deletion contrib/tracing/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -262,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...
Expand Down
11 changes: 6 additions & 5 deletions contrib/tracing/log_utxocache_flush.py
Original file line number Diff line number Diff line change
Expand Up @@ -13,13 +13,14 @@
# 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_flush_for_prune;
};
// BPF perf buffer to push the data to user space.
Expand All @@ -31,7 +32,7 @@
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_flush_for_prune);
flush.perf_submit(ctx, &data, sizeof(data));
return 0;
}
Expand All @@ -52,7 +53,7 @@ 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_flush_for_prune", ctypes.c_bool)
]


Expand All @@ -62,7 +63,7 @@ def print_event(event):
FLUSH_MODES[event.mode],
event.coins_count,
"%.2f kB" % (event.coins_mem_usage/1000),
event.is_flush_prune,
event.is_flush_for_prune
))


Expand All @@ -85,7 +86,7 @@ def handle_flush(_, data, size):
print("Logging utxocache flushes. Ctrl-C to end...")
print("%-15s %-10s %-15s %-15s %-8s" % ("Duration (µs)", "Mode",
"Coins Count", "Memory Usage",
"Prune"))
"Flush for Prune"))

while True:
try:
Expand Down
2 changes: 1 addition & 1 deletion contrib/tracing/log_utxos.bt
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
32 changes: 22 additions & 10 deletions doc/tracing.md
Original file line number Diff line number Diff line change
Expand Up @@ -110,22 +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 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`
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)
Expand All @@ -136,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)
Expand All @@ -147,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

Expand Down

0 comments on commit 799968e

Please sign in to comment.