From cad47623041d87620450f674b4da9653cf7a20a7 Mon Sep 17 00:00:00 2001 From: Sjors Provoost Date: Mon, 24 Nov 2025 12:46:29 +0100 Subject: [PATCH 1/2] Log getMemoryLoad() --- src/interfaces/mining.h | 12 ++++++++++++ src/ipc/capnp/mining.capnp | 5 +++++ src/sv2/template_provider.cpp | 27 +++++++++++++++++++++++++++ src/sv2/template_provider.h | 10 ++++++++++ src/test/sv2_mock_mining.cpp | 7 +++++++ src/test/sv2_mock_mining.h | 3 +++ 6 files changed, 64 insertions(+) diff --git a/src/interfaces/mining.h b/src/interfaces/mining.h index ec88829..354a789 100644 --- a/src/interfaces/mining.h +++ b/src/interfaces/mining.h @@ -23,6 +23,12 @@ class CScript; namespace interfaces { +//! Tracks memory usage for template-bound transactions. +struct MemoryLoad +{ + uint64_t usage{0}; +}; + //! Block template interface class BlockTemplate { @@ -129,6 +135,12 @@ class Mining * For signets the challenge verification is skipped when check_pow is false. */ virtual bool checkBlock(const CBlock& block, const node::BlockCheckOptions& options, std::string& reason, std::string& debug) = 0; + + /** + * Returns the current memory load for template transactions outside the + * mempool. + */ + virtual MemoryLoad getMemoryLoad() = 0; }; } // namespace interfaces diff --git a/src/ipc/capnp/mining.capnp b/src/ipc/capnp/mining.capnp index ed01e44..dd6c097 100644 --- a/src/ipc/capnp/mining.capnp +++ b/src/ipc/capnp/mining.capnp @@ -19,6 +19,7 @@ interface Mining $Proxy.wrap("interfaces::Mining") { waitTipChanged @3 (context :Proxy.Context, currentTip: Data, timeout: Float64) -> (result: Common.BlockRef); createNewBlock @4 (options: BlockCreateOptions) -> (result: BlockTemplate); checkBlock @5 (block: Data, options: BlockCheckOptions) -> (reason: Text, debug: Text, result: Bool); + getMemoryLoad @6 (context :Proxy.Context) -> (result: MemoryLoad); } interface BlockTemplate $Proxy.wrap("interfaces::BlockTemplate") { @@ -36,6 +37,10 @@ interface BlockTemplate $Proxy.wrap("interfaces::BlockTemplate") { interruptWait @11() -> (); } +struct MemoryLoad $Proxy.wrap("interfaces::MemoryLoad") { + usage @0 :UInt64; +} + struct BlockCreateOptions $Proxy.wrap("node::BlockCreateOptions") { useMempool @0 :Bool $Proxy.name("use_mempool"); blockReservedWeight @1 :UInt64 $Proxy.name("block_reserved_weight"); diff --git a/src/sv2/template_provider.cpp b/src/sv2/template_provider.cpp index d308cc6..18c95c9 100644 --- a/src/sv2/template_provider.cpp +++ b/src/sv2/template_provider.cpp @@ -17,6 +17,8 @@ #include #include +using interfaces::MemoryLoad; + // Allow a few seconds for clients to submit a block or to request transactions constexpr size_t STALE_TEMPLATE_GRACE_PERIOD{10}; @@ -110,6 +112,8 @@ bool Sv2TemplateProvider::Start(const Sv2TemplateProviderOptions& options) } m_thread_sv2_handler = std::thread(&util::TraceThread, "sv2", [this] { ThreadSv2Handler(); }); + m_thread_memory_handler = std::thread(&util::TraceThread, "memory", [this] { ThreadMemoryHandler(); }); + return true; } @@ -154,6 +158,9 @@ void Sv2TemplateProvider::StopThreads() if (m_thread_sv2_handler.joinable()) { m_thread_sv2_handler.join(); } + if (m_thread_memory_handler.joinable()) { + m_thread_memory_handler.join(); + } } class Timer { @@ -249,6 +256,26 @@ void Sv2TemplateProvider::ThreadSv2Handler() } +void Sv2TemplateProvider::ThreadMemoryHandler() +{ + size_t seconds{0}; + while (!m_flag_interrupt_sv2) { + std::this_thread::sleep_for(1000ms); + if (++seconds % 60 != 0) continue; + if (m_mining.isInitialBlockDownload()) continue; + try { + MemoryLoad memory_load{m_mining.getMemoryLoad()}; + const double usage_mib{static_cast(memory_load.usage) / (1024.0 * 1024.0)}; + const std::string usage_mib_str{strprintf("%.3f", usage_mib)}; + LogTrace(BCLog::SV2, "Template memory footprint %s MiB", usage_mib_str); + } catch (const ipc::Exception& e) { + LogTrace(BCLog::SV2, "getMemoryLoad() not implemented on the node"); + // Nothing to do for this thread + break; + } + } +} + void Sv2TemplateProvider::ThreadSv2ClientHandler(size_t client_id) { try { diff --git a/src/sv2/template_provider.h b/src/sv2/template_provider.h index 68caff9..632720a 100644 --- a/src/sv2/template_provider.h +++ b/src/sv2/template_provider.h @@ -81,6 +81,11 @@ class Sv2TemplateProvider : public Sv2EventsInterface */ std::thread m_thread_sv2_handler; + /** + * Memory management thread + */ + std::thread m_thread_memory_handler; + /** * Signal for handling interrupts and stopping the template provider event loop. */ @@ -129,6 +134,11 @@ class Sv2TemplateProvider : public Sv2EventsInterface */ void ThreadSv2Handler() EXCLUSIVE_LOCKS_REQUIRED(!m_tp_mutex); + /** + * Template memory management thread. + */ + void ThreadMemoryHandler() EXCLUSIVE_LOCKS_REQUIRED(!m_tp_mutex); + /** * Give each client its own thread so they're treated equally * and so that newly connected clients don't have to wait. diff --git a/src/test/sv2_mock_mining.cpp b/src/test/sv2_mock_mining.cpp index 674343b..875b35c 100644 --- a/src/test/sv2_mock_mining.cpp +++ b/src/test/sv2_mock_mining.cpp @@ -123,6 +123,13 @@ std::unique_ptr MockMining::createNewBlock(const node } bool MockMining::checkBlock(const CBlock&, const node::BlockCheckOptions&, std::string&, std::string&) { return true; } +MemoryLoad MockMining::getMemoryLoad() +{ + return { + .usage = 0 + }; +} + uint64_t MockMining::GetTemplateSeq() { LOCK(state->m); diff --git a/src/test/sv2_mock_mining.h b/src/test/sv2_mock_mining.h index 57f1275..e5ec616 100644 --- a/src/test/sv2_mock_mining.h +++ b/src/test/sv2_mock_mining.h @@ -17,6 +17,8 @@ #include #include +using interfaces::MemoryLoad; + // Minimal mocks for the Mining IPC interface used by sv2 tests. struct MockEvent { @@ -82,6 +84,7 @@ class MockMining : public interfaces::Mining { std::optional waitTipChanged(uint256, MillisecondsDouble) override; std::unique_ptr createNewBlock(const node::BlockCreateOptions&) override; bool checkBlock(const CBlock&, const node::BlockCheckOptions&, std::string&, std::string&) override; + MemoryLoad getMemoryLoad() override; // Accessors for tests (thread-safe) uint64_t GetTemplateSeq(); From 1a280b1ead788b95c2c7d0b61b2ecb729a8cbdec Mon Sep 17 00:00:00 2001 From: Sjors Provoost Date: Wed, 3 Dec 2025 14:59:55 +0100 Subject: [PATCH 2/2] contrib: plot getMemoryLoad() Add Python script to make plots. Assisted-by: GitHub Copilot Assisted-by: OpenAI GPT-5.1-Codex --- .gitignore | 2 + contrib/devtools/plot_memory_load.py | 380 +++++++++++++++++++++++++++ 2 files changed, 382 insertions(+) create mode 100755 contrib/devtools/plot_memory_load.py diff --git a/.gitignore b/.gitignore index 3b22e35..c2531b6 100644 --- a/.gitignore +++ b/.gitignore @@ -26,3 +26,5 @@ target/ /guix-build-* /ci/scratch/ + +plots diff --git a/contrib/devtools/plot_memory_load.py b/contrib/devtools/plot_memory_load.py new file mode 100755 index 0000000..dfb691d --- /dev/null +++ b/contrib/devtools/plot_memory_load.py @@ -0,0 +1,380 @@ +#!/usr/bin/env python3 +"""Plot GetTemplateMemoryUsage durations and template memory footprints over time.""" +from __future__ import annotations + +import argparse +import datetime as dt +import pickle +import re +from pathlib import Path +from typing import List, Tuple + +import matplotlib.dates as mdates # type: ignore[import, import-not-found] +import matplotlib.pyplot as plt # type: ignore[import, import-not-found] +from matplotlib import transforms # type: ignore[import, import-not-found] +from matplotlib.ticker import NullFormatter # type: ignore[import, import-not-found] + +MEMORY_LOAD_COMPLETED = re.compile( + r"^(?P\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d+Z).*GetTemplateMemoryUsage:.*completed \((?P\d+\.\d+)ms\)" +) +UPDATE_TIP = re.compile( + r"^(?P\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d+Z).*UpdateTip:.*height=(?P\d+) " +) +TP_LOG_ENTRY = re.compile( + r"^(?P\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(?:\.\d+)?)Z.*Template memory footprint (?P\d+(?:\.\d+)?) MiB" +) + +TIP_LABEL_MIN_FRACTION = 0.02 +CLIPPED_LABEL_MIN_FRACTION = 0.01 +DEFAULT_DURATION_CAP_MS = 15.0 # Hard cap for GetTemplateMemoryUsage durations + + +def format_with_machine(base: str, machine: str | None) -> str: + return f"{base} ({machine})" if machine else base + + +def parse_args() -> argparse.Namespace: + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument( + "bitcoin_log", + type=Path, + help="Path to bitcoin debug log containing GetTemplateMemoryUsage entries", + ) + parser.add_argument( + "--output", + type=Path, + default=Path("getmemoryload-scatter.svg"), + help="Destination image path (default: ./getmemoryload-scatter.svg)", + ) + parser.add_argument( + "--show", + action="store_true", + help="Display the plot interactively instead of saving it", + ) + parser.add_argument( + "tp_log", + type=Path, + help="SV2 template provider log containing 'Template memory footprint' lines", + ) + parser.add_argument( + "--since", + type=str, + default=None, + help=( + "Ignore log events earlier than this ISO 8601 timestamp. Naive timestamps " + "are interpreted as UTC (e.g. '2025-12-02T14:50:00')." + ), + ) + parser.add_argument( + "--duration-cap", + type=float, + default=DEFAULT_DURATION_CAP_MS, + help=( + "Clip GetTemplateMemoryUsage durations above this value (ms) and annotate their " + f"true value at the top of the chart. Default: {DEFAULT_DURATION_CAP_MS:.0f} ms." + ), + ) + parser.add_argument( + "--figure-pickle", + type=Path, + default=None, + help=( + "Optional path to write a pickle of the Matplotlib Figure for further " + "inspection." + ), + ) + parser.add_argument( + "--dpi", + type=int, + default=300, + help="Raster output resolution (applies to PNG/JPEG/TIFF). Default: 300 dpi.", + ) + parser.add_argument( + "--machine", + type=str, + default=None, + help="Optional machine label to append to dataset names (e.g. 'M4').", + ) + return parser.parse_args() + + +def parse_timestamp(raw: str) -> dt.datetime: + """Return timezone-aware UTC timestamps from log entries.""" + parsed = dt.datetime.fromisoformat(raw.replace("Z", "+00:00")) + if parsed.tzinfo is None: + parsed = parsed.replace(tzinfo=dt.timezone.utc) + return parsed.astimezone(dt.timezone.utc) + + +def parse_since_timestamp(raw: str) -> dt.datetime: + sanitized = raw.strip() + if not sanitized: + raise SystemExit("--since timestamp must not be empty") + if sanitized.endswith("Z"): + sanitized = f"{sanitized[:-1]}+00:00" + try: + parsed = dt.datetime.fromisoformat(sanitized) + except ValueError as exc: + raise SystemExit(f"Invalid --since timestamp '{raw}': {exc}") from exc + if parsed.tzinfo is None: + parsed = parsed.replace(tzinfo=dt.timezone.utc) + return parsed.astimezone(dt.timezone.utc) + + +def load_events(log_path: Path, since: dt.datetime | None = None): + mem_points = [] + tip_events = [] + with log_path.open("r", encoding="utf-8") as handle: + for line in handle: + mem_match = MEMORY_LOAD_COMPLETED.search(line) + if mem_match: + timestamp = parse_timestamp(mem_match.group("ts")) + if since is not None and timestamp < since: + continue + mem_points.append((timestamp, float(mem_match.group("ms")))) + continue + tip_match = UPDATE_TIP.search(line) + if tip_match: + timestamp = parse_timestamp(tip_match.group("ts")) + if since is not None and timestamp < since: + continue + tip_events.append((timestamp, int(tip_match.group("height")))) + mem_points.sort(key=lambda item: item[0]) + tip_events.sort(key=lambda item: item[0]) + return mem_points, tip_events + + +def load_tp_points( + log_path: Path, since: dt.datetime | None = None +) -> List[Tuple[dt.datetime, float]]: + tp_points: List[Tuple[dt.datetime, float]] = [] + if not log_path.exists(): + raise SystemExit(f"Template provider log '{log_path}' not found") + + with log_path.open("r", encoding="utf-8") as handle: + for line in handle: + match = TP_LOG_ENTRY.search(line) + if match: + mib_val = float(match.group("mib")) + timestamp = parse_timestamp(match.group("ts")) + if since is not None and timestamp < since: + continue + tp_points.append((timestamp, mib_val)) + + tp_points.sort(key=lambda item: item[0]) + if not tp_points: + raise SystemExit( + f"No template provider entries were found in '{log_path}'. Does it contain " + "'Template memory footprint' lines?" + ) + return tp_points + +def plot_memory_load( + mem_points, + tip_events, + tp_points, + duration_cap, + figure_pickle: Path | None, + dpi: int, + machine_label: str | None, + output: Path, + show_plot: bool, +) -> None: + if not mem_points: + raise SystemExit("No GetTemplateMemoryUsage() completion records found in log") + + times, durations = zip(*mem_points) + fig, ax = plt.subplots(figsize=(15, 5)) + fig.patch.set_facecolor("white") + fig.patch.set_alpha(1.0) + ax.set_facecolor("white") + duration_label = format_with_machine("GetTemplateMemoryUsage() duration", machine_label) + ax.scatter( + times, + durations, + s=5, + color="tab:blue", + label=duration_label, + zorder=3, + ) + + ax.set_ylabel("Duration (ms)") + ax.set_xlabel("") + ax.set_title("") + ax.xaxis.set_major_formatter(NullFormatter()) + ax.margins(x=0) + + max_duration = max(durations) + effective_cap = duration_cap + clipped_points = [] + if effective_cap is not None and effective_cap < max_duration: + ax.set_ylim(bottom=0, top=effective_cap) + clipped_points = [(timestamp, value) for timestamp, value in mem_points if value > effective_cap] + else: + upper_pad = max_duration * 1.05 if max_duration > 0 else 1 + ax.set_ylim(bottom=0, top=upper_pad) + + twin_ax = None + if tp_points: + tp_times, tp_mib = zip(*tp_points) + twin_ax = ax.twinx() + twin_ax.margins(x=0) + twin_ax.vlines( + tp_times, + [0] * len(tp_times), + tp_mib, + color="#4fbf73", + alpha=0.5, + linewidth=1, + zorder=1, + label="Template provider memory", + ) + twin_ax.set_ylabel("Memory footprint (MiB)", color="#2b8a46") + twin_ax.tick_params(axis="y", colors="#2b8a46") + twin_ax.set_ylim(bottom=0) + + if clipped_points: + clip_trans = transforms.blended_transform_factory(ax.transData, ax.transAxes) + marker_y = 1.0 + clipped_times = [timestamp for timestamp, _ in clipped_points] + clipped_values = [value for _, value in clipped_points] + clipped_time_nums = mdates.date2num(clipped_times) + ax.scatter( + clipped_time_nums, + [marker_y] * len(clipped_points), + marker="o", + s=22, + facecolors="none", + edgecolors="tab:blue", + linewidths=1, + label=f"Clipped duration (> {effective_cap:.2f} ms)", + transform=clip_trans, + clip_on=False, + zorder=4, + ) + label_min_delta = (ax.get_xlim()[1] - ax.get_xlim()[0]) * CLIPPED_LABEL_MIN_FRACTION + last_clipped_label_num: float | None = None + for ts_num, value in zip(clipped_time_nums, clipped_values): + if last_clipped_label_num is not None and ts_num - last_clipped_label_num < label_min_delta: + continue + label = f"{value:.0f} ms" + ax.annotate( + label, + xy=(ts_num, marker_y), + xycoords=clip_trans, + xytext=(0, -8), + textcoords="offset points", + ha="center", + va="top", + fontsize=8, + color="tab:blue", + rotation=270, + clip_on=False, + ) + last_clipped_label_num = ts_num + + if tip_events: + tip_color = "tab:red" + tip_times, tip_heights = zip(*tip_events) + tip_time_nums = mdates.date2num(tip_times) + trans = transforms.blended_transform_factory(ax.transData, ax.transAxes) + marker_y = -0.01 + ax.scatter( + tip_time_nums, + [marker_y] * len(tip_events), + marker="^", + s=70, + color=tip_color, + edgecolors="none", + label="Tip update", + zorder=4, + transform=trans, + clip_on=False, + ) + label_trans = transforms.blended_transform_factory(ax.transData, ax.transAxes) + x_start, x_end = ax.get_xlim() + min_delta = (x_end - x_start) * TIP_LABEL_MIN_FRACTION + last_label_num: float | None = None + for ts_num, height in zip(tip_time_nums, tip_heights): + if last_label_num is not None and ts_num - last_label_num < min_delta: + continue + label = f"{height:,}" + ax.annotate( + label, + xy=(ts_num, 0), + xycoords=label_trans, + xytext=(1, -8), + textcoords="offset points", + rotation=45, + ha="right", + va="top", + color=tip_color, + fontsize=8, + clip_on=False, + ) + last_label_num = ts_num + + handles, labels = ax.get_legend_handles_labels() + if twin_ax is not None: + twin_handles, twin_labels = twin_ax.get_legend_handles_labels() + handles += twin_handles + labels += twin_labels + try: + tip_idx = labels.index("Tip update") + tip_handle = handles.pop(tip_idx) + tip_label = labels.pop(tip_idx) + handles.append(tip_handle) + labels.append(tip_label) + except ValueError: + pass + legend = fig.legend( + handles, + labels, + loc="upper left", + bbox_to_anchor=(0.12, 0.78), + ) + legend.set_zorder(10) + frame = legend.get_frame() + frame.set_alpha(0.75) + frame.set_zorder(legend.get_zorder()) + ax.grid(True, axis="y", linestyle="--", alpha=0.3) + + if figure_pickle is not None: + figure_pickle.parent.mkdir(parents=True, exist_ok=True) + with figure_pickle.open("wb") as handle: + pickle.dump(fig, handle) + + if show_plot: + plt.show() + else: + output.parent.mkdir(parents=True, exist_ok=True) + raster_exts = {".png", ".jpg", ".jpeg", ".tif", ".tiff", ".bmp", ".gif"} + if output.suffix.lower() in raster_exts: + fig.savefig(output, bbox_inches="tight", facecolor=fig.get_facecolor(), dpi=dpi) + else: + fig.savefig(output, bbox_inches="tight", facecolor=fig.get_facecolor()) + print(f"Wrote {output}") + + plt.close(fig) + + +def main() -> None: + args = parse_args() + since_ts = parse_since_timestamp(args.since) if args.since else None + mem_points, tip_events = load_events(args.bitcoin_log, since_ts) + tp_points = load_tp_points(args.tp_log, since_ts) + plot_memory_load( + mem_points, + tip_events, + tp_points, + args.duration_cap, + args.figure_pickle, + args.dpi, + args.machine, + args.output, + args.show, + ) + + +if __name__ == "__main__": + main()