tracing: Tracepoint for connected blocks

Can, for example, be used to benchmark block connections.
This commit is contained in:
0xb10c 2021-05-20 17:53:24 +02:00
parent 4224dec22b
commit 8f37f5c2a5
No known key found for this signature in database
GPG key ID: E2FFD5B1D88CA97D
4 changed files with 259 additions and 0 deletions

View file

@ -163,3 +163,79 @@ Warning: incomplete message (only 32568 out of 53552 bytes)! inbound msg 'tx' fr
Possibly lost 2 samples Possibly lost 2 samples
``` ```
### connectblock_benchmark.bt
A `bpftrace` script to benchmark the `ConnectBlock()` function during, for
example, a blockchain re-index. Based on the `validation:block_connected` USDT
tracepoint.
The script takes three positional arguments. The first two arguments, the start,
and end height indicate between which blocks the benchmark should be run. The
third acts as a duration threshold in milliseconds. When the `ConnectBlock()`
function takes longer than the threshold, information about the block, is
printed. For more details, see the header comment in the script.
By default, `bpftrace` limits strings to 64 bytes due to the limited stack size
in the kernel VM. Block hashes as zero-terminated hex strings are 65 bytes which
exceed the string limit. The string size limit can be set to 65 bytes with the
environment variable `BPFTRACE_STRLEN`.
The following command can be used to benchmark, for example, `ConnectBlock()`
between height 20000 and 38000 on SigNet while logging all blocks that take
longer than 25ms to connect.
```
$ BPFTRACE_STRLEN=65 bpftrace contrib/tracing/connectblock_benchmark.bt 20000 38000 25
```
In a different terminal, starting Bitcoin Core in SigNet mode and with
re-indexing enabled.
```
$ ./src/bitcoind -signet -reindex
```
This produces the following output.
```
Attaching 5 probes...
ConnectBlock Benchmark between height 20000 and 38000 inclusive
Logging blocks taking longer than 25 ms to connect.
Starting Connect Block Benchmark between height 20000 and 38000.
BENCH 39 blk/s 59 tx/s 59 inputs/s 20 sigops/s (height 20038)
Block 20492 (000000f555653bb05e2f3c6e79925e01a20dd57033f4dc7c354b46e34735d32b) 20 tx 2319 ins 2318 sigops took 38 ms
BENCH 1840 blk/s 2117 tx/s 4478 inputs/s 2471 sigops/s (height 21879)
BENCH 1816 blk/s 4972 tx/s 4982 inputs/s 125 sigops/s (height 23695)
BENCH 2095 blk/s 2890 tx/s 2910 inputs/s 152 sigops/s (height 25790)
BENCH 1684 blk/s 3979 tx/s 4053 inputs/s 288 sigops/s (height 27474)
BENCH 1155 blk/s 3216 tx/s 3252 inputs/s 115 sigops/s (height 28629)
BENCH 1797 blk/s 2488 tx/s 2503 inputs/s 111 sigops/s (height 30426)
BENCH 1849 blk/s 6318 tx/s 6569 inputs/s 12189 sigops/s (height 32275)
BENCH 946 blk/s 20209 tx/s 20775 inputs/s 83809 sigops/s (height 33221)
Block 33406 (0000002adfe4a15cfcd53bd890a89bbae836e5bb7f38bac566f61ad4548c87f6) 25 tx 2045 ins 2090 sigops took 29 ms
Block 33687 (00000073231307a9828e5607ceb8156b402efe56747271a4442e75eb5b77cd36) 52 tx 1797 ins 1826 sigops took 26 ms
BENCH 582 blk/s 21581 tx/s 27673 inputs/s 60345 sigops/s (height 33803)
BENCH 1035 blk/s 19735 tx/s 19776 inputs/s 51355 sigops/s (height 34838)
Block 35625 (0000006b00b347390c4768ea9df2655e9ff4b120f29d78594a2a702f8a02c997) 20 tx 3374 ins 3371 sigops took 49 ms
BENCH 887 blk/s 17857 tx/s 22191 inputs/s 24404 sigops/s (height 35725)
Block 35937 (000000d816d13d6e39b471cd4368db60463a764ba1f29168606b04a22b81ea57) 75 tx 3943 ins 3940 sigops took 61 ms
BENCH 823 blk/s 16298 tx/s 21031 inputs/s 18440 sigops/s (height 36548)
Block 36583 (000000c3e260556dbf42968aae3f904dba8b8c1ff96a6f6e3aa5365d2e3ad317) 24 tx 2198 ins 2194 sigops took 34 ms
Block 36700 (000000b3b173de9e65a3cfa738d976af6347aaf83fa17ab3f2a4d2ede3ddfac4) 73 tx 1615 ins 1611 sigops took 31 ms
Block 36832 (0000007859578c02c1ac37dabd1b9ec19b98f350b56935f5dd3a41e9f79f836e) 34 tx 1440 ins 1436 sigops took 26 ms
BENCH 613 blk/s 16718 tx/s 25074 inputs/s 23022 sigops/s (height 37161)
Block 37870 (000000f5c1086291ba2d943fb0c3bc82e71c5ee341ee117681d1456fbf6c6c38) 25 tx 1517 ins 1514 sigops took 29 ms
BENCH 811 blk/s 16031 tx/s 20921 inputs/s 18696 sigops/s (height 37972)
Took 14055 ms to connect the blocks between height 20000 and 38000.
Histogram of block connection times in milliseconds (ms).
@durations:
[0] 16838 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[1] 882 |@@ |
[2, 4) 236 | |
[4, 8) 23 | |
[8, 16) 9 | |
[16, 32) 9 | |
[32, 64) 4 | |
```

View file

@ -0,0 +1,150 @@
#!/usr/bin/env bpftrace
/*
USAGE:
BPFTRACE_STRLEN=65 bpftrace contrib/tracing/connectblock_benchmark.bt <start height> <end height> <logging threshold in ms>
- The environment variable BPFTRACE_STRLEN needs to be set to 65 chars as
strings are limited to 64 chars by default. Hex strings with Bitcoin block
hashes are 64 hex chars + 1 null-termination char.
- <start height> sets the height at which the benchmark should start. Setting
the start height to 0 starts the benchmark immediately, even before the
first block is connected.
- <end height> sets the height after which the benchmark should end. Setting
the end height to 0 disables the benchmark. The script only logs blocks
over <logging threshold in ms>.
- Threshold <logging threshold in ms>
This script requires a 'bitcoind' binary compiled with eBPF support and the
'validation:block_connected' USDT. By default, it's assumed that 'bitcoind' is
located in './src/bitcoind'. This can be modified in the script below.
EXAMPLES:
BPFTRACE_STRLEN=65 bpftrace contrib/tracing/connectblock_benchmark.bt 300000 680000 1000
When run together 'bitcoind -reindex', this benchmarks the time it takes to
connect the blocks between height 300.000 and 680.000 (inclusive) and prints
details about all blocks that take longer than 1000ms to connect. Prints a
histogram with block connection times when the benchmark is finished.
BPFTRACE_STRLEN=65 bpftrace contrib/tracing/connectblock_benchmark.bt 0 0 500
When running together 'bitcoind', all newly connected blocks that
take longer than 500ms to connect are logged. A histogram with block
connection times is shown when the script is terminated.
*/
BEGIN
{
$start_height = $1;
$end_height = $2;
$logging_threshold_ms = $3;
if ($end_height < $start_height) {
printf("Error: start height (%d) larger than end height (%d)!\n", $start_height, $end_height);
exit();
}
if ($end_height > 0) {
printf("ConnectBlock benchmark between height %d and %d inclusive\n", $start_height, $end_height);
} else {
printf("ConnectBlock logging starting at height %d\n", $start_height);
}
if ($logging_threshold_ms > 0) {
printf("Logging blocks taking longer than %d ms to connect.\n", $3);
}
if ($start_height == 0) {
@start = nsecs;
}
}
/*
Attaches to the 'validation:block_connected' USDT and collects stats when the
connected block is between the start and end height (or the end height is
unset).
*/
usdt:./src/bitcoind:validation:block_connected /arg1 >= $1 && (arg1 <= $2 || $2 == 0 )/
{
$height = arg1;
$transactions = arg2;
$inputs = arg3;
$sigops = arg4;
$duration = (uint64) arg5;
@height = $height;
@blocks = @blocks + 1;
@transactions = @transactions + $transactions;
@inputs = @inputs + $inputs;
@sigops = @sigops + $sigops;
@durations = hist($duration / 1000);
if ($height == $1 && $height != 0) {
@start = nsecs;
printf("Starting Connect Block Benchmark between height %d and %d.\n", $1, $2);
}
if ($2 > 0 && $height >= $2) {
@end = nsecs;
$duration = @end - @start;
printf("\nTook %d ms to connect the blocks between height %d and %d.\n", $duration / 1000000, $1, $2);
exit();
}
}
/*
Attaches to the 'validation:block_connected' USDT and logs information about
blocks where the time it took to connect the block is above the
<logging threshold in ms>.
*/
usdt:./src/bitcoind:validation:block_connected / (uint64) arg5 / 1000> $3 /
{
$hash_str = str(arg0);
$height = (int32) arg1;
$transactions = (uint64) arg2;
$inputs = (int32) arg3;
$sigops = (int64) arg4;
$duration = (int64) arg5;
printf("Block %d (%s) %4d tx %5d ins %5d sigops took %4d ms\n", $height, $hash_str, $transactions, $inputs, $sigops, (uint64) $duration / 1000);
}
/*
Prints stats about the blocks, transactions, inputs, and sigops processed in
the last second (if any).
*/
interval:s:1 {
if (@blocks > 0) {
printf("BENCH %4d blk/s %6d tx/s %7d inputs/s %8d sigops/s (height %d)\n", @blocks, @transactions, @inputs, @sigops, @height);
zero(@blocks);
zero(@transactions);
zero(@inputs);
zero(@sigops);
}
}
END
{
printf("\nHistogram of block connection times in milliseconds (ms).\n");
print(@durations);
clear(@durations);
clear(@blocks);
clear(@transactions);
clear(@inputs);
clear(@sigops);
clear(@height);
clear(@start);
clear(@end);
}

View file

@ -93,6 +93,28 @@ to user-space in full. Messages longer than a 32kb might be cut off. This can
be detected in tracing scripts by comparing the message size to the length of be detected in tracing scripts by comparing the message size to the length of
the passed message. the passed message.
### Context `validation`
#### Tracepoint `validation:block_connected`
Is called *after* a block is connected to the chain. Can, for example, be used
to benchmark block connections together with `-reindex`.
Arguments passed:
1. Block Header Hash as `pointer to C-style String` (64 characters)
2. Block Height as `int32`
3. Transactions in the Block as `uint64`
4. Inputs spend in the Block as `int32`
5. SigOps in the Block (excluding coinbase SigOps) `uint64`
6. Time it took to connect the Block in microseconds (µs) as `uint64`
7. Block Header Hash as `pointer to unsigned chars` (i.e. 32 bytes in little-endian)
Note: The 7th argument can't be accessed by bpftrace and is purposefully chosen
to be the block header hash as bytes. See [bpftrace argument limit] for more
details.
[bpftrace argument limit]: #bpftrace-argument-limit
## Adding tracepoints to Bitcoin Core ## Adding tracepoints to Bitcoin Core
To add a new tracepoint, `#include <util/trace.h>` in the compilation unit where To add a new tracepoint, `#include <util/trace.h>` in the compilation unit where

View file

@ -48,6 +48,7 @@
#include <util/rbf.h> #include <util/rbf.h>
#include <util/strencodings.h> #include <util/strencodings.h>
#include <util/system.h> #include <util/system.h>
#include <util/trace.h>
#include <util/translation.h> #include <util/translation.h>
#include <validationinterface.h> #include <validationinterface.h>
#include <warnings.h> #include <warnings.h>
@ -1997,6 +1998,16 @@ bool CChainState::ConnectBlock(const CBlock& block, BlockValidationState& state,
int64_t nTime6 = GetTimeMicros(); nTimeCallbacks += nTime6 - nTime5; int64_t nTime6 = GetTimeMicros(); nTimeCallbacks += nTime6 - nTime5;
LogPrint(BCLog::BENCH, " - Callbacks: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (nTime6 - nTime5), nTimeCallbacks * MICRO, nTimeCallbacks * MILLI / nBlocksTotal); LogPrint(BCLog::BENCH, " - Callbacks: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (nTime6 - nTime5), nTimeCallbacks * MICRO, nTimeCallbacks * MILLI / nBlocksTotal);
TRACE7(validation, block_connected,
block.GetHash().ToString().c_str(),
pindex->nHeight,
block.vtx.size(),
nInputs,
nSigOpsCost,
GetTimeMicros() - nTimeStart, // in microseconds (µs)
block.GetHash().data()
);
return true; return true;
} }