tracing: correctly scope utxocache:flush tracepoint

Previously, the `utxocache:flush` tracepoint was in the wrong scope and
reached every time `CChainState::FlushStateToDisk` was called, even when
there was no flushing of the cache. The tracepoint is now properly scoped
and will be reached during a full flush.

Inside the scope, the `fDoFullFlush` value will always be `true`, so it
doesn't need to be logged separately. Hence, it's dropped from the
tracepoint arguments.
This commit is contained in:
Arnab Sen 2021-12-22 11:57:44 +05:30
parent 5d91133699
commit 36a6584703
4 changed files with 16 additions and 35 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/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

View file

@ -20,7 +20,6 @@ struct data_t
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.
@ -33,7 +32,6 @@ int trace_flush(struct pt_regs *ctx) {
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;
}
@ -55,18 +53,16 @@ class Data(ctypes.Structure):
("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" % (
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
))
@ -87,9 +83,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",
"Prune"))
while True:
try:

View file

@ -112,7 +112,7 @@ Arguments passed:
#### Tracepoint `utxocache:flush`
Is called *after* the caches and indexes are flushed depending on the mode
Is called *after* the caches are flushed depending on the mode
`CChainState::FlushStateToDisk` is called with.
Arguments passed:
@ -122,7 +122,6 @@ Arguments passed:
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`

View file

@ -2324,14 +2324,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).