Cooldown testing for bitcoin/bitcoin#34184

run_mainnet_pool_loop.zsh

#!/usr/bin/env zsh
# Experiment: repeatedly start/stop the SV2 pool against a syncing mainnet node
# and log template-related events as the node catches up to tip.
#
# Requirement: the node should be at least 24 hours behind the network tip
# before running this script to make the experiment meaningful.
#
# WARNING: the node is intentionally SIGKILL'ed at the end so progress is not
# flushed to disk, allowing the experiment to be repeated from the same point.
#
# Run the node as:
#   build/bin/bitcoin-node -ipcbind=unix -debug=ipc -logtimemicros=1

ROOT_DIR=$(cd "$(dirname "$0")/.." && pwd)
SV2_APPS_DIR="$ROOT_DIR/../sv2-apps"

cd "$SV2_APPS_DIR/pool-apps/pool" || exit 1

CLI=("$ROOT_DIR/build/bin/bitcoin-cli" -rpcwait -rpcclienttimeout=30)
POOL_CONFIG="$SV2_APPS_DIR/pool-apps/pool/config-examples/mainnet/pool-config-bitcoin-core-ipc-example.toml"
POOL_BIN="$SV2_APPS_DIR/pool-apps/target/release/pool_sv2"
LOG="$ROOT_DIR/tmp/mainnet-pool-loop.log"
i=1

log() {
  echo "$@" | tee -a "$LOG"
}

TIP_URL="https://mempool.space/api/blocks/tip/height"

get_tip_height() {
  local tip
  tip=$(curl -fsSL "$TIP_URL" 2>/dev/null | tr -d '[:space:]' || true)
  [[ $tip =~ ^[0-9]+$ ]] || return 1
  echo "$tip"
}

if [[ -z "${TARGET:-}" ]]; then
  TARGET=$(get_tip_height) || {
    log "Failed to fetch expected tip height from public APIs. Set TARGET manually to continue."
    exit 1
  }
fi
log "Target tip height: $TARGET"

log "Enabling network activity"
${CLI[@]} setnetworkactive true >/dev/null

cleanup_pool() {
  local cfg="$1"
  local pids
  pids=$(pgrep -f "pool_sv2 .* -c ${cfg}" || true)
  if [[ -n "$pids" ]]; then
    log "Cleaning up lingering pool_sv2 pids: $pids"
    pkill -TERM -f "pool_sv2 .* -c ${cfg}" 2>/dev/null || true
    sleep 0.2
    pkill -KILL -f "pool_sv2 .* -c ${cfg}" 2>/dev/null || true
  fi
}

cleanup_pool "$POOL_CONFIG"

if [[ ! -x "$POOL_BIN" ]]; then
  log "pool_sv2 binary not found; building release binary"
  (cd "$SV2_APPS_DIR/pool-apps" && cargo build --release --bin pool_sv2) || exit 1
fi

while true; do
  info=$(${CLI[@]} getblockchaininfo)
  blocks=$(echo "$info" | jq -r '.blocks')
  headers=$(echo "$info" | jq -r '.headers')
  ibd=$(echo "$info" | jq -r '.initialblockdownload')
  progress=$(echo "$info" | jq -r '.verificationprogress')
  log "status before run $i: blocks=$blocks headers=$headers ibd=$ibd progress=$progress"
  if [[ "$ibd" == "false" && $blocks -ge $headers && $blocks -ge $TARGET ]]; then
    log "Reached tip."
    break
  fi

  run_log="$ROOT_DIR/tmp/mainnet-pool-run-$i.log"
  "$POOL_BIN" -c "$POOL_CONFIG" > "$run_log" 2>&1 &
  pool_pid=$!
  for _ in {1..300}; do
    if ! kill -0 "$pool_pid" 2>/dev/null; then
      break
    fi
    sleep 0.1
  done
  pgid=""
  self_pgid=""
  if kill -0 "$pool_pid" 2>/dev/null; then
    pgid=$(ps -o pgid= "$pool_pid" | tr -d ' ')
    self_pgid=$(ps -o pgid= $$ | tr -d ' ')
  fi
  if kill -0 "$pool_pid" 2>/dev/null; then
    log "sending SIGINT to pool pid $pool_pid${pgid:+ (pgid $pgid)}"
    if [[ -n "$pgid" && -n "$self_pgid" && "$pgid" != "$self_pgid" ]]; then
      kill -INT -- -"$pgid" 2>/dev/null || true
    else
      kill -INT "$pool_pid" 2>/dev/null || true
    fi
    for _ in {1..50}; do
      if ! kill -0 "$pool_pid" 2>/dev/null; then
        break
      fi
      sleep 0.1
    done
  fi
  if kill -0 "$pool_pid" 2>/dev/null; then
    log "pool still running; sending SIGTERM"
    if [[ -n "$pgid" && -n "$self_pgid" && "$pgid" != "$self_pgid" ]]; then
      kill -TERM -- -"$pgid" 2>/dev/null || true
    else
      kill -TERM "$pool_pid" 2>/dev/null || true
    fi
  fi
  if kill -0 "$pool_pid" 2>/dev/null; then
    log "pool still running; sending SIGKILL"
    if [[ -n "$pgid" && -n "$self_pgid" && "$pgid" != "$self_pgid" ]]; then
      kill -KILL -- -"$pgid" 2>/dev/null || true
    else
      kill -KILL "$pool_pid" 2>/dev/null || true
    fi
  fi
  wait "$pool_pid" 2>/dev/null || true
  cleanup_pool "$POOL_CONFIG"
  newtmpl=$(rg -c 'NewTemplate' "$run_log" || echo 0)
  prevhash=$(rg -c 'SetNewPrevHash' "$run_log" || echo 0)
  waiting=$(rg -c 'Waiting for initial template' "$run_log" || echo 0)
  log "run $i counts: NewTemplate=$newtmpl SetNewPrevHash=$prevhash Waiting=$waiting"

  info=$(${CLI[@]} getblockchaininfo)
  blocks=$(echo "$info" | jq -r '.blocks')
  headers=$(echo "$info" | jq -r '.headers')
  ibd=$(echo "$info" | jq -r '.initialblockdownload')
  progress=$(echo "$info" | jq -r '.verificationprogress')
  log "status after run $i: blocks=$blocks headers=$headers ibd=$ibd progress=$progress"
  if [[ "$ibd" == "false" && $blocks -ge $headers && $blocks -ge $TARGET ]]; then
    log "Reached tip."
    break
  fi

  i=$((i+1))
done

log "Experiment complete; killing bitcoin-node (unclean) to reset progress"
killall -9 bitcoin-node 2>/dev/null || true

tip_interval_charts.py

#!/usr/bin/env python3
"""
Generate HTML page with vertical bar charts of tip update intervals.
Splits the most recent experiment into IBD and post-IBD phases.

Usage:
  tip_interval_charts.py /path/to/debug.log
"""

import argparse
import os
import re
from datetime import datetime

# Define bins (in seconds) - 1s wide for first 5, then 5-10s and >10s
BINS = [
    (0, 1, "0-1s"),
    (1, 2, "1-2s"),
    (2, 3, "2-3s"),
    (3, 4, "3-4s"),
    (4, 5, "4-5s"),
    (5, 10, "5-10s"),
    (10, float("inf"), ">10s"),
]

# Visual cap for bar heights (axis break threshold)
BAR_CAP = 200

# Blocks with timestamp within this many seconds of wall clock are "freshly mined"
# and should be excluded from sync timing analysis
FRESH_BLOCK_THRESHOLD = 600  # 10 minutes

IBD_END_PATTERN = "Leaving InitialBlockDownload"

def parse_log_timestamp(line):
    try:
        ts_part = line.split()[0]
        ts_part = ts_part.rstrip('Z').replace('T', ' ')
        try:
            return datetime.strptime(ts_part, "%Y-%m-%d %H:%M:%S.%f")
        except ValueError:
            return datetime.strptime(ts_part, "%Y-%m-%d %H:%M:%S")
    except (ValueError, IndexError):
        return None

def load_log_events(log_path):
    """Load UpdateTip timestamps with block timestamps and progress, plus key lifecycle events."""
    timestamps = []  # List of (wall_time, block_time, progress) tuples
    network_on_events = []
    node_starts = []
    ibd_end_events = []
    last_log_time = None

    with open(log_path, "r") as f:
        lines = f.readlines()

    i = 0
    while i < len(lines):
        line = lines[i]
        try:
            t = parse_log_timestamp(line)
            if t:
                last_log_time = t

            if "UpdateTip: new best=" in line:
                # Extract block timestamp from date='YYYY-MM-DDTHH:MM:SSZ'
                # Note: date= field may be on the NEXT line (continuation line)
                block_time = None
                progress = None
                combined = line
                if i + 1 < len(lines) and lines[i + 1].startswith(' '):
                    combined += lines[i + 1]
                if "date='" in combined:
                    try:
                        date_start = combined.index("date='") + 6
                        date_end = combined.index("'", date_start)
                        date_str = combined[date_start:date_end].rstrip('Z').replace('T', ' ')
                        block_time = datetime.strptime(date_str, "%Y-%m-%d %H:%M:%S")
                    except:
                        pass
                progress_match = re.search(r"progress=([0-9.]+)", combined)
                if progress_match:
                    try:
                        progress = float(progress_match.group(1))
                    except ValueError:
                        progress = None
                if t:
                    timestamps.append((t, block_time, progress))
            elif "SetNetworkActive: true" in line:
                if t:
                    network_on_events.append(t)
            elif "Bitcoin Core version" in line:
                if t:
                    node_starts.append(t)
            elif IBD_END_PATTERN in line:
                if t:
                    ibd_end_events.append(t)
        except:
            pass
        i += 1

    return timestamps, network_on_events, node_starts, ibd_end_events, last_log_time

def detect_latest_experiment(timestamps, node_starts, ibd_end_events, last_log_time):
    """Detect the most recent experiment from node startup to end-of-log."""
    if not node_starts:
        return None

    start = max(node_starts)
    end = last_log_time or start

    ibd_end = None
    for t in sorted(ibd_end_events):
        if t >= start:
            ibd_end = t
            break

    if ibd_end is None:
        for t, _, progress in sorted(timestamps, key=lambda x: x[0]):
            if t < start:
                continue
            if progress is not None and progress >= 0.999999:
                ibd_end = t
                break

    if ibd_end is None or ibd_end > end:
        ibd_end = end

    name = f"Most recent experiment ({start.strftime('%Y-%m-%d %H:%M')})"
    return {
        "name": name,
        "start": start,
        "end": end,
        "ibd_end": ibd_end,
    }

def get_intervals(timestamps, network_on_events, node_starts, start, end):
    """Get intervals between timestamps in range, stopping at node restart, skipping first after start and network-on.

    Also filters out intervals where the block was freshly mined (block timestamp close to wall clock).
    """
    # Truncate end at first node restart after start
    effective_end = end
    for restart in node_starts:
        if start < restart < end:
            effective_end = restart
            break

    filtered = [(t, bt) for t, bt, _ in timestamps if start <= t <= effective_end]
    if len(filtered) < 2:
        return []

    # Find network-on events in this range
    net_events_in_range = [t for t in network_on_events if start <= t <= effective_end]

    intervals = []
    for i in range(1, len(filtered)):
        prev_ts, prev_bt = filtered[i-1]
        curr_ts, curr_bt = filtered[i]
        delta = (curr_ts - prev_ts).total_seconds()

        # Skip first interval (after start)
        if i == 1:
            continue

        # Skip interval if there was a network-on event between prev and curr
        skip = False
        for net_on in net_events_in_range:
            if prev_ts < net_on <= curr_ts:
                skip = True
                break

        # Skip if block is freshly mined (block timestamp close to wall clock)
        if curr_bt is not None:
            block_age = (curr_ts - curr_bt).total_seconds()
            if block_age < FRESH_BLOCK_THRESHOLD:
                skip = True

        if not skip:
            intervals.append(delta)

    return intervals

def bin_intervals(intervals):
    """Bin intervals into histogram."""
    counts = {label: 0 for _, _, label in BINS}
    for interval in intervals:
        for lo, hi, label in BINS:
            if lo <= interval < hi:
                counts[label] += 1
                break
    return counts

def generate_chart_svg(counts, title, global_max):
    """Generate SVG vertical bar chart with axis break for values > BAR_CAP."""
    labels = [label for _, _, label in BINS]
    values = [counts.get(label, 0) for label in labels]

    bar_width = 40
    gap = 10
    chart_width = len(labels) * (bar_width + gap) + 60
    chart_height = 200
    bar_area_height = 150

    svg = f'''<svg width="{chart_width}" height="{chart_height}" xmlns="http://www.w3.org/2000/svg">
  <style>
    .bar {{ fill: #4a90d9; }}
    .bar:hover {{ fill: #2d6cb5; }}
    .bar-break {{ fill: #4a90d9; }}
    .label {{ font-size: 10px; text-anchor: middle; font-family: monospace; }}
    .value {{ font-size: 9px; text-anchor: middle; font-family: monospace; fill: #666; }}
    .title {{ font-size: 12px; text-anchor: middle; font-family: sans-serif; font-weight: bold; }}
    .break-line {{ stroke: #fff; stroke-width: 3; }}
    .break-bg {{ fill: #fff; }}
  </style>
  <text x="{chart_width/2}" y="15" class="title">{title}</text>
'''

    total = sum(values)

    for i, (label, val) in enumerate(zip(labels, values)):
        x = 30 + i * (bar_width + gap)

        # Cap visual height at BAR_CAP but show actual value
        display_val = min(val, global_max)
        bar_height = (display_val / global_max) * bar_area_height if global_max > 0 else 0
        y = 25 + bar_area_height - bar_height

        if val > BAR_CAP:
            # Draw bar with break indicator (capped at BAR_CAP visual height)
            capped_height = bar_area_height  # Full height since global_max = BAR_CAP
            y_capped = 25

            # Main bar (full height)
            svg += f'  <rect x="{x}" y="{y_capped}" width="{bar_width}" height="{capped_height}" class="bar"/>\n'

            # Break indicator (zigzag/wave pattern near top) with white background
            break_y = y_capped + 12
            wave_h = 6
            # Draw white background rectangle for break area
            svg += f'  <rect x="{x}" y="{break_y - 2}" width="{bar_width}" height="{wave_h + 4}" class="break-bg"/>\n'
            # Draw zigzag lines
            mid = x + bar_width / 2
            svg += f'  <polyline points="{x},{break_y} {mid},{break_y + wave_h} {x + bar_width},{break_y}" fill="none" stroke="#4a90d9" stroke-width="2"/>\n'
            svg += f'  <polyline points="{x},{break_y + wave_h} {mid},{break_y} {x + bar_width},{break_y + wave_h}" fill="none" stroke="#4a90d9" stroke-width="2"/>\n'
        else:
            svg += f'  <rect x="{x}" y="{y}" width="{bar_width}" height="{bar_height}" class="bar"/>\n'

        svg += f'  <text x="{x + bar_width/2}" y="{25 + bar_area_height + 12}" class="label">{label}</text>\n'
        if val > 0:
            if val > BAR_CAP:
                y_text = 22  # Above the full-height bar with break
            else:
                y_text = (25 + bar_area_height - (val / global_max) * bar_area_height) - 3 if global_max > 0 else 25
            svg += f'  <text x="{x + bar_width/2}" y="{y_text}" class="value">{val}</text>\n'

    svg += f'  <text x="{chart_width/2}" y="{chart_height - 5}" class="label">n={total}</text>\n'
    svg += '</svg>'
    return svg

def main():
    parser = argparse.ArgumentParser(
        description="Generate tip interval charts from a Bitcoin Core debug.log",
    )
    parser.add_argument("debug_log", help="Path to debug.log")
    args = parser.parse_args()

    debug_log = args.debug_log
    if not os.path.exists(debug_log):
        print(f"Debug log not found: {debug_log}")
        raise SystemExit(1)

    print(f"Loading events from debug log: {debug_log}")
    all_timestamps, network_on_events, node_starts, ibd_end_events, last_log_time = load_log_events(debug_log)
    print(
        f"Loaded {len(all_timestamps)} UpdateTip entries, {len(network_on_events)} network-on events, "
        f"{len(node_starts)} node starts"
    )

    experiment = detect_latest_experiment(all_timestamps, node_starts, ibd_end_events, last_log_time)
    if not experiment:
        print("No node startup entries found (Bitcoin Core version). Cannot detect experiment window.")
        raise SystemExit(1)

    experiments = [experiment]
    exp_start = experiment["start"]
    exp_end = experiment["end"]
    exp_ibd_end = experiment["ibd_end"]
    if exp_ibd_end >= exp_end:
        print("Warning: IBD end not found; post-IBD chart may be empty.")

    exp_info_html = f'''  <h2>Experiment</h2>
  <p><strong>{experiment["name"]}</strong><br>
     Start: {exp_start.strftime("%Y-%m-%d %H:%M:%S")}<br>
     IBD end: {exp_ibd_end.strftime("%Y-%m-%d %H:%M:%S")}<br>
     End: {exp_end.strftime("%Y-%m-%d %H:%M:%S")}
  </p>
'''

    # First pass: collect all counts to find global max
    all_counts = []
    for exp in experiments:
        start = exp["start"]
        end = exp["end"]
        ibd_end = exp["ibd_end"]

        ibd_intervals = get_intervals(all_timestamps, network_on_events, node_starts, start, ibd_end)
        post_intervals = get_intervals(all_timestamps, network_on_events, node_starts, ibd_end, end)

        all_counts.append(bin_intervals(ibd_intervals))
        all_counts.append(bin_intervals(post_intervals))

    if not all_counts:
        print("No intervals found in the detected experiment window.")
        raise SystemExit(1)

    global_max = max(max(c.values()) for c in all_counts if c.values())
    global_max = min(global_max, BAR_CAP)
    print(f"Using global max scale: {global_max}")

    html = '''<!DOCTYPE html>
<html>
<head>
  <title>Tip Update Interval Analysis - IBD vs Post-IBD</title>
  <style>
    body { font-family: -apple-system, BlinkMacSystemFont, sans-serif; margin: 20px; }
    h1 { color: #333; }
    table { border-collapse: collapse; margin: 20px 0; }
    th, td { border: 1px solid #ddd; padding: 10px; vertical-align: top; }
    th { background: #f5f5f5; }
    .stats { font-size: 11px; color: #666; margin-top: 5px; }
  </style>
</head>
<body>
  <h1>Tip Update Interval Analysis</h1>
  <p>Comparing interval distributions during Initial Block Download (IBD) vs after IBD completion.</p>
  <p><em>Note: Excluded from analysis: (1) First interval after node start and after network re-enable,
  (2) intervals after node restart, (3) freshly mined blocks (block timestamp within 10 min of wall clock).</em></p>
  <table>
    <tr>
      <th>During IBD</th>
      <th>After IBD</th>
    </tr>
'''

    for exp in experiments:
        start = exp["start"]
        end = exp["end"]
        ibd_end = exp["ibd_end"]

        ibd_intervals = get_intervals(all_timestamps, network_on_events, node_starts, start, ibd_end)
        post_intervals = get_intervals(all_timestamps, network_on_events, node_starts, ibd_end, end)

        ibd_counts = bin_intervals(ibd_intervals)
        post_counts = bin_intervals(post_intervals)

        ibd_svg = generate_chart_svg(ibd_counts, "IBD", global_max)
        post_svg = generate_chart_svg(post_counts, "Post-IBD", global_max)

        ibd_avg = sum(ibd_intervals) / len(ibd_intervals) if ibd_intervals else 0
        post_avg = sum(post_intervals) / len(post_intervals) if post_intervals else 0
        ibd_max = max(ibd_intervals) if ibd_intervals else 0
        post_max = max(post_intervals) if post_intervals else 0

        html += f'''    <tr>
      <td>
        {ibd_svg}
        <div class="stats">Avg: {ibd_avg:.2f}s, Max: {ibd_max:.1f}s</div>
      </td>
      <td>
        {post_svg}
        <div class="stats">Avg: {post_avg:.2f}s, Max: {post_max:.1f}s</div>
      </td>
    </tr>
'''

    html += '''  </table>
'''
    html += exp_info_html
    html += '''
  <h2>Legend</h2>
  <ul>
    <li><strong>IBD (Initial Block Download)</strong>: Node is catching up with the blockchain, processing historical blocks rapidly</li>
    <li><strong>Post-IBD</strong>: Node has caught up, processing recent blocks at normal network pace</li>
    <li><strong>Intervals</strong>: Time between consecutive tip updates (first after start/network-enable excluded)</li>
    <li><strong>Bars with zigzag</strong>: Value exceeds scale cap, shown with axis break</li>
    <li><strong>Note</strong>: Data is truncated at node restarts within experiment windows</li>
  </ul>
</body>
</html>'''

    output_path = os.path.join(os.path.dirname(__file__), "tip_interval_charts.html")
    with open(output_path, "w") as f:
        f.write(html)
    print(f"Generated: {output_path}")

if __name__ == "__main__":
    main()