|
| 1 | +#!/usr/bin/env python3 |
| 2 | +""" |
| 3 | +tick-rate latency bench. |
| 4 | +
|
| 5 | +Measures producer→consumer end-to-end latency for pgque under different |
| 6 | +ticker_loop tick periods. |
| 7 | +
|
| 8 | +Latency definition: |
| 9 | + latency_ms = consumer_recv_ts - producer_send_ts |
| 10 | +where both timestamps are server-side `clock_timestamp()` (no clock skew). |
| 11 | +
|
| 12 | +The producer stamps `clock_timestamp()` into the event payload at INSERT |
| 13 | +time. The consumer reads the payload, computes the delta, and records it. |
| 14 | +
|
| 15 | +Two scenarios: |
| 16 | + --scenario idle : light producer, sweep tick_period_ms. |
| 17 | + --scenario held-xmin : a long-running RR transaction holds xmin while |
| 18 | + a 1000 ev/s producer runs. Demonstrates how |
| 19 | + tick/subscription metadata UPDATEs degrade |
| 20 | + latency under blocked vacuum. |
| 21 | +
|
| 22 | +Usage: |
| 23 | + python3 bench.py --dsn "host=localhost dbname=pgque_bench user=postgres" \ |
| 24 | + --scenario idle \ |
| 25 | + --periods 10000,1000,100,10,1 \ |
| 26 | + --duration-s 30 \ |
| 27 | + --rate-eps 100 |
| 28 | +
|
| 29 | + python3 bench.py --dsn "..." \ |
| 30 | + --scenario held-xmin \ |
| 31 | + --tick-period-ms 100 \ |
| 32 | + --duration-s 300 \ |
| 33 | + --rate-eps 1000 |
| 34 | +""" |
| 35 | +from __future__ import annotations |
| 36 | + |
| 37 | +import argparse |
| 38 | +import json |
| 39 | +import statistics |
| 40 | +import sys |
| 41 | +import threading |
| 42 | +import time |
| 43 | +from contextlib import closing |
| 44 | + |
| 45 | +import psycopg |
| 46 | + |
| 47 | + |
| 48 | +def percentile(xs, p): |
| 49 | + if not xs: |
| 50 | + return float("nan") |
| 51 | + xs = sorted(xs) |
| 52 | + k = int(round((p / 100.0) * (len(xs) - 1))) |
| 53 | + return xs[k] |
| 54 | + |
| 55 | + |
| 56 | +def fmt_ms(x): |
| 57 | + return "n/a" if x != x else f"{x:.2f}" # NaN check |
| 58 | + |
| 59 | + |
| 60 | +def setup(dsn, queue, consumer): |
| 61 | + with closing(psycopg.connect(dsn, autocommit=True)) as cn, cn.cursor() as cur: |
| 62 | + cur.execute("select 1 from pgque.queue where queue_name = %s", (queue,)) |
| 63 | + if not cur.fetchone(): |
| 64 | + cur.execute("select pgque.create_queue(%s)", (queue,)) |
| 65 | + # Aggressive ticking even when idle: max_lag = 0 means any tick fires. |
| 66 | + cur.execute("select pgque.set_queue_config(%s, 'ticker_max_lag', '0 seconds')", (queue,)) |
| 67 | + cur.execute("select pgque.set_queue_config(%s, 'ticker_idle_period', '0 seconds')", (queue,)) |
| 68 | + cur.execute("select pgque.set_queue_config(%s, 'ticker_max_count', '1')", (queue,)) |
| 69 | + # Subscribe (idempotent — re-subscribe after cleanup) |
| 70 | + cur.execute("select 1 from pgque.subscription s join pgque.queue q on q.queue_id=s.sub_queue " |
| 71 | + "where q.queue_name=%s and s.sub_consumer=(select co_id from pgque.consumer where co_name=%s)", (queue, consumer)) |
| 72 | + if not cur.fetchone(): |
| 73 | + cur.execute("select pgque.subscribe(%s, %s)", (queue, consumer)) |
| 74 | + |
| 75 | + |
| 76 | +def teardown(dsn, queue, consumer): |
| 77 | + with closing(psycopg.connect(dsn, autocommit=True)) as cn, cn.cursor() as cur: |
| 78 | + try: |
| 79 | + cur.execute("select pgque.unsubscribe(%s, %s)", (queue, consumer)) |
| 80 | + except Exception: |
| 81 | + pass |
| 82 | + try: |
| 83 | + cur.execute("select pgque.drop_queue(%s)", (queue,)) |
| 84 | + except Exception: |
| 85 | + pass |
| 86 | + |
| 87 | + |
| 88 | +def producer_thread(dsn, queue, rate_eps, duration_s, stop_evt, stats): |
| 89 | + """Send events at target rate. Each payload carries server-side send_ts.""" |
| 90 | + interval = 1.0 / rate_eps |
| 91 | + sent = 0 |
| 92 | + start = time.monotonic() |
| 93 | + next_send = start |
| 94 | + with closing(psycopg.connect(dsn, autocommit=True)) as cn, cn.cursor() as cur: |
| 95 | + while not stop_evt.is_set() and (time.monotonic() - start) < duration_s: |
| 96 | + now = time.monotonic() |
| 97 | + if now < next_send: |
| 98 | + time.sleep(min(next_send - now, 0.001)) |
| 99 | + continue |
| 100 | + # Server-side timestamp goes into the payload. |
| 101 | + try: |
| 102 | + cur.execute( |
| 103 | + "select pgque.send(%s, jsonb_build_object('seq', %s::int, " |
| 104 | + "'send_ts', extract(epoch from clock_timestamp())))", |
| 105 | + (queue, sent), |
| 106 | + ) |
| 107 | + sent += 1 |
| 108 | + except Exception as e: |
| 109 | + stats.setdefault("errors", []).append(f"producer: {e}") |
| 110 | + next_send += interval |
| 111 | + stats["sent"] = sent |
| 112 | + stats["duration_s"] = time.monotonic() - start |
| 113 | + |
| 114 | + |
| 115 | +def consumer_thread(dsn, queue, consumer, stop_evt, stats, drain_extra_s=2.0): |
| 116 | + """Continuously receive + ack, computing latency = recv_ts - send_ts per event.""" |
| 117 | + latencies_ms = [] |
| 118 | + received = 0 |
| 119 | + last_msg_at = time.monotonic() |
| 120 | + with closing(psycopg.connect(dsn, autocommit=True)) as cn, cn.cursor() as cur: |
| 121 | + while True: |
| 122 | + cur.execute( |
| 123 | + "select extract(epoch from clock_timestamp()), payload, batch_id " |
| 124 | + "from pgque.receive(%s, %s, 1000)", |
| 125 | + (queue, consumer), |
| 126 | + ) |
| 127 | + rows = cur.fetchall() |
| 128 | + if rows: |
| 129 | + last_msg_at = time.monotonic() |
| 130 | + bid = rows[0][2] |
| 131 | + for recv_epoch, payload, _ in rows: |
| 132 | + pl = payload if isinstance(payload, dict) else json.loads(payload) |
| 133 | + latency_ms = (float(recv_epoch) - float(pl["send_ts"])) * 1000.0 |
| 134 | + latencies_ms.append(latency_ms) |
| 135 | + received += 1 |
| 136 | + cur.execute("select pgque.ack(%s)", (bid,)) |
| 137 | + else: |
| 138 | + # No batch yet — sleep briefly to avoid busy-looping. |
| 139 | + if stop_evt.is_set() and (time.monotonic() - last_msg_at) > drain_extra_s: |
| 140 | + break |
| 141 | + time.sleep(0.001) |
| 142 | + stats["received"] = received |
| 143 | + stats["latencies_ms"] = latencies_ms |
| 144 | + |
| 145 | + |
| 146 | +def run_one(dsn, queue, consumer, tick_period_ms, rate_eps, duration_s): |
| 147 | + """Run one (tick_period_ms, rate_eps, duration_s) cell.""" |
| 148 | + # Set the rate. |
| 149 | + with closing(psycopg.connect(dsn, autocommit=True)) as cn, cn.cursor() as cur: |
| 150 | + cur.execute("select pgque.set_tick_period_ms(%s)", (tick_period_ms,)) |
| 151 | + # Wait one full pg_cron slot so the new rate kicks in. |
| 152 | + time.sleep(1.2) |
| 153 | + |
| 154 | + stop_evt = threading.Event() |
| 155 | + p_stats, c_stats = {}, {} |
| 156 | + # drain budget: at least one full tick period plus 2 s slack so slow |
| 157 | + # ticks don't truncate trailing events. |
| 158 | + drain_extra_s = max(2.0, (tick_period_ms / 1000.0) * 3.0) |
| 159 | + pt = threading.Thread(target=producer_thread, |
| 160 | + args=(dsn, queue, rate_eps, duration_s, stop_evt, p_stats), |
| 161 | + daemon=True) |
| 162 | + ct = threading.Thread(target=consumer_thread, |
| 163 | + args=(dsn, queue, consumer, stop_evt, c_stats, drain_extra_s), |
| 164 | + daemon=True) |
| 165 | + ct.start() |
| 166 | + pt.start() |
| 167 | + pt.join() |
| 168 | + stop_evt.set() |
| 169 | + ct.join(timeout=duration_s + drain_extra_s + 10) |
| 170 | + |
| 171 | + lat = c_stats.get("latencies_ms", []) |
| 172 | + return { |
| 173 | + "tick_period_ms": tick_period_ms, |
| 174 | + "rate_eps": rate_eps, |
| 175 | + "duration_s": p_stats.get("duration_s", duration_s), |
| 176 | + "sent": p_stats.get("sent", 0), |
| 177 | + "received": c_stats.get("received", 0), |
| 178 | + "p50_ms": percentile(lat, 50), |
| 179 | + "p95_ms": percentile(lat, 95), |
| 180 | + "p99_ms": percentile(lat, 99), |
| 181 | + "max_ms": max(lat) if lat else float("nan"), |
| 182 | + "mean_ms": statistics.fmean(lat) if lat else float("nan"), |
| 183 | + } |
| 184 | + |
| 185 | + |
| 186 | +def print_table(rows, scenario): |
| 187 | + header = ( |
| 188 | + f"\n=== Scenario: {scenario} ===\n" |
| 189 | + "| tick_period_ms | rate_eps | sent | recvd | p50 | p95 | p99 | max | mean |\n" |
| 190 | + "|---:|---:|---:|---:|---:|---:|---:|---:|---:|" |
| 191 | + ) |
| 192 | + print(header) |
| 193 | + for r in rows: |
| 194 | + print( |
| 195 | + f"| {r['tick_period_ms']:>5} | {r['rate_eps']:>5} | " |
| 196 | + f"{r['sent']:>5} | {r['received']:>5} | " |
| 197 | + f"{fmt_ms(r['p50_ms']):>5} | {fmt_ms(r['p95_ms']):>5} | " |
| 198 | + f"{fmt_ms(r['p99_ms']):>5} | {fmt_ms(r['max_ms']):>5} | " |
| 199 | + f"{fmt_ms(r['mean_ms']):>5} |" |
| 200 | + ) |
| 201 | + |
| 202 | + |
| 203 | +def main(): |
| 204 | + p = argparse.ArgumentParser() |
| 205 | + p.add_argument("--dsn", required=True) |
| 206 | + p.add_argument("--scenario", choices=("idle", "held-xmin"), default="idle") |
| 207 | + p.add_argument("--periods", default="10000,1000,100,10,1", |
| 208 | + help="comma-separated tick_period_ms values (idle scenario only)") |
| 209 | + p.add_argument("--tick-period-ms", type=int, default=100, |
| 210 | + help="single tick_period_ms (held-xmin scenario)") |
| 211 | + p.add_argument("--duration-s", type=float, default=30.0) |
| 212 | + p.add_argument("--rate-eps", type=int, default=100) |
| 213 | + p.add_argument("--queue", default="bench_tick") |
| 214 | + p.add_argument("--consumer", default="bench_consumer") |
| 215 | + p.add_argument("--out-json", default=None) |
| 216 | + args = p.parse_args() |
| 217 | + |
| 218 | + setup(args.dsn, args.queue, args.consumer) |
| 219 | + |
| 220 | + rows = [] |
| 221 | + try: |
| 222 | + if args.scenario == "idle": |
| 223 | + for tp in [int(x) for x in args.periods.split(",")]: |
| 224 | + print(f"running tick_period_ms={tp}, rate={args.rate_eps} ev/s, " |
| 225 | + f"duration={args.duration_s}s ...", flush=True) |
| 226 | + rows.append(run_one(args.dsn, args.queue, args.consumer, |
| 227 | + tp, args.rate_eps, args.duration_s)) |
| 228 | + else: |
| 229 | + print(f"running held-xmin scenario, tick_period_ms={args.tick_period_ms}, " |
| 230 | + f"rate={args.rate_eps} ev/s, duration={args.duration_s}s ...", |
| 231 | + flush=True) |
| 232 | + rows.append(run_one(args.dsn, args.queue, args.consumer, |
| 233 | + args.tick_period_ms, args.rate_eps, |
| 234 | + args.duration_s)) |
| 235 | + finally: |
| 236 | + teardown(args.dsn, args.queue, args.consumer) |
| 237 | + |
| 238 | + print_table(rows, args.scenario) |
| 239 | + if args.out_json: |
| 240 | + with open(args.out_json, "w") as f: |
| 241 | + json.dump({"scenario": args.scenario, "rows": rows}, f, indent=2, |
| 242 | + default=lambda o: None if o != o else o) |
| 243 | + print(f"\nwrote {args.out_json}") |
| 244 | + |
| 245 | + |
| 246 | +if __name__ == "__main__": |
| 247 | + sys.exit(main()) |
0 commit comments