interface_usdt_utxocache.py
1 #!/usr/bin/env python3 2 # Copyright (c) 2022-present The Bitcoin Core developers 3 # Distributed under the MIT software license, see the accompanying 4 # file COPYING or http://www.opensource.org/licenses/mit-license.php. 5 6 """ Tests the utxocache:* tracepoint API interface. 7 See https://github.com/bitcoin/bitcoin/blob/master/doc/tracing.md#context-utxocache 8 """ 9 10 import ctypes 11 # Test will be skipped if we don't have bcc installed 12 try: 13 from bcc import BPF, USDT # type: ignore[import] 14 except ImportError: 15 pass 16 from test_framework.messages import COIN 17 from test_framework.test_framework import BitcoinTestFramework 18 from test_framework.util import ( 19 assert_equal, 20 bpf_cflags, 21 ) 22 from test_framework.wallet import MiniWallet 23 24 utxocache_changes_program = """ 25 #include <uapi/linux/ptrace.h> 26 27 typedef signed long long i64; 28 29 struct utxocache_change 30 { 31 char txid[32]; 32 u32 index; 33 u32 height; 34 i64 value; 35 bool is_coinbase; 36 }; 37 38 BPF_PERF_OUTPUT(utxocache_add); 39 int trace_utxocache_add(struct pt_regs *ctx) { 40 struct utxocache_change add = {}; 41 void *ptxid = NULL; 42 bpf_usdt_readarg(1, ctx, &ptxid); 43 bpf_probe_read_user(&add.txid, sizeof(add.txid), ptxid); 44 bpf_usdt_readarg(2, ctx, &add.index); 45 bpf_usdt_readarg(3, ctx, &add.height); 46 bpf_usdt_readarg(4, ctx, &add.value); 47 bpf_usdt_readarg(5, ctx, &add.is_coinbase); 48 utxocache_add.perf_submit(ctx, &add, sizeof(add)); 49 return 0; 50 } 51 52 BPF_PERF_OUTPUT(utxocache_spent); 53 int trace_utxocache_spent(struct pt_regs *ctx) { 54 struct utxocache_change spent = {}; 55 void *ptxid = NULL; 56 bpf_usdt_readarg(1, ctx, &ptxid); 57 bpf_probe_read_user(&spent.txid, sizeof(spent.txid), ptxid); 58 bpf_usdt_readarg(2, ctx, &spent.index); 59 bpf_usdt_readarg(3, ctx, &spent.height); 60 bpf_usdt_readarg(4, ctx, &spent.value); 61 bpf_usdt_readarg(5, ctx, &spent.is_coinbase); 62 utxocache_spent.perf_submit(ctx, &spent, sizeof(spent)); 63 return 0; 64 } 65 66 BPF_PERF_OUTPUT(utxocache_uncache); 67 int trace_utxocache_uncache(struct pt_regs *ctx) { 68 struct utxocache_change uncache = {}; 69 void *ptxid = NULL; 70 bpf_usdt_readarg(1, ctx, &ptxid); 71 bpf_probe_read_user(&uncache.txid, sizeof(uncache.txid), ptxid); 72 bpf_usdt_readarg(2, ctx, &uncache.index); 73 bpf_usdt_readarg(3, ctx, &uncache.height); 74 bpf_usdt_readarg(4, ctx, &uncache.value); 75 bpf_usdt_readarg(5, ctx, &uncache.is_coinbase); 76 utxocache_uncache.perf_submit(ctx, &uncache, sizeof(uncache)); 77 return 0; 78 } 79 """ 80 81 utxocache_flushes_program = """ 82 #include <uapi/linux/ptrace.h> 83 84 typedef signed long long i64; 85 86 struct utxocache_flush 87 { 88 i64 duration; 89 u32 mode; 90 u64 size; 91 u64 memory; 92 bool for_prune; 93 }; 94 95 BPF_PERF_OUTPUT(utxocache_flush); 96 int trace_utxocache_flush(struct pt_regs *ctx) { 97 struct utxocache_flush flush = {}; 98 bpf_usdt_readarg(1, ctx, &flush.duration); 99 bpf_usdt_readarg(2, ctx, &flush.mode); 100 bpf_usdt_readarg(3, ctx, &flush.size); 101 bpf_usdt_readarg(4, ctx, &flush.memory); 102 bpf_usdt_readarg(5, ctx, &flush.for_prune); 103 utxocache_flush.perf_submit(ctx, &flush, sizeof(flush)); 104 return 0; 105 } 106 """ 107 108 FLUSHMODE_NAME = { 109 0: "NONE", 110 1: "IF_NEEDED", 111 2: "PERIODIC", 112 3: "FORCE_FLUSH", 113 4: "FORCE_SYNC", 114 } 115 116 117 class UTXOCacheChange(ctypes.Structure): 118 _fields_ = [ 119 ("txid", ctypes.c_ubyte * 32), 120 ("index", ctypes.c_uint32), 121 ("height", ctypes.c_uint32), 122 ("value", ctypes.c_uint64), 123 ("is_coinbase", ctypes.c_bool), 124 ] 125 126 def __repr__(self): 127 return f"UTXOCacheChange(outpoint={bytes(self.txid[::-1]).hex()}:{self.index}, height={self.height}, value={self.value}sat, is_coinbase={self.is_coinbase})" 128 129 130 class UTXOCacheFlush(ctypes.Structure): 131 _fields_ = [ 132 ("duration", ctypes.c_int64), 133 ("mode", ctypes.c_uint32), 134 ("size", ctypes.c_uint64), 135 ("memory", ctypes.c_uint64), 136 ("for_prune", ctypes.c_bool), 137 ] 138 139 def __repr__(self): 140 return f"UTXOCacheFlush(duration={self.duration}, mode={FLUSHMODE_NAME[self.mode]}, size={self.size}, memory={self.memory}, for_prune={self.for_prune})" 141 142 143 class UTXOCacheTracepointTest(BitcoinTestFramework): 144 def set_test_params(self): 145 self.setup_clean_chain = False 146 self.num_nodes = 1 147 self.extra_args = [["-txindex"]] 148 149 def skip_test_if_missing_module(self): 150 self.skip_if_platform_not_linux() 151 self.skip_if_no_bitcoind_tracepoints() 152 self.skip_if_no_python_bcc() 153 self.skip_if_no_bpf_permissions() 154 self.skip_if_running_under_valgrind() 155 156 def run_test(self): 157 self.wallet = MiniWallet(self.nodes[0]) 158 159 self.test_uncache() 160 self.test_add_spent() 161 self.test_flush() 162 163 def test_uncache(self): 164 """ Tests the utxocache:uncache tracepoint API. 165 https://github.com/bitcoin/bitcoin/blob/master/doc/tracing.md#tracepoint-utxocacheuncache 166 """ 167 # To trigger an UTXO uncache from the cache, we create an invalid transaction 168 # spending a not-cached, but existing UTXO. During transaction validation, this 169 # the UTXO is added to the utxo cache, but as the transaction is invalid, it's 170 # uncached again. 171 self.log.info("testing the utxocache:uncache tracepoint API") 172 173 # Retrieve the txid for the UTXO created in the first block. This UTXO is not 174 # in our UTXO cache. 175 EARLY_BLOCK_HEIGHT = 1 176 block_1_hash = self.nodes[0].getblockhash(EARLY_BLOCK_HEIGHT) 177 block_1 = self.nodes[0].getblock(block_1_hash) 178 block_1_coinbase_txid = block_1["tx"][0] 179 180 # Create a transaction and invalidate it by changing the txid of the previous 181 # output to the coinbase txid of the block at height 1. 182 invalid_tx = self.wallet.create_self_transfer()["tx"] 183 invalid_tx.vin[0].prevout.hash = int(block_1_coinbase_txid, 16) 184 185 self.log.info("hooking into the utxocache:uncache tracepoint") 186 ctx = USDT(pid=self.nodes[0].process.pid) 187 ctx.enable_probe(probe="utxocache:uncache", 188 fn_name="trace_utxocache_uncache") 189 bpf = BPF(text=utxocache_changes_program, usdt_contexts=[ctx], debug=0, cflags=bpf_cflags()) 190 191 # The handle_* function is a ctypes callback function called from C. When 192 # we assert in the handle_* function, the AssertError doesn't propagate 193 # back to Python. The exception is ignored. We manually count and assert 194 # that the handle_* functions succeeded. 195 EXPECTED_HANDLE_UNCACHE_SUCCESS = 1 196 handle_uncache_succeeds = 0 197 198 def handle_utxocache_uncache(_, data, __): 199 nonlocal handle_uncache_succeeds 200 event = ctypes.cast(data, ctypes.POINTER(UTXOCacheChange)).contents 201 self.log.info(f"handle_utxocache_uncache(): {event}") 202 try: 203 assert_equal(block_1_coinbase_txid, bytes(event.txid[::-1]).hex()) 204 assert_equal(0, event.index) # prevout index 205 assert_equal(EARLY_BLOCK_HEIGHT, event.height) 206 assert_equal(50 * COIN, event.value) 207 assert_equal(True, event.is_coinbase) 208 except AssertionError: 209 self.log.exception("Assertion failed") 210 else: 211 handle_uncache_succeeds += 1 212 213 bpf["utxocache_uncache"].open_perf_buffer(handle_utxocache_uncache) 214 215 self.log.info( 216 "testmempoolaccept the invalid transaction to trigger an UTXO-cache uncache") 217 result = self.nodes[0].testmempoolaccept( 218 [invalid_tx.serialize().hex()])[0] 219 assert_equal(result["allowed"], False) 220 221 bpf.perf_buffer_poll(timeout=100) 222 bpf.cleanup() 223 224 self.log.info( 225 f"check that we successfully traced {EXPECTED_HANDLE_UNCACHE_SUCCESS} uncaches") 226 assert_equal(EXPECTED_HANDLE_UNCACHE_SUCCESS, handle_uncache_succeeds) 227 228 def test_add_spent(self): 229 """ Tests the utxocache:add utxocache:spent tracepoint API 230 See https://github.com/bitcoin/bitcoin/blob/master/doc/tracing.md#tracepoint-utxocacheadd 231 and https://github.com/bitcoin/bitcoin/blob/master/doc/tracing.md#tracepoint-utxocachespent 232 """ 233 234 self.log.info( 235 "test the utxocache:add and utxocache:spent tracepoint API") 236 237 self.log.info("create an unconfirmed transaction") 238 self.wallet.send_self_transfer(from_node=self.nodes[0]) 239 240 # We mine a block to trace changes (add/spent) to the active in-memory cache 241 # of the UTXO set (see CoinsTip() of CCoinsViewCache). However, in some cases 242 # temporary clones of the active cache are made. For example, during mining with 243 # the generate RPC call, the block is first tested in TestBlockValidity(). There, 244 # a clone of the active cache is modified during a test ConnectBlock() call. 245 # These are implementation details we don't want to test here. Thus, after 246 # mining, we invalidate the block, start the tracing, and then trace the cache 247 # changes to the active utxo cache. 248 self.log.info("mine and invalidate a block that is later reconsidered") 249 block_hash = self.generate(self.wallet, 1)[0] 250 self.nodes[0].invalidateblock(block_hash) 251 252 self.log.info( 253 "hook into the utxocache:add and utxocache:spent tracepoints") 254 ctx = USDT(pid=self.nodes[0].process.pid) 255 ctx.enable_probe(probe="utxocache:add", fn_name="trace_utxocache_add") 256 ctx.enable_probe(probe="utxocache:spent", 257 fn_name="trace_utxocache_spent") 258 bpf = BPF(text=utxocache_changes_program, usdt_contexts=[ctx], debug=0, cflags=bpf_cflags()) 259 260 # The handle_* function is a ctypes callback function called from C. When 261 # we assert in the handle_* function, the AssertError doesn't propagate 262 # back to Python. The exception is ignored. We manually count and assert 263 # that the handle_* functions succeeded. 264 EXPECTED_HANDLE_ADD_SUCCESS = 2 265 EXPECTED_HANDLE_SPENT_SUCCESS = 1 266 267 expected_utxocache_adds = [] 268 expected_utxocache_spents = [] 269 270 actual_utxocache_adds = [] 271 actual_utxocache_spents = [] 272 273 def handle_utxocache_add(_, data, __): 274 event = ctypes.cast(data, ctypes.POINTER(UTXOCacheChange)).contents 275 self.log.info(f"handle_utxocache_add(): {event}") 276 actual_utxocache_adds.append(event) 277 278 def handle_utxocache_spent(_, data, __): 279 event = ctypes.cast(data, ctypes.POINTER(UTXOCacheChange)).contents 280 self.log.info(f"handle_utxocache_spent(): {event}") 281 actual_utxocache_spents.append(event) 282 283 bpf["utxocache_add"].open_perf_buffer(handle_utxocache_add) 284 bpf["utxocache_spent"].open_perf_buffer(handle_utxocache_spent) 285 286 # We trigger a block re-connection. This causes changes (add/spent) 287 # to the UTXO-cache which in turn triggers the tracepoints. 288 self.log.info("reconsider the previously invalidated block") 289 self.nodes[0].reconsiderblock(block_hash) 290 291 block = self.nodes[0].getblock(block_hash, 2) 292 for (block_index, tx) in enumerate(block["tx"]): 293 for vin in tx["vin"]: 294 if "coinbase" not in vin: 295 prevout_tx = self.nodes[0].getrawtransaction( 296 vin["txid"], True) 297 prevout_tx_block = self.nodes[0].getblockheader( 298 prevout_tx["blockhash"]) 299 spends_coinbase = "coinbase" in prevout_tx["vin"][0] 300 expected_utxocache_spents.append({ 301 "txid": vin["txid"], 302 "index": vin["vout"], 303 "height": prevout_tx_block["height"], 304 "value": int(prevout_tx["vout"][vin["vout"]]["value"] * COIN), 305 "is_coinbase": spends_coinbase, 306 }) 307 for (i, vout) in enumerate(tx["vout"]): 308 if vout["scriptPubKey"]["type"] != "nulldata": 309 expected_utxocache_adds.append({ 310 "txid": tx["txid"], 311 "index": i, 312 "height": block["height"], 313 "value": int(vout["value"] * COIN), 314 "is_coinbase": block_index == 0, 315 }) 316 317 bpf.perf_buffer_poll(timeout=200) 318 319 assert_equal(EXPECTED_HANDLE_ADD_SUCCESS, len(expected_utxocache_adds), len(actual_utxocache_adds)) 320 assert_equal(EXPECTED_HANDLE_SPENT_SUCCESS, len(expected_utxocache_spents), len(actual_utxocache_spents)) 321 322 self.log.info( 323 f"check that we successfully traced {EXPECTED_HANDLE_ADD_SUCCESS} adds and {EXPECTED_HANDLE_SPENT_SUCCESS} spent") 324 325 # Check that all expected tracepoints are received, but not the order they were received in. 326 # Tracepoint ordering is not strictly guaranteed, so this comparison avoids intermittent failures in the test. 327 def cache_event_to_key(event): 328 return ( 329 bytes(event.txid[::-1]).hex(), 330 event.index, 331 event.height, 332 event.value, 333 event.is_coinbase 334 ) 335 336 expected_add_keys = {(e["txid"], e["index"], e["height"], e["value"], e["is_coinbase"]) 337 for e in expected_utxocache_adds} 338 expected_spent_keys = {(e["txid"], e["index"], e["height"], e["value"], e["is_coinbase"]) 339 for e in expected_utxocache_spents} 340 341 actual_add_keys = {cache_event_to_key(e) for e in actual_utxocache_adds} 342 actual_spent_keys = {cache_event_to_key(e) for e in actual_utxocache_spents} 343 344 assert_equal(expected_add_keys, actual_add_keys) 345 assert_equal(expected_spent_keys, actual_spent_keys) 346 347 bpf.cleanup() 348 349 def test_flush(self): 350 """ Tests the utxocache:flush tracepoint API. 351 See https://github.com/bitcoin/bitcoin/blob/master/doc/tracing.md#tracepoint-utxocacheflush""" 352 353 self.log.info("test the utxocache:flush tracepoint API") 354 self.log.info("hook into the utxocache:flush tracepoint") 355 ctx = USDT(pid=self.nodes[0].process.pid) 356 ctx.enable_probe(probe="utxocache:flush", 357 fn_name="trace_utxocache_flush") 358 bpf = BPF(text=utxocache_flushes_program, usdt_contexts=[ctx], debug=0, cflags=bpf_cflags()) 359 360 # The handle_* function is a ctypes callback function called from C. When 361 # we assert in the handle_* function, the AssertError doesn't propagate 362 # back to Python. The exception is ignored. We manually count and assert 363 # that the handle_* functions succeeded. 364 EXPECTED_HANDLE_FLUSH_SUCCESS = 3 365 handle_flush_succeeds = 0 366 expected_flushes = list() 367 368 def handle_utxocache_flush(_, data, __): 369 nonlocal handle_flush_succeeds 370 event = ctypes.cast(data, ctypes.POINTER(UTXOCacheFlush)).contents 371 self.log.info(f"handle_utxocache_flush(): {event}") 372 expected_flushes.remove({ 373 "mode": FLUSHMODE_NAME[event.mode], 374 "for_prune": event.for_prune, 375 "size": event.size 376 }) 377 # sanity checks only 378 try: 379 assert event.memory > 0 380 assert event.duration > 0 381 except AssertionError: 382 self.log.exception("Assertion error") 383 else: 384 handle_flush_succeeds += 1 385 386 bpf["utxocache_flush"].open_perf_buffer(handle_utxocache_flush) 387 388 self.log.info("stop the node to flush the UTXO cache") 389 UTXOS_IN_CACHE = 3 # might need to be changed if the earlier tests are modified 390 # A node shutdown causes two flushes. One that flushes UTXOS_IN_CACHE 391 # UTXOs and one that flushes 0 UTXOs. Normally the 0-UTXO-flush is the 392 # second flush, however it can happen that the order changes. 393 expected_flushes.append({"mode": "FORCE_FLUSH", "for_prune": False, "size": UTXOS_IN_CACHE}) 394 expected_flushes.append({"mode": "FORCE_FLUSH", "for_prune": False, "size": 0}) 395 self.stop_node(0) 396 397 bpf.perf_buffer_poll(timeout=200) 398 bpf.cleanup() 399 400 self.log.info("check that we don't expect additional flushes") 401 assert_equal(0, len(expected_flushes)) 402 403 self.log.info("restart the node with -prune") 404 self.start_node(0, ["-fastprune=1", "-prune=1"]) 405 406 BLOCKS_TO_MINE = 350 407 self.log.info(f"mine {BLOCKS_TO_MINE} blocks to be able to prune") 408 self.generate(self.wallet, BLOCKS_TO_MINE) 409 410 self.log.info("test the utxocache:flush tracepoint API with pruning") 411 self.log.info("hook into the utxocache:flush tracepoint") 412 ctx = USDT(pid=self.nodes[0].process.pid) 413 ctx.enable_probe(probe="utxocache:flush", 414 fn_name="trace_utxocache_flush") 415 bpf = BPF(text=utxocache_flushes_program, usdt_contexts=[ctx], debug=0, cflags=bpf_cflags()) 416 bpf["utxocache_flush"].open_perf_buffer(handle_utxocache_flush) 417 418 self.log.info("prune blockchain to trigger a flush for pruning") 419 expected_flushes.append({"mode": "NONE", "for_prune": True, "size": BLOCKS_TO_MINE}) 420 self.nodes[0].pruneblockchain(315) 421 422 bpf.perf_buffer_poll(timeout=500) 423 bpf.cleanup() 424 425 self.log.info( 426 "check that we don't expect additional flushes and that the handle_* function succeeded") 427 assert_equal(0, len(expected_flushes)) 428 assert_equal(EXPECTED_HANDLE_FLUSH_SUCCESS, handle_flush_succeeds) 429 430 431 if __name__ == '__main__': 432 UTXOCacheTracepointTest(__file__).main()