tracing: Tracepoint for connected blocks

Can, for example, be used to benchmark block connections.

2 files changed, 226 insertions, 0 deletions

diff --git a/contrib/tracing/README.md b/contrib/tracing/README.md
index 2d81e375dc..047354cda1 100644
--- a/contrib/tracing/README.md
+++ b/contrib/tracing/README.md
@@ -163,3 +163,79 @@ Warning: incomplete message (only 32568 out of 53552 bytes)! inbound msg 'tx' fr
 …
 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 |                                                    |
+```
diff --git a/contrib/tracing/connectblock_benchmark.bt b/contrib/tracing/connectblock_benchmark.bt
new file mode 100755
index 0000000000..d268eff7f8
--- /dev/null
+++ b/contrib/tracing/connectblock_benchmark.bt
@@ -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);
+}
+