mirror of https://github.com/bitcoin/bitcoin
Merge bitcoin/bitcoin#26531: mempool: Add mempool tracepoints
4b7aec2951Add mempool tracepoints (virtu) Pull request description: This PR adds multiple mempool tracepoints. | tracepoint | description | | ------------- | ------------- | | `mempool:added` | Is called when a transaction enters the mempool | | `mempool:removed` | ... when a transaction is removed from the mempool | | `mempool:replaced` | ... when a transaction is replaced in the mempool | | `mempool:rejected` | ... when a transaction is rejected from entering the mempool | The tracepoints are further documented in `docs/tracing.md`. Usage is demonstrated in the example script `contrib/tracing/mempool_monitor.py`. Interface tests are provided in `test/functional/interface_usdt_mempool.py`. The rationale for passing the removal reason as a string instead of numerically is that the benefits of not having to maintain a redundant enum-string mapping seem to outweigh the small cost of string generation. The reject reason is passed as string as well, although in this instance the string does not have to be generated but is readily available. ACKs for top commit: 0xB10C: ACK4b7aec2951achow101: ACK4b7aec2951Tree-SHA512: 6deb3ba2d1a061292fb9b0f885f7a5c4d11b109b838102d8a8f4828cd68f5cd03fa3fc64adc6fdf54a08a1eaccce261b0aa90c2b8c33cd5fd3828c8f74978958
This commit is contained in:
Andrew Chow
commit
60f142e395
|
|
@ -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) │
|
||||
│ │
|
||||
└──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
|
||||
```
|
||||
|
|
|
|||
|
|
@ -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 <uapi/linux/ptrace.h>
|
||||
|
||||
// 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)
|
||||
|
|
@ -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 <util/trace.h>` in the compilation unit where
|
||||
|
|
|
|||
|
|
@ -20,6 +20,7 @@
|
|||
#include <util/result.h>
|
||||
#include <util/system.h>
|
||||
#include <util/time.h>
|
||||
#include <util/trace.h>
|
||||
#include <util/translation.h>
|
||||
#include <validationinterface.h>
|
||||
|
||||
|
|
@ -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<std::chrono::duration<std::uint64_t>>(it->GetTime()).count()
|
||||
);
|
||||
|
||||
const uint256 hash = it->GetTx().GetHash();
|
||||
for (const CTxIn& txin : it->GetTx().vin)
|
||||
|
|
|
|||
|
|
@ -1074,6 +1074,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<std::chrono::duration<std::uint64_t>>(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);
|
||||
|
|
@ -1486,6 +1495,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;
|
||||
|
|
|
|||
|
|
@ -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 <uapi/linux/ptrace.h>
|
||||
|
||||
// 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()
|
||||
|
|
@ -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',
|
||||
|
|
|
|||
Loading…
Reference in New Issue