tracing: Tracepoint for connected blocks

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

Author: 0xB10C

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 |                                                    |
+```

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);
+}
+

doc/tracing.md

@@ -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
 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
 
 To add a new tracepoint, `#include <util/trace.h>` in the compilation unit where

src/validation.cpp

@@ -48,6 +48,7 @@
 #include <util/rbf.h>
 #include <util/strencodings.h>
 #include <util/system.h>
+#include <util/trace.h>
 #include <util/translation.h>
 #include <validationinterface.h>
 #include <warnings.h>
@@ -1997,6 +1998,16 @@ bool CChainState::ConnectBlock(const CBlock& block, BlockValidationState& state,
     int64_t nTime6 = GetTimeMicros(); nTimeCallbacks += nTime6 - nTime5;
     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;
 }