Merge bitcoin/bitcoin#29877: tracing: explicitly cast block_connected duration to nanoseconds

cd0edf26c0 tracing: cast block_connected duration to nanoseconds (0xb10c)

Pull request description:

  When the `validation:block_connected` tracepoint was introduced in 8f37f5c2a5, the connect block duration was passed in microseconds `µs`. By starting to use steady clock in fabf1cdb20 this changed to nanoseconds `ns`. As the test only checked if the duration value is `> 0` as a plausibility check, this went unnoticed. This was detected this when setting up monitoring for block validation time as part of the Great Consensus Cleanup Revival discussion.

  This change casts the duration explicitly to nanoseconds, updates the documentation, and adds a check for an upper bound to the tracepoint interface tests. The upper bound is quite lax as mining the block takes much longer than connecting the empty test block. It's however able to detect a duration passed in an incorrect unit (1000x off).

  A previous version of this PR casted the duration to microseconds `µs` - however, as the last three major releases have had the duration as nanoseconds (and this went unnoticed), we assume that this is the API now and changeing it back to microseconds would break the API again. See also https://github.com/bitcoin/bitcoin/pull/29877#issuecomment-2067867597

ACKs for top commit:
  maflcko:
    re-lgtm ACK cd0edf26c0
  laanwj:
    re-ACK cd0edf26c0

Tree-SHA512: 54a1eea0297e01c07c2d071ffafbf97dbd080f763e1dc0014ff086a913b739637c1634b1cf87c90b94a3c2f66006acfaada0414a15769cac761e03bc4aab2a77

contrib/tracing/connectblock_benchmark.bt

@@ -82,7 +82,7 @@ usdt:./build/src/bitcoind:validation:block_connected /arg1 >= $1 && (arg1 <= $2
   @inputs = @inputs + $inputs;
   @sigops = @sigops + $sigops;
 
-  @durations = hist($duration / 1000);
+  @durations = hist($duration / 1e6);
 
   if ($height == $1 && $height != 0) {
     @start = nsecs;
@@ -92,7 +92,7 @@ usdt:./build/src/bitcoind:validation:block_connected /arg1 >= $1 && (arg1 <= $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);
+    printf("\nTook %d ms to connect the blocks between height %d and %d.\n", $duration / 1e9, $1, $2);
     exit();
   }
 }
@@ -102,7 +102,7 @@ usdt:./build/src/bitcoind:validation:block_connected /arg1 >= $1 && (arg1 <= $2
   blocks where the time it took to connect the block is above the
   <logging threshold in ms>.
 */
-usdt:./build/src/bitcoind:validation:block_connected / (uint64) arg5 / 1000> $3 /
+usdt:./build/src/bitcoind:validation:block_connected / (uint64) arg5 / 1e6 > $3 /
 {
   $hash = arg0;
   $height = (int32) arg1;
@@ -120,7 +120,7 @@ usdt:./build/src/bitcoind:validation:block_connected / (uint64) arg5 / 1000> $3
       printf("%02x", $b);
       $p -= 1;
   }
-  printf(")  %4d tx  %5d ins  %5d sigops  took %4d ms\n", $transactions, $inputs, $sigops, (uint64) $duration / 1000);
+  printf(")  %4d tx  %5d ins  %5d sigops  took %4d ms\n", $transactions, $inputs, $sigops, (uint64) $duration / 1e6);
 }
 
 

doc/tracing.md

@@ -106,7 +106,7 @@ Arguments passed:
 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`
+6. Time it took to connect the Block in nanoseconds (ns) as `uint64`
 
 ### Context `utxocache`
 

src/validation.cpp

@@ -2736,7 +2736,7 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state,
         block.vtx.size(),
         nInputs,
         nSigOpsCost,
-        time_5 - time_start // in microseconds (µs)
+        Ticks<std::chrono::nanoseconds>(time_5 - time_start)
     );
 
     return true;

test/functional/interface_usdt_validation.py

@@ -8,6 +8,7 @@
 """
 
 import ctypes
+import time
 
 # Test will be skipped if we don't have bcc installed
 try:
@@ -105,10 +106,12 @@ class ValidationTracepointTest(BitcoinTestFramework):
             handle_blockconnected)
 
         self.log.info(f"mine {BLOCKS_EXPECTED} blocks")
-        block_hashes = self.generatetoaddress(
-            self.nodes[0], BLOCKS_EXPECTED, ADDRESS_BCRT1_UNSPENDABLE)
-        for block_hash in block_hashes:
-            expected_blocks[block_hash] = self.nodes[0].getblock(block_hash, 2)
+        generatetoaddress_duration = dict()
+        for _ in range(BLOCKS_EXPECTED):
+            start = time.time()
+            hash = self.generatetoaddress(self.nodes[0], 1, ADDRESS_BCRT1_UNSPENDABLE)[0]
+            generatetoaddress_duration[hash] = (time.time() - start) * 1e9  # in nanoseconds
+            expected_blocks[hash] = self.nodes[0].getblock(hash, 2)
 
         bpf.perf_buffer_poll(timeout=200)
 
@@ -123,6 +126,10 @@ class ValidationTracepointTest(BitcoinTestFramework):
             assert_equal(0, event.sigops)  # no sigops in coinbase tx
             # only plausibility checks
             assert event.duration > 0
+            # generatetoaddress (mining and connecting) takes longer than
+            # connecting the block. In case the duration unit is off, we'll
+            # detect it with this assert.
+            assert event.duration < generatetoaddress_duration[block_hash]
             del expected_blocks[block_hash]
         assert_equal(BLOCKS_EXPECTED, len(events))
         assert_equal(0, len(expected_blocks))