diff --git a/contrib/tracing/README.md b/contrib/tracing/README.md index a409a23ef8d..206bec16478 100644 --- a/contrib/tracing/README.md +++ b/contrib/tracing/README.md @@ -286,3 +286,53 @@ Spent a05880b8c77971ed0b9f73062c7c4cdb0ff3856ab14cbf8bc481ed571cd34b83:1 Added eb689865f7d957938978d6207918748f74e6aa074f47874724327089445b0960:0 5589696005 2094513 No Added eb689865f7d957938978d6207918748f74e6aa074f47874724327089445b0960:1 1565556 2094513 No ``` + +### mempool_monitor.py + +A BCC Python script producing mempool statistics and an event log. Based on the +`mempool:added`, `mempool:removed`, `mempool:replaced`, and `mempool:rejected` +tracepoints. + +Statistics include incidence and rate for each event type since the script was +started (`total`) as well as during the last minute (`1 min`) and ten minutes +(`10 min`). The event log shows mempool events in real time, each entry +comprising a timestamp along with all event data available via the event's +tracepoint. + +```console +$ python3 contrib/tracing/mempool_monitor.py ./src/bitcoind +``` + +``` + Mempool Monitor + Press CTRL-C to stop. + + ┌─Event count───────────────────────┐ ┌─Event rate──────────────────────────┐ + │ Event total 1 min 10 min │ │ Event total 1 min 10 min │ + │ added 1425tx 201tx 1425tx │ │ added 4.7tx/s 3.4tx/s 4.7tx/s │ + │ removed 35tx 4tx 35tx │ │ removed 0.1tx/s 0.1tx/s 0.1tx/s │ + │ replaced 35tx 4tx 35tx │ │ replaced 0.1tx/s 0.1tx/s 0.1tx/s │ + │ rejected 0tx 0tx 0tx │ │ rejected 0.0tx/s 0.0tx/s 0.0tx/s │ + └───────────────────────────────────┘ └─────────────────────────────────────┘ + + ┌─Event log────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐ + │ 13:10:30Z added f9064ca5bfc87cdd191faa42bf697217cd920b2b94838c1f1192e4f06c4fd217 with feerate 8.92 sat/vB (981 sat, 110 vbytes) │ + │ 13:10:30Z added 53ffa3afbe57b1bfe423e1755ca2b52c5b6cb4aa91b8b7ee9cb694953f47f234 with feerate 5.00 sat/vB (550 sat, 110 vbytes) │ + │ 13:10:30Z added 4177df5e19465eb5e53c3f8b6830a293f57474921bc6c2ae89375e0986e1f0f9 with feerate 2.98 sat/vB (429 sat, 144 vbytes) │ + │ 13:10:30Z added 931a10d83f0a268768da75dc4b9e199f2f055f12979ae5491cc304ee10f890ea with feerate 3.55 sat/vB (500 sat, 141 vbytes) │ + │ 13:10:30Z added 4cf32b295723cc4ab73f2a2e51d4bb276c0042760a4c00a3eb9595b8ebb24721 with feerate 89.21 sat/vB (12668 sat, 142 vbytes) │ + │ 13:10:31Z replaced d1eecf9d662121322f4f31f0c2267a752d14bb3956e6016ba96e87f47890e1db with feerate 27.12 sat/vB received 23.3 seconds ago (7213 sat, 266 vbytes) with c412db908│ + │ 9b7ed53f3e5e36d2819dd291278b59ccaabaeb17fd37c3d87fdcd57 with feerate 28.12 sat/vB (8351 sat, 297 vbytes) │ + │ 13:10:31Z added c412db9089b7ed53f3e5e36d2819dd291278b59ccaabaeb17fd37c3d87fdcd57 with feerate 28.12 sat/vB (8351 sat, 297 vbytes) │ + │ 13:10:31Z added b8388a5bdc421b11460bdf477d5a85a1a39c2784e7dd7bffabe688740424ea57 with feerate 25.21 sat/vB (3554 sat, 141 vbytes) │ + │ 13:10:31Z added 4ddb88bc90a122cd9eae8a664e73bdf5bebe75f3ef901241b4a251245854a98e with feerate 24.15 sat/vB (5072 sat, 210 vbytes) │ + │ 13:10:31Z added 19101e4161bca5271ad5d03e7747f2faec7793b274dc2f3c4cf516b7cef1aac3 with feerate 7.06 sat/vB (1080 sat, 153 vbytes) │ + │ 13:10:31Z removed d1eecf9d662121322f4f31f0c2267a752d14bb3956e6016ba96e87f47890e1db with feerate 27.12 sat/vB (7213 sat, 266 vbytes): replaced │ + │ 13:10:31Z added 6c511c60d9b95b9eff81df6ecba5c86780f513fe62ce3ad6be2c5340d957025a with feerate 4.00 sat/vB (440 sat, 110 vbytes) │ + │ 13:10:31Z added 44d66f7f004bd52c46be4dff3067cab700e51c7866a84282bd8aab560a5bfb79 with feerate 3.15 sat/vB (448 sat, 142 vbytes) │ + │ 13:10:31Z added b17b7c9ec5acfbbf12f0eeef8e29826fad3105bb95eef7a47d2f1f22b4784643 with feerate 4.10 sat/vB (1348 sat, 329 vbytes) │ + │ 13:10:31Z added b7a4ad93554e57454e8a8049bfc0bd803fa962bd3f0a08926aa72e7cb23e2276 with feerate 1.01 sat/vB (205 sat, 202 vbytes) │ + │ 13:10:32Z added c78e87be86c828137a6e7e00a177c03b52202ce4c39029b99904c2a094b9da87 with feerate 11.00 sat/vB (1562 sat, 142 vbytes) │ + │ │ + └──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘ +``` diff --git a/contrib/tracing/mempool_monitor.py b/contrib/tracing/mempool_monitor.py new file mode 100755 index 00000000000..9d427d4632a --- /dev/null +++ b/contrib/tracing/mempool_monitor.py @@ -0,0 +1,372 @@ +#!/usr/bin/env python3 +# Copyright (c) 2022 The Bitcoin Core developers +# Distributed under the MIT software license, see the accompanying +# file COPYING or http://www.opensource.org/licenses/mit-license.php. + +""" Example logging Bitcoin Core mempool events using the mempool:added, + mempool:removed, mempool:replaced, and mempool:rejected tracepoints. """ + +import curses +import sys +from datetime import datetime, timezone + +from bcc import BPF, USDT + +# BCC: The C program to be compiled to an eBPF program (by BCC) and loaded into +# a sandboxed Linux kernel VM. +PROGRAM = """ +# include + +// The longest rejection reason is 118 chars and is generated in case of SCRIPT_ERR_EVAL_FALSE by +// strprintf("mandatory-script-verify-flag-failed (%s)", ScriptErrorString(check.GetScriptError())) +#define MAX_REJECT_REASON_LENGTH 118 +// The longest string returned by RemovalReasonToString() is 'sizelimit' +#define MAX_REMOVAL_REASON_LENGTH 9 +#define HASH_LENGTH 32 + +struct added_event +{ + u8 hash[HASH_LENGTH]; + u64 vsize; + s64 fee; +}; + +struct removed_event +{ + u8 hash[HASH_LENGTH]; + char reason[MAX_REMOVAL_REASON_LENGTH]; + u64 vsize; + s64 fee; + u64 entry_time; +}; + +struct rejected_event +{ + u8 hash[HASH_LENGTH]; + char reason[MAX_REJECT_REASON_LENGTH]; +}; + +struct replaced_event +{ + u8 replaced_hash[HASH_LENGTH]; + u64 replaced_vsize; + s64 replaced_fee; + u64 replaced_entry_time; + u8 replacement_hash[HASH_LENGTH]; + u64 replacement_vsize; + s64 replacement_fee; +}; + +// BPF perf buffer to push the data to user space. +BPF_PERF_OUTPUT(added_events); +BPF_PERF_OUTPUT(removed_events); +BPF_PERF_OUTPUT(rejected_events); +BPF_PERF_OUTPUT(replaced_events); + +int trace_added(struct pt_regs *ctx) { + struct added_event added = {}; + + bpf_usdt_readarg_p(1, ctx, &added.hash, HASH_LENGTH); + bpf_usdt_readarg(2, ctx, &added.vsize); + bpf_usdt_readarg(3, ctx, &added.fee); + + added_events.perf_submit(ctx, &added, sizeof(added)); + return 0; +} + +int trace_removed(struct pt_regs *ctx) { + struct removed_event removed = {}; + + bpf_usdt_readarg_p(1, ctx, &removed.hash, HASH_LENGTH); + bpf_usdt_readarg_p(2, ctx, &removed.reason, MAX_REMOVAL_REASON_LENGTH); + bpf_usdt_readarg(3, ctx, &removed.vsize); + bpf_usdt_readarg(4, ctx, &removed.fee); + bpf_usdt_readarg(5, ctx, &removed.entry_time); + + removed_events.perf_submit(ctx, &removed, sizeof(removed)); + return 0; +} + +int trace_rejected(struct pt_regs *ctx) { + struct rejected_event rejected = {}; + + bpf_usdt_readarg_p(1, ctx, &rejected.hash, HASH_LENGTH); + bpf_usdt_readarg_p(2, ctx, &rejected.reason, MAX_REJECT_REASON_LENGTH); + + rejected_events.perf_submit(ctx, &rejected, sizeof(rejected)); + return 0; +} + +int trace_replaced(struct pt_regs *ctx) { + struct replaced_event replaced = {}; + + bpf_usdt_readarg_p(1, ctx, &replaced.replaced_hash, HASH_LENGTH); + bpf_usdt_readarg(2, ctx, &replaced.replaced_vsize); + bpf_usdt_readarg(3, ctx, &replaced.replaced_fee); + bpf_usdt_readarg(4, ctx, &replaced.replaced_entry_time); + bpf_usdt_readarg_p(5, ctx, &replaced.replacement_hash, HASH_LENGTH); + bpf_usdt_readarg(6, ctx, &replaced.replacement_vsize); + bpf_usdt_readarg(7, ctx, &replaced.replacement_fee); + + replaced_events.perf_submit(ctx, &replaced, sizeof(replaced)); + return 0; +} +""" + + +def main(bitcoind_path): + bitcoind_with_usdts = USDT(path=str(bitcoind_path)) + + # attaching the trace functions defined in the BPF program + # to the tracepoints + bitcoind_with_usdts.enable_probe(probe="mempool:added", fn_name="trace_added") + bitcoind_with_usdts.enable_probe(probe="mempool:removed", fn_name="trace_removed") + bitcoind_with_usdts.enable_probe(probe="mempool:replaced", fn_name="trace_replaced") + bitcoind_with_usdts.enable_probe(probe="mempool:rejected", fn_name="trace_rejected") + bpf = BPF(text=PROGRAM, usdt_contexts=[bitcoind_with_usdts]) + + events = [] + + def get_timestamp(): + return datetime.now(timezone.utc) + + def handle_added(_, data, size): + event = bpf["added_events"].event(data) + events.append((get_timestamp(), "added", event)) + + def handle_removed(_, data, size): + event = bpf["removed_events"].event(data) + events.append((get_timestamp(), "removed", event)) + + def handle_rejected(_, data, size): + event = bpf["rejected_events"].event(data) + events.append((get_timestamp(), "rejected", event)) + + def handle_replaced(_, data, size): + event = bpf["replaced_events"].event(data) + events.append((get_timestamp(), "replaced", event)) + + bpf["added_events"].open_perf_buffer(handle_added) + # By default, open_perf_buffer uses eight pages for a buffer, making for a total + # buffer size of 32k on most machines. In practice, this size is insufficient: + # Each `mempool:removed` event takes up 57 bytes in the buffer (32 bytes for txid, + # 9 bytes for removal reason, and 8 bytes each for vsize and fee). Full blocks + # contain around 2k transactions, requiring a buffer size of around 114kB. To cover + # this amount, 32 4k pages are required. + bpf["removed_events"].open_perf_buffer(handle_removed, page_cnt=32) + bpf["rejected_events"].open_perf_buffer(handle_rejected) + bpf["replaced_events"].open_perf_buffer(handle_replaced) + + curses.wrapper(loop, bpf, events) + + +def loop(screen, bpf, events): + dashboard = Dashboard(screen) + while True: + try: + bpf.perf_buffer_poll(timeout=50) + dashboard.render(events) + except KeyboardInterrupt: + exit() + + +class Dashboard: + """Visualization of mempool state using ncurses.""" + + INFO_WIN_HEIGHT = 2 + EVENT_WIN_HEIGHT = 7 + + def __init__(self, screen): + screen.nodelay(True) + curses.curs_set(False) + self._screen = screen + self._time_started = datetime.now(timezone.utc) + self._timestamps = {"added": [], "removed": [], "rejected": [], "replaced": []} + self._event_history = {"added": 0, "removed": 0, "rejected": 0, "replaced": 0} + self._init_windows() + + def _init_windows(self): + """Initialize all windows.""" + self._init_info_win() + self._init_event_count_win() + self._init_event_rate_win() + self._init_event_log_win() + + @staticmethod + def create_win(x, y, height, width, title=None): + """Helper function to create generic windows and decorate them with box and title if requested.""" + win = curses.newwin(height, width, x, y) + if title: + win.box() + win.addstr(0, 2, title, curses.A_BOLD) + return win + + def _init_info_win(self): + """Create and populate the info window.""" + self._info_win = Dashboard.create_win( + x=0, y=1, height=Dashboard.INFO_WIN_HEIGHT, width=22 + ) + self._info_win.addstr(0, 0, "Mempool Monitor", curses.A_REVERSE) + self._info_win.addstr(1, 0, "Press CTRL-C to stop.", curses.A_NORMAL) + self._info_win.refresh() + + def _init_event_count_win(self): + """Create and populate the event count window.""" + self._event_count_win = Dashboard.create_win( + x=3, y=1, height=Dashboard.EVENT_WIN_HEIGHT, width=37, title="Event count" + ) + header = " {:<8} {:>8} {:>7} {:>7} " + self._event_count_win.addstr( + 1, 1, header.format("Event", "total", "1 min", "10 min"), curses.A_UNDERLINE + ) + self._event_count_win.refresh() + + def _init_event_rate_win(self): + """Create and populate the event rate window.""" + self._event_rate_win = Dashboard.create_win( + x=3, y=40, height=Dashboard.EVENT_WIN_HEIGHT, width=42, title="Event rate" + ) + header = " {:<8} {:>9} {:>9} {:>9} " + self._event_rate_win.addstr( + 1, 1, header.format("Event", "total", "1 min", "10 min"), curses.A_UNDERLINE + ) + self._event_rate_win.refresh() + + def _init_event_log_win(self): + """Create windows showing event log. This comprises a dummy boxed window and an + inset window so line breaks don't overwrite box.""" + # dummy boxed window + num_rows, num_cols = self._screen.getmaxyx() + space_above = Dashboard.INFO_WIN_HEIGHT + 1 + Dashboard.EVENT_WIN_HEIGHT + 1 + box_win_height = num_rows - space_above + box_win_width = num_cols - 2 + win_box = Dashboard.create_win( + x=space_above, + y=1, + height=box_win_height, + width=box_win_width, + title="Event log", + ) + # actual logging window + log_lines = box_win_height - 2 # top and bottom box lines + log_line_len = box_win_width - 2 - 1 # box lines and left padding + win = win_box.derwin(log_lines, log_line_len, 1, 2) + win.idlok(True) + win.scrollok(True) + win_box.refresh() + win.refresh() + self._event_log_win_box = win_box + self._event_log_win = win + + def calculate_metrics(self, events): + """Calculate count and rate metrics.""" + count, rate = {}, {} + for event_ts, event_type, event_data in events: + self._timestamps[event_type].append(event_ts) + for event_type, ts in self._timestamps.items(): + # remove timestamps older than ten minutes but keep track of their + # count for the 'total' metric + # + self._event_history[event_type] += len( + [t for t in ts if Dashboard.timestamp_age(t) >= 600] + ) + ts = [t for t in ts if Dashboard.timestamp_age(t) < 600] + self._timestamps[event_type] = ts + # count metric + count_1m = len([t for t in ts if Dashboard.timestamp_age(t) < 60]) + count_10m = len(ts) + count_total = self._event_history[event_type] + len(ts) + count[event_type] = (count_total, count_1m, count_10m) + # rate metric + runtime = Dashboard.timestamp_age(self._time_started) + rate_1m = count_1m / min(60, runtime) + rate_10m = count_10m / min(600, runtime) + rate_total = count_total / runtime + rate[event_type] = (rate_total, rate_1m, rate_10m) + return count, rate + + def _update_event_count(self, count): + """Update the event count window.""" + w = self._event_count_win + row_format = " {:<8} {:>6}tx {:>5}tx {:>5}tx " + for line, metric in enumerate(["added", "removed", "replaced", "rejected"]): + w.addstr(2 + line, 1, row_format.format(metric, *count[metric])) + w.refresh() + + def _update_event_rate(self, rate): + """Update the event rate window.""" + w = self._event_rate_win + row_format = " {:<8} {:>5.1f}tx/s {:>5.1f}tx/s {:>5.1f}tx/s " + for line, metric in enumerate(["added", "removed", "replaced", "rejected"]): + w.addstr(2 + line, 1, row_format.format(metric, *rate[metric])) + w.refresh() + + def _update_event_log(self, events): + """Update the event log window.""" + w = self._event_log_win + for event in events: + w.addstr(Dashboard.parse_event(event) + "\n") + w.refresh() + + def render(self, events): + """Render the dashboard.""" + count, rate = self.calculate_metrics(events) + self._update_event_count(count) + self._update_event_rate(rate) + self._update_event_log(events) + events.clear() + + @staticmethod + def parse_event(event): + """Converts events into human-readable messages""" + + ts_dt, type_, data = event + ts = ts_dt.strftime("%H:%M:%SZ") + if type_ == "added": + return ( + f"{ts} added {bytes(data.hash)[::-1].hex()}" + f" with feerate {data.fee/data.vsize:.2f} sat/vB" + f" ({data.fee} sat, {data.vsize} vbytes)" + ) + + if type_ == "removed": + return ( + f"{ts} removed {bytes(data.hash)[::-1].hex()}" + f" with feerate {data.fee/data.vsize:.2f} sat/vB" + f" ({data.fee} sat, {data.vsize} vbytes)" + f" received {ts_dt.timestamp()-data.entry_time:.1f} seconds ago" + f": {data.reason.decode('UTF-8')}" + ) + + if type_ == "rejected": + return ( + f"{ts} rejected {bytes(data.hash)[::-1].hex()}" + f": {data.reason.decode('UTF-8')}" + ) + + if type_ == "replaced": + return ( + f"{ts} replaced {bytes(data.replaced_hash)[::-1].hex()}" + f" with feerate {data.replaced_fee/data.replaced_vsize:.2f} sat/vB" + f" received {ts_dt.timestamp()-data.replaced_entry_time:.1f} seconds ago" + f" ({data.replaced_fee} sat, {data.replaced_vsize} vbytes)" + f" with {bytes(data.replacement_hash)[::-1].hex()}" + f" with feerate {data.replacement_fee/data.replacement_vsize:.2f} sat/vB" + f" ({data.replacement_fee} sat, {data.replacement_vsize} vbytes)" + ) + + raise NotImplementedError("Unsupported event type: {type_}") + + @staticmethod + def timestamp_age(timestamp): + """Return age of timestamp in seconds.""" + return (datetime.now(timezone.utc) - timestamp).total_seconds() + + +if __name__ == "__main__": + if len(sys.argv) < 2: + print("USAGE: ", sys.argv[0], "path/to/bitcoind") + exit(1) + + path = sys.argv[1] + main(path) diff --git a/doc/tracing.md b/doc/tracing.md index 6e60901496b..d26cf52fc3b 100644 --- a/doc/tracing.md +++ b/doc/tracing.md @@ -211,6 +211,58 @@ Arguments passed: 4. The expected transaction fee as an `int64` 5. The position of the change output as an `int32` +### Context `mempool` + +#### Tracepoint `mempool:added` + +Is called when a transaction is added to the node's mempool. Passes information +about the transaction. + +Arguments passed: +1. Transaction ID (hash) as `pointer to unsigned chars` (i.e. 32 bytes in little-endian) +2. Transaction virtual size as `uint64` +3. Transaction fee as `int64` + +#### Tracepoint `mempool:removed` + +Is called when a transaction is removed from the node's mempool. Passes information +about the transaction. + +Arguments passed: +1. Transaction ID (hash) as `pointer to unsigned chars` (i.e. 32 bytes in little-endian) +2. Removal reason as `pointer to C-style String` (max. length 9 characters) +3. Transaction virtual size as `uint64` +4. Transaction fee as `int64` +5. Transaction mempool entry time (epoch) as `uint64` + +#### Tracepoint `mempool:replaced` + +Is called when a transaction in the node's mempool is getting replaced by another. +Passes information about the replaced and replacement transactions. + +Arguments passed: +1. Replaced transaction ID (hash) as `pointer to unsigned chars` (i.e. 32 bytes in little-endian) +2. Replaced transaction virtual size as `uint64` +3. Replaced transaction fee as `int64` +4. Replaced transaction mempool entry time (epoch) as `uint64` +5. Replacement transaction ID (hash) as `pointer to unsigned chars` (i.e. 32 bytes in little-endian) +6. Replacement transaction virtual size as `uint64` +7. Replacement transaction fee as `int64` + +Note: In cases where a single replacement transaction replaces multiple +existing transactions in the mempool, the tracepoint is called once for each +replaced transaction, with data of the replacement transaction being the same +in each call. + +#### Tracepoint `mempool:rejected` + +Is called when a transaction is not permitted to enter the mempool. Passes +information about the rejected transaction. + +Arguments passed: +1. Transaction ID (hash) as `pointer to unsigned chars` (i.e. 32 bytes in little-endian) +2. Reject reason as `pointer to C-style String` (max. length 118 characters) + ## Adding tracepoints to Bitcoin Core To add a new tracepoint, `#include ` in the compilation unit where diff --git a/src/txmempool.cpp b/src/txmempool.cpp index aa04f8a4d06..43579c0dc0b 100644 --- a/src/txmempool.cpp +++ b/src/txmempool.cpp @@ -20,6 +20,7 @@ #include #include #include +#include #include #include @@ -464,6 +465,12 @@ void CTxMemPool::addUnchecked(const CTxMemPoolEntry &entry, setEntries &setAnces vTxHashes.emplace_back(tx.GetWitnessHash(), newit); newit->vTxHashesIdx = vTxHashes.size() - 1; + + TRACE3(mempool, added, + entry.GetTx().GetHash().data(), + entry.GetTxSize(), + entry.GetFee() + ); } void CTxMemPool::removeUnchecked(txiter it, MemPoolRemovalReason reason) @@ -479,6 +486,13 @@ void CTxMemPool::removeUnchecked(txiter it, MemPoolRemovalReason reason) // notification. GetMainSignals().TransactionRemovedFromMempool(it->GetSharedTx(), reason, mempool_sequence); } + TRACE5(mempool, removed, + it->GetTx().GetHash().data(), + RemovalReasonToString(reason).c_str(), + it->GetTxSize(), + it->GetFee(), + std::chrono::duration_cast>(it->GetTime()).count() + ); const uint256 hash = it->GetTx().GetHash(); for (const CTxIn& txin : it->GetTx().vin) diff --git a/src/validation.cpp b/src/validation.cpp index b42b398619c..a6a2f62791b 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -1049,6 +1049,15 @@ bool MemPoolAccept::Finalize(const ATMPArgs& args, Workspace& ws) hash.ToString(), FormatMoney(ws.m_modified_fees - ws.m_conflicting_fees), (int)entry->GetTxSize() - (int)ws.m_conflicting_size); + TRACE7(mempool, replaced, + it->GetTx().GetHash().data(), + it->GetTxSize(), + it->GetFee(), + std::chrono::duration_cast>(it->GetTime()).count(), + hash.data(), + entry->GetTxSize(), + entry->GetFee() + ); ws.m_replaced_transactions.push_back(it->GetSharedTx()); } m_pool.RemoveStaged(ws.m_all_conflicting, false, MemPoolRemovalReason::REPLACED); @@ -1461,6 +1470,10 @@ MempoolAcceptResult AcceptToMemoryPool(Chainstate& active_chainstate, const CTra for (const COutPoint& hashTx : coins_to_uncache) active_chainstate.CoinsTip().Uncache(hashTx); + TRACE2(mempool, rejected, + tx->GetHash().data(), + result.m_state.GetRejectReason().c_str() + ); } // After we've (potentially) uncached entries, ensure our coins cache is still within its size limits BlockValidationState state_dummy; diff --git a/test/functional/interface_usdt_mempool.py b/test/functional/interface_usdt_mempool.py new file mode 100755 index 00000000000..ec2f9e4e778 --- /dev/null +++ b/test/functional/interface_usdt_mempool.py @@ -0,0 +1,343 @@ +#!/usr/bin/env python3 +# Copyright (c) 2022 The Bitcoin Core developers +# Distributed under the MIT software license, see the accompanying +# file COPYING or http://www.opensource.org/licenses/mit-license.php. + +""" Tests the mempool:* tracepoint API interface. + See https://github.com/bitcoin/bitcoin/blob/master/doc/tracing.md#context-mempool +""" + +from decimal import Decimal + +# Test will be skipped if we don't have bcc installed +try: + from bcc import BPF, USDT # type: ignore[import] +except ImportError: + pass + +from test_framework.blocktools import COINBASE_MATURITY +from test_framework.messages import COIN, DEFAULT_MEMPOOL_EXPIRY_HOURS +from test_framework.p2p import P2PDataStore +from test_framework.test_framework import BitcoinTestFramework +from test_framework.util import assert_equal +from test_framework.wallet import MiniWallet + +MEMPOOL_TRACEPOINTS_PROGRAM = """ +# include + +// The longest rejection reason is 118 chars and is generated in case of SCRIPT_ERR_EVAL_FALSE by +// strprintf("mandatory-script-verify-flag-failed (%s)", ScriptErrorString(check.GetScriptError())) +#define MAX_REJECT_REASON_LENGTH 118 +// The longest string returned by RemovalReasonToString() is 'sizelimit' +#define MAX_REMOVAL_REASON_LENGTH 9 +#define HASH_LENGTH 32 + +struct added_event +{ + u8 hash[HASH_LENGTH]; + u64 vsize; + s64 fee; +}; + +struct removed_event +{ + u8 hash[HASH_LENGTH]; + char reason[MAX_REMOVAL_REASON_LENGTH]; + u64 vsize; + s64 fee; + u64 entry_time; +}; + +struct rejected_event +{ + u8 hash[HASH_LENGTH]; + char reason[MAX_REJECT_REASON_LENGTH]; +}; + +struct replaced_event +{ + u8 replaced_hash[HASH_LENGTH]; + u64 replaced_vsize; + s64 replaced_fee; + u64 replaced_entry_time; + u8 replacement_hash[HASH_LENGTH]; + u64 replacement_vsize; + s64 replacement_fee; +}; + +// BPF perf buffer to push the data to user space. +BPF_PERF_OUTPUT(added_events); +BPF_PERF_OUTPUT(removed_events); +BPF_PERF_OUTPUT(rejected_events); +BPF_PERF_OUTPUT(replaced_events); + +int trace_added(struct pt_regs *ctx) { + struct added_event added = {}; + + bpf_usdt_readarg_p(1, ctx, &added.hash, HASH_LENGTH); + bpf_usdt_readarg(2, ctx, &added.vsize); + bpf_usdt_readarg(3, ctx, &added.fee); + + added_events.perf_submit(ctx, &added, sizeof(added)); + return 0; +} + +int trace_removed(struct pt_regs *ctx) { + struct removed_event removed = {}; + + bpf_usdt_readarg_p(1, ctx, &removed.hash, HASH_LENGTH); + bpf_usdt_readarg_p(2, ctx, &removed.reason, MAX_REMOVAL_REASON_LENGTH); + bpf_usdt_readarg(3, ctx, &removed.vsize); + bpf_usdt_readarg(4, ctx, &removed.fee); + bpf_usdt_readarg(5, ctx, &removed.entry_time); + + removed_events.perf_submit(ctx, &removed, sizeof(removed)); + return 0; +} + +int trace_rejected(struct pt_regs *ctx) { + struct rejected_event rejected = {}; + + bpf_usdt_readarg_p(1, ctx, &rejected.hash, HASH_LENGTH); + bpf_usdt_readarg_p(2, ctx, &rejected.reason, MAX_REJECT_REASON_LENGTH); + + rejected_events.perf_submit(ctx, &rejected, sizeof(rejected)); + return 0; +} + +int trace_replaced(struct pt_regs *ctx) { + struct replaced_event replaced = {}; + + bpf_usdt_readarg_p(1, ctx, &replaced.replaced_hash, HASH_LENGTH); + bpf_usdt_readarg(2, ctx, &replaced.replaced_vsize); + bpf_usdt_readarg(3, ctx, &replaced.replaced_fee); + bpf_usdt_readarg(4, ctx, &replaced.replaced_entry_time); + bpf_usdt_readarg_p(5, ctx, &replaced.replacement_hash, HASH_LENGTH); + bpf_usdt_readarg(6, ctx, &replaced.replacement_vsize); + bpf_usdt_readarg(7, ctx, &replaced.replacement_fee); + + replaced_events.perf_submit(ctx, &replaced, sizeof(replaced)); + return 0; +} +""" + + +class MempoolTracepointTest(BitcoinTestFramework): + def set_test_params(self): + self.num_nodes = 1 + self.setup_clean_chain = True + + def skip_test_if_missing_module(self): + self.skip_if_platform_not_linux() + self.skip_if_no_bitcoind_tracepoints() + self.skip_if_no_python_bcc() + self.skip_if_no_bpf_permissions() + + def added_test(self): + """Add a transaction to the mempool and make sure the tracepoint returns + the expected txid, vsize, and fee.""" + + EXPECTED_ADDED_EVENTS = 1 + handled_added_events = 0 + + self.log.info("Hooking into mempool:added tracepoint...") + node = self.nodes[0] + ctx = USDT(pid=node.process.pid) + ctx.enable_probe(probe="mempool:added", fn_name="trace_added") + bpf = BPF(text=MEMPOOL_TRACEPOINTS_PROGRAM, usdt_contexts=[ctx], debug=0) + + def handle_added_event(_, data, __): + nonlocal handled_added_events + event = bpf["added_events"].event(data) + assert_equal(txid, bytes(event.hash)[::-1].hex()) + assert_equal(vsize, event.vsize) + assert_equal(fee, event.fee) + handled_added_events += 1 + + bpf["added_events"].open_perf_buffer(handle_added_event) + + self.log.info("Sending transaction...") + fee = Decimal(31200) + tx = self.wallet.send_self_transfer(from_node=node, fee=fee / COIN) + # expected data + txid = tx["txid"] + vsize = tx["tx"].get_vsize() + + self.log.info("Polling buffer...") + bpf.perf_buffer_poll(timeout=200) + + self.log.info("Cleaning up mempool...") + self.generate(node, 1) + + bpf.cleanup() + + self.log.info("Ensuring mempool:added event was handled successfully...") + assert_equal(EXPECTED_ADDED_EVENTS, handled_added_events) + + def removed_test(self): + """Expire a transaction from the mempool and make sure the tracepoint returns + the expected txid, expiry reason, vsize, and fee.""" + + EXPECTED_REMOVED_EVENTS = 1 + handled_removed_events = 0 + + self.log.info("Hooking into mempool:removed tracepoint...") + node = self.nodes[0] + ctx = USDT(pid=node.process.pid) + ctx.enable_probe(probe="mempool:removed", fn_name="trace_removed") + bpf = BPF(text=MEMPOOL_TRACEPOINTS_PROGRAM, usdt_contexts=[ctx], debug=0) + + def handle_removed_event(_, data, __): + nonlocal handled_removed_events + event = bpf["removed_events"].event(data) + assert_equal(txid, bytes(event.hash)[::-1].hex()) + assert_equal(reason, event.reason.decode("UTF-8")) + assert_equal(vsize, event.vsize) + assert_equal(fee, event.fee) + assert_equal(entry_time, event.entry_time) + handled_removed_events += 1 + + bpf["removed_events"].open_perf_buffer(handle_removed_event) + + self.log.info("Sending transaction...") + fee = Decimal(31200) + tx = self.wallet.send_self_transfer(from_node=node, fee=fee / COIN) + # expected data + txid = tx["txid"] + reason = "expiry" + vsize = tx["tx"].get_vsize() + + self.log.info("Fast-forwarding time to mempool expiry...") + entry_time = node.getmempoolentry(txid)["time"] + expiry_time = entry_time + 60 * 60 * DEFAULT_MEMPOOL_EXPIRY_HOURS + 5 + node.setmocktime(expiry_time) + + self.log.info("Triggering expiry...") + self.wallet.get_utxo(txid=txid) + self.wallet.send_self_transfer(from_node=node) + + self.log.info("Polling buffer...") + bpf.perf_buffer_poll(timeout=200) + + bpf.cleanup() + + self.log.info("Ensuring mempool:removed event was handled successfully...") + assert_equal(EXPECTED_REMOVED_EVENTS, handled_removed_events) + + def replaced_test(self): + """Replace one and two transactions in the mempool and make sure the tracepoint + returns the expected txids, vsizes, and fees.""" + + EXPECTED_REPLACED_EVENTS = 1 + handled_replaced_events = 0 + + self.log.info("Hooking into mempool:replaced tracepoint...") + node = self.nodes[0] + ctx = USDT(pid=node.process.pid) + ctx.enable_probe(probe="mempool:replaced", fn_name="trace_replaced") + bpf = BPF(text=MEMPOOL_TRACEPOINTS_PROGRAM, usdt_contexts=[ctx], debug=0) + + def handle_replaced_event(_, data, __): + nonlocal handled_replaced_events + event = bpf["replaced_events"].event(data) + assert_equal(replaced_txid, bytes(event.replaced_hash)[::-1].hex()) + assert_equal(replaced_vsize, event.replaced_vsize) + assert_equal(replaced_fee, event.replaced_fee) + assert_equal(replaced_entry_time, event.replaced_entry_time) + assert_equal(replacement_txid, bytes(event.replacement_hash)[::-1].hex()) + assert_equal(replacement_vsize, event.replacement_vsize) + assert_equal(replacement_fee, event.replacement_fee) + handled_replaced_events += 1 + + bpf["replaced_events"].open_perf_buffer(handle_replaced_event) + + self.log.info("Sending RBF transaction...") + utxo = self.wallet.get_utxo(mark_as_spent=True) + original_fee = Decimal(40000) + original_tx = self.wallet.send_self_transfer( + from_node=node, utxo_to_spend=utxo, fee=original_fee / COIN + ) + entry_time = node.getmempoolentry(original_tx["txid"])["time"] + + self.log.info("Sending replacement transaction...") + replacement_fee = Decimal(45000) + replacement_tx = self.wallet.send_self_transfer( + from_node=node, utxo_to_spend=utxo, fee=replacement_fee / COIN + ) + + # expected data + replaced_txid = original_tx["txid"] + replaced_vsize = original_tx["tx"].get_vsize() + replaced_fee = original_fee + replaced_entry_time = entry_time + replacement_txid = replacement_tx["txid"] + replacement_vsize = replacement_tx["tx"].get_vsize() + + self.log.info("Polling buffer...") + bpf.perf_buffer_poll(timeout=200) + + bpf.cleanup() + + self.log.info("Ensuring mempool:replaced event was handled successfully...") + assert_equal(EXPECTED_REPLACED_EVENTS, handled_replaced_events) + + def rejected_test(self): + """Create an invalid transaction and make sure the tracepoint returns + the expected txid, rejection reason, peer id, and peer address.""" + + EXPECTED_REJECTED_EVENTS = 1 + handled_rejected_events = 0 + + self.log.info("Adding P2P connection...") + node = self.nodes[0] + node.add_p2p_connection(P2PDataStore()) + + self.log.info("Hooking into mempool:rejected tracepoint...") + ctx = USDT(pid=node.process.pid) + ctx.enable_probe(probe="mempool:rejected", fn_name="trace_rejected") + bpf = BPF(text=MEMPOOL_TRACEPOINTS_PROGRAM, usdt_contexts=[ctx], debug=0) + + def handle_rejected_event(_, data, __): + nonlocal handled_rejected_events + event = bpf["rejected_events"].event(data) + assert_equal(txid, bytes(event.hash)[::-1].hex()) + assert_equal(reason, event.reason.decode("UTF-8")) + handled_rejected_events += 1 + + bpf["rejected_events"].open_perf_buffer(handle_rejected_event) + + self.log.info("Sending invalid transaction...") + tx = self.wallet.create_self_transfer(fee_rate=Decimal(0)) + node.p2ps[0].send_txs_and_test([tx["tx"]], node, success=False) + + # expected data + txid = tx["tx"].hash + reason = "min relay fee not met" + + self.log.info("Polling buffer...") + bpf.perf_buffer_poll(timeout=200) + + bpf.cleanup() + + self.log.info("Ensuring mempool:rejected event was handled successfully...") + assert_equal(EXPECTED_REJECTED_EVENTS, handled_rejected_events) + + def run_test(self): + """Tests the mempool:added, mempool:removed, mempool:replaced, + and mempool:rejected tracepoints.""" + + # Create some coinbase transactions and mature them so they can be spent + node = self.nodes[0] + self.wallet = MiniWallet(node) + self.generate(self.wallet, 4) + self.generate(node, COINBASE_MATURITY) + + # Test individual tracepoints + self.added_test() + self.removed_test() + self.replaced_test() + self.rejected_test() + + +if __name__ == "__main__": + MempoolTracepointTest().main() diff --git a/test/functional/test_runner.py b/test/functional/test_runner.py index 4b9bf11d0e4..44c356dfc4c 100755 --- a/test/functional/test_runner.py +++ b/test/functional/test_runner.py @@ -195,6 +195,7 @@ BASE_SCRIPTS = [ 'interface_http.py', 'interface_rpc.py', 'interface_usdt_coinselection.py', + 'interface_usdt_mempool.py', 'interface_usdt_net.py', 'interface_usdt_utxocache.py', 'interface_usdt_validation.py',