From cd0edf26c07c8c615f3ae3ac040c4774dcc8e650 Mon Sep 17 00:00:00 2001 From: 0xb10c Date: Tue, 2 Apr 2024 15:16:58 +0200 Subject: [PATCH] tracing: cast block_connected duration to nanoseconds MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit When the tracepoint was introduced in 8f37f5c2a562c38c83fc40234ade9c301fc4e685, the connect_block duration was passed in microseconds `µs`. By starting to use steady clock in fabf1cdb206e368a9433abf99a5ea2762a5ed2c0 this changed to nanoseconds `ns`. As the test only checked if the duration value is `> 0` as a plausibility check, this went unnoticed. I 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 (as it has been nanoseconds for the last three releases; switching back now would 'break' the broken API again; there don't seem to be many users affected), 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 incorrect duration units passed. --- contrib/tracing/connectblock_benchmark.bt | 8 ++++---- doc/tracing.md | 2 +- src/validation.cpp | 2 +- test/functional/interface_usdt_validation.py | 15 +++++++++++---- 4 files changed, 17 insertions(+), 10 deletions(-) diff --git a/contrib/tracing/connectblock_benchmark.bt b/contrib/tracing/connectblock_benchmark.bt index 4aa47421031..de112af639c 100755 --- a/contrib/tracing/connectblock_benchmark.bt +++ b/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 . */ -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); } diff --git a/doc/tracing.md b/doc/tracing.md index 3948b1ab499..c12af122db5 100644 --- a/doc/tracing.md +++ b/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` diff --git a/src/validation.cpp b/src/validation.cpp index 9571e144cf2..3a64be753b4 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -2738,7 +2738,7 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, block.vtx.size(), nInputs, nSigOpsCost, - time_5 - time_start // in microseconds (µs) + Ticks(time_5 - time_start) ); return true; diff --git a/test/functional/interface_usdt_validation.py b/test/functional/interface_usdt_validation.py index 9a37b96ada8..8a98a452de7 100755 --- a/test/functional/interface_usdt_validation.py +++ b/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))