diff --git a/README.md b/README.md index 83eea35..eb30ec0 100644 --- a/README.md +++ b/README.md @@ -35,18 +35,30 @@ The numbers are only worth something if the method is. This is what the tool doe | | Why | |---|---| +| **Two timings per data point** | **total** is the wall clock an application feels — planning, execution, transfer and the driver building Python objects. **server** is PostgreSQL's own `Execution Time` from `EXPLAIN (ANALYZE, TIMING OFF)`. The gap between them is the client. | | **One discarded warm-up run** | Without it, whichever query runs first pays for the cold cache. That alone was enough to make the "slow" query look slow. | | **Median of 5 timed runs** | A single sample is dominated by scheduler noise. The median ignores the outlier that a mean would carry. | | **Data points derived from the real row count** | A `LIMIT` above the table size returns the whole table every time, which flattens the curve into a straight line of noise. | -| **`rows_fetched` shown in every table** | So you can see the query actually returned something. A benchmark over an empty result set measures nothing. | -| **Timing includes `fetchall()`** | The cost of `SELECT *` is largely transferring and materialising the columns, so the client-side fetch is part of what is being measured. | +| **Row counts shown in every table** | So you can see the query actually returned something. A benchmark over an empty result set measures nothing. | + +### Why both timings matter + +Reporting only the wall clock is how a client-side cost gets presented as a database result. On this +dataset, `SELECT * LIMIT 10000` takes **17.22 ms total but 0.31 ms inside PostgreSQL** — 98% of what +you would be "measuring" is psycopg2 turning bytes into tuples. + +It cuts the other way too. Adding a B-tree index to `WHERE age = 35` improves the wall clock by only +**2.1x**, because fetching and shipping the matching rows swamps the lookup. PostgreSQL's own time +improves by **7.7x**. Judge the index on the second number; budget your endpoint with the first. + +In the charts, **solid lines are the total and dashed lines are PostgreSQL alone**. ### What this is not -These are **wall-clock timings on a synthetic dataset in a container**, not a claim about your -production database. Row counts, hardware, PostgreSQL version, `work_mem`, concurrency and data -distribution all move these numbers. Use the tool to see *why* a plan changes — read the -`EXPLAIN ANALYZE` output, not just the chart. +These are **timings on a synthetic dataset in a container**, not a claim about your production +database. Row counts, hardware, PostgreSQL version, `work_mem`, concurrency and data distribution all +move these numbers. Use the tool to see *why* a plan changes — read the `EXPLAIN ANALYZE` output, not +just the chart. --- @@ -59,10 +71,18 @@ SELECT * FROM users LIMIT %s; SELECT id, name, email FROM users LIMIT %s; ``` -The `users` table has 16 columns, one of them a `TEXT` bio that dominates the row width. Selecting 3 -narrow columns instead of all 16 cuts the bytes PostgreSQL has to read, materialise and ship to the -client. The LIMITs sweep from 10% to 100% of the table, so the curve reflects a growing result set -rather than the same query run ten times. +The `users` table has 16 columns. `EXPLAIN` puts the full row at **143 bytes** against **30 bytes** +for the three-column projection — a 4.8x difference in what has to be shipped, and the measured +total-time gap lands at ~5x, right where the widths predict. + +The interesting part is where that time goes. **PostgreSQL is marginally *faster* for `SELECT *`** +(0.31 ms vs 0.46 ms at 10k rows): returning the stored tuple needs no projection work, while picking +three columns means building a new one. The entire penalty is on the client — 98% of the wall clock +is psycopg2 decoding 16 columns instead of 3. + +So `SELECT *` is worth avoiding, but not for the reason it is usually given. It is not straining the +planner; it is straining your application and your network. The LIMITs sweep from 10% to 100% of the +table, so the curve reflects a growing result set rather than the same query run ten times.

SELECT * vs columns benchmark @@ -79,9 +99,14 @@ Same query, twice: once with no index on `age`, then again after `CREATE INDEX`. plan is captured before the index exists** — otherwise both `EXPLAIN` runs report the same indexed plan and the label lies about what you are looking at. -Note that on a small dataset PostgreSQL may legitimately still choose a sequential scan: reading -10,000 rows is cheaper than an index lookup plus heap fetches. That is the planner being right, not -the benchmark being broken — pick a larger dataset size to see the crossover. +This is the clearest case for reading both lines. At 100k rows the index is worth **7.7x** to +PostgreSQL (5.25 ms → 0.68 ms) but only **2.1x** on the wall clock (8.16 ms → 3.83 ms), because +`SELECT *` ships ~1,600 wide rows either way and that transfer cost is indifferent to how they were +found. An index speeds up *finding* rows, not *sending* them. + +On a small dataset PostgreSQL may legitimately still choose a sequential scan: reading 10,000 rows is +cheaper than an index lookup plus heap fetches. That is the planner being right, not the benchmark +being broken — pick a larger dataset size to see the crossover.

Index usage benchmark @@ -101,9 +126,19 @@ SELECT id, name, email FROM users u WHERE EXISTS (SELECT 1 FROM sqlperf_orders o WHERE o.user_id = u.id AND o.amount > %s); ``` -Each pattern has different characteristics depending on data distribution, indexes and result set -size. There is no universal "fastest" — often the planner rewrites `IN` and `EXISTS` into the same -plan, which the `EXPLAIN` output will show you directly. +**These three do not return the same thing.** Each user has up to 5 orders, so `JOIN` emits one row +per matching *order* while `IN` and `EXISTS` emit one row per matching *user*: at `amount > 50` that +is **225,245 rows against 95,077**. Comparing their times without noticing that is comparing two +different questions. + +Which is exactly what makes it interesting. `JOIN` is the fastest of the three inside PostgreSQL +(40.8 ms vs 47.1 and 55.8) and the slowest overall (160.6 ms vs 83.4 and 78.3), because it ships 2.4x +more rows. `IN` and `EXISTS` usually collapse to the same `Hash Semi Join` — the `EXPLAIN` output +shows it directly. + +> An earlier version of this benchmark gave every user at most one order. With 1:1 data there is no +> fan-out, all three return identical row sets, and the planner produces byte-identical plans — it +> compared three spellings of the same query.

JOIN vs subquery benchmark @@ -120,6 +155,10 @@ The page size is held at 100 and **the offset is what varies**, from the first p one the dataset allows. That is the whole point: `OFFSET` has to walk and throw away every skipped row, so its cost grows with page *depth*, while keyset pagination stays flat. +This is the one benchmark where the server number is the dramatic one, because both queries return +the same 100 rows and the transfer cost cancels out. At page 400, PostgreSQL spends 1.80 ms on +`OFFSET` and 0.01 ms on keyset — **150x** — while the wall clock only shows 4x. +

Pagination benchmark

@@ -210,7 +249,7 @@ from matplotlib.backends.backend_agg import FigureCanvasAgg from matplotlib.figure import Figure from benchmarks.base import ( - BenchmarkBase, BenchmarkResult, QueryResult, measure, table_row_count, + BenchmarkBase, BenchmarkResult, QueryResult, format_ms, measure, table_row_count, ) from benchmarks.registry import register @@ -230,26 +269,25 @@ class CityFilterBenchmark(BenchmarkBase): def run(self, conn) -> BenchmarkResult: # Cities that actually exist in the seed data. cities = ["New York", "Los Angeles", "Chicago", "Houston", "Phoenix"] - times, rows_fetched = [], [] with conn.cursor() as cur: - for city in cities: - rows, elapsed = measure(cur, QUERY, (city,)) # warm-up + median - times.append(elapsed) - rows_fetched.append(rows) + # measure() does the warm-up, the median and the server timing. + results = [measure(cur, QUERY, (city,)) for city in cities] query = QueryResult( name="Filter by city", query=QUERY, - times=times, limits=cities, # x-axis values - rows_fetched=rows_fetched, + times=[m.wall_ms for m in results], + rows_fetched=[m.rows_fetched for m in results], + server_times=[m.server_ms for m in results], ) comparison = pd.DataFrame({ "city": cities, - "rows_matched": rows_fetched, - "time_ms": [round(t, 2) for t in times], + "rows": query.rows_fetched, + "total": [format_ms(m.wall_ms) for m in results], + "server": [format_ms(m.server_ms) for m in results], }) fig = Figure(figsize=(8, 5)) @@ -294,9 +332,15 @@ class CityFilterBenchmark(BenchmarkBase): them automatically — supply them yourself when the plan must be captured at a specific moment, as `index_usage` does. -**Helpers worth using:** `measure(cursor, query, params)` gives you the warm-up plus median for free, -and `table_row_count(conn)` lets you size your data points to the dataset instead of hardcoding them. -Raise `BenchmarkNotApplicable` when the dataset is too small for your benchmark to mean anything. +**Helpers worth using:** `measure(cursor, query, params)` returns a `Measurement` with +`rows_fetched`, `wall_ms`, `server_ms` and a `client_share` property, doing the warm-up, the median +and the `EXPLAIN` for you. `table_row_count(conn)` lets you size your data points to the dataset +instead of hardcoding them, `format_ms` and `speedup` keep table columns consistent, and +`plot_server_series(ax, query, color)` adds the dashed server line to a chart. Raise +`BenchmarkNotApplicable` when the dataset is too small for your benchmark to mean anything. + +**Report both timings.** A table with only wall-clock numbers cannot distinguish a query PostgreSQL +struggles with from one that merely returns a lot of data. --- diff --git a/app/img/screenshot_index_usage.png b/app/img/screenshot_index_usage.png index fed6c42..af1aaee 100644 Binary files a/app/img/screenshot_index_usage.png and b/app/img/screenshot_index_usage.png differ diff --git a/app/img/screenshot_join.png b/app/img/screenshot_join.png index 9e84c36..18a82ba 100644 Binary files a/app/img/screenshot_join.png and b/app/img/screenshot_join.png differ diff --git a/app/img/screenshot_pagination.png b/app/img/screenshot_pagination.png index daad71c..63ca7a8 100644 Binary files a/app/img/screenshot_pagination.png and b/app/img/screenshot_pagination.png differ diff --git a/app/img/screenshot_select_star.png b/app/img/screenshot_select_star.png index 03089e8..6b920fe 100644 Binary files a/app/img/screenshot_select_star.png and b/app/img/screenshot_select_star.png differ diff --git a/benchmarks/base.py b/benchmarks/base.py index 1217a72..507b136 100644 --- a/benchmarks/base.py +++ b/benchmarks/base.py @@ -1,3 +1,4 @@ +import re import statistics import time from abc import ABC, abstractmethod @@ -8,6 +9,37 @@ REPETITIONS = 5 +_EXECUTION_TIME = re.compile(r"Execution Time:\s*([\d.]+)\s*ms") + + +@dataclass +class Measurement: + """One data point, split into where the time actually goes. + + `wall_ms` is what an application feels: planning, execution, transfer and + the driver turning bytes into Python objects. `server_ms` is what + PostgreSQL reports for itself. The gap between them is usually most of the + total, and pretending otherwise is how a client-side cost gets presented + as a database result. + """ + + rows_fetched: int + wall_ms: float + server_ms: float | None + + @property + def client_ms(self) -> float | None: + if self.server_ms is None: + return None + return max(0.0, self.wall_ms - self.server_ms) + + @property + def client_share(self) -> float | None: + """Fraction of wall time spent outside PostgreSQL.""" + if self.server_ms is None or self.wall_ms <= 0: + return None + return max(0.0, (self.wall_ms - self.server_ms) / self.wall_ms) + @dataclass class QueryResult: @@ -18,6 +50,8 @@ class QueryResult: #: depending on what the benchmark varies. Same length as `times`. limits: list rows_fetched: list[int] + #: PostgreSQL's own Execution Time per data point, None where unavailable. + server_times: list[float | None] = field(default_factory=list) @dataclass @@ -31,14 +65,27 @@ class BenchmarkResult: explain_plans: dict[str, str] = field(default_factory=dict) -def measure(cursor, query, params=None, repetitions=REPETITIONS, clock=time.perf_counter): +def server_execution_ms(cursor, query, params=None) -> float | None: + """PostgreSQL's own Execution Time, excluding transfer to the client. + + TIMING OFF keeps the per-node instrumentation overhead out of the total. + """ + cursor.execute("EXPLAIN (ANALYZE, TIMING OFF) " + query, params) + for row in cursor.fetchall(): + match = _EXECUTION_TIME.search(row[0]) + if match: + return float(match.group(1)) + return None + + +def measure( + cursor, query, params=None, repetitions=REPETITIONS, clock=time.perf_counter +) -> Measurement: """Time a query as the median of `repetitions` runs after one warm-up. The warm-up matters more than the repetitions: without it whichever query runs first pays for the cold cache, which systematically favours whatever the benchmark runs second. - - Returns (rows_fetched, median_milliseconds). """ cursor.execute(query, params) rows = cursor.fetchall() @@ -50,7 +97,11 @@ def measure(cursor, query, params=None, repetitions=REPETITIONS, clock=time.perf rows = cursor.fetchall() timings.append((clock() - start) * 1000) - return len(rows), statistics.median(timings) + return Measurement( + rows_fetched=len(rows), + wall_ms=statistics.median(timings), + server_ms=server_execution_ms(cursor, query, params), + ) def table_row_count(conn, table: str = "users") -> int: @@ -59,6 +110,30 @@ def table_row_count(conn, table: str = "users") -> int: return cur.fetchone()[0] +def format_ms(value: float | None) -> str: + return "n/a" if value is None else f"{value:.2f} ms" + + +def speedup(slow: float | None, fast: float | None) -> str: + if slow is None or not fast: + return "n/a" + return f"{slow / fast:.1f}x" + + +def plot_server_series(ax, query, color): + """Dashed companion line showing PostgreSQL's own time. + + The gap to the solid line is the client: for a wide SELECT * it is most of + the chart, which is the point. + """ + if not query.server_times or any(t is None for t in query.server_times): + return + ax.plot( + query.limits, query.server_times, linestyle="--", linewidth=1.2, + marker=".", color=color, alpha=0.75, label=f"{query.name} — server", + ) + + class BenchmarkNotApplicable(RuntimeError): """Raised when the current dataset is too small for the benchmark to mean anything.""" diff --git a/benchmarks/index_usage.py b/benchmarks/index_usage.py index 9dcbafa..a9489c6 100644 --- a/benchmarks/index_usage.py +++ b/benchmarks/index_usage.py @@ -12,7 +12,10 @@ BenchmarkBase, BenchmarkResult, QueryResult, + format_ms, measure, + plot_server_series, + speedup, ) from benchmarks.registry import register @@ -39,14 +42,11 @@ def setup(self, conn) -> None: conn.commit() def run(self, conn) -> BenchmarkResult: - q1_times, q1_rows = [], [] - q2_times, q2_rows = [], [] + m1, m2 = [], [] with conn.cursor() as cur: for age in THRESHOLDS: - rows, elapsed = measure(cur, QUERY, (age,)) - q1_times.append(elapsed) - q1_rows.append(rows) + m1.append(measure(cur, QUERY, (age,))) # Captured before the index exists: running both EXPLAINs after # CREATE INDEX makes them identical and the "no index" label a lie. @@ -58,19 +58,19 @@ def run(self, conn) -> BenchmarkResult: conn.commit() for age in THRESHOLDS: - rows, elapsed = measure(cur, QUERY, (age,)) - q2_times.append(elapsed) - q2_rows.append(rows) + m2.append(measure(cur, QUERY, (age,))) with_index_plan = run_explain(conn, QUERY, (EXPLAIN_AGE,)) q1 = QueryResult( - name=NO_INDEX_LABEL, query=QUERY, - times=q1_times, limits=THRESHOLDS, rows_fetched=q1_rows, + name=NO_INDEX_LABEL, query=QUERY, limits=THRESHOLDS, + times=[m.wall_ms for m in m1], rows_fetched=[m.rows_fetched for m in m1], + server_times=[m.server_ms for m in m1], ) q2 = QueryResult( - name=WITH_INDEX_LABEL, query=QUERY, - times=q2_times, limits=THRESHOLDS, rows_fetched=q2_rows, + name=WITH_INDEX_LABEL, query=QUERY, limits=THRESHOLDS, + times=[m.wall_ms for m in m2], rows_fetched=[m.rows_fetched for m in m2], + server_times=[m.server_ms for m in m2], ) return BenchmarkResult( @@ -89,13 +89,15 @@ def teardown(self, conn) -> None: def _build_comparison(self, q1, q2): rows = [] for i, age in enumerate(q1.limits): - speedup = f"{q1.times[i] / q2.times[i]:.1f}x" if q2.times[i] > 0 else "N/A" rows.append({ "age =": age, - "rows_matched": q1.rows_fetched[i], - "without_index": f"{q1.times[i]:.2f} ms", - "with_index": f"{q2.times[i]:.2f} ms", - "speedup": speedup, + "rows": q1.rows_fetched[i], + "no index (total)": format_ms(q1.times[i]), + "no index (server)": format_ms(q1.server_times[i]), + "indexed (total)": format_ms(q2.times[i]), + "indexed (server)": format_ms(q2.server_times[i]), + "speedup (total)": speedup(q1.times[i], q2.times[i]), + "speedup (server)": speedup(q1.server_times[i], q2.server_times[i]), }) return pd.DataFrame(rows) @@ -103,9 +105,11 @@ def _build_plot(self, q1, q2): fig = Figure(figsize=(10, 6)) canvas = FigureCanvasAgg(fig) ax = fig.add_subplot(111) - ax.plot(q1.limits, q1.times, marker="o", label=q1.name, color="#e74c3c") - ax.plot(q2.limits, q2.times, marker="s", label=q2.name, color="#2ecc71") - ax.set_title(self.title) + ax.plot(q1.limits, q1.times, marker="o", label=f"{q1.name} — total", color="#e74c3c") + ax.plot(q2.limits, q2.times, marker="s", label=f"{q2.name} — total", color="#2ecc71") + plot_server_series(ax, q1, "#e74c3c") + plot_server_series(ax, q2, "#2ecc71") + ax.set_title(f"{self.title} — solid: total, dashed: PostgreSQL only") ax.set_xlabel("age = value") ax.set_ylabel("Median execution time (ms)") ax.set_xticks(q1.limits) diff --git a/benchmarks/join_vs_subquery.py b/benchmarks/join_vs_subquery.py index ca9336b..7f1e88d 100644 --- a/benchmarks/join_vs_subquery.py +++ b/benchmarks/join_vs_subquery.py @@ -12,6 +12,7 @@ BenchmarkBase, BenchmarkResult, QueryResult, + format_ms, measure, ) from benchmarks.registry import register @@ -39,12 +40,20 @@ THRESHOLDS = [50, 100, 200, 300, 400] EXPLAIN_THRESHOLD = 100 +# Each user gets between 0 and MAX_ORDERS_PER_USER orders. Without a real 1:N +# relationship the three patterns are indistinguishable. +MAX_ORDERS_PER_USER = 5 +ORDER_PROBABILITY = 0.5 + @register class JoinVsSubqueryBenchmark(BenchmarkBase): name = "join_vs_subquery" title = "JOIN vs subquery for filtering" - description = "Compares JOIN, IN (subquery) and EXISTS for relational filtering" + description = ( + "Compares JOIN, IN (subquery) and EXISTS when a user has many orders — " + "JOIN fans out one row per order, IN and EXISTS collapse to a semi-join" + ) required_tables = ["users"] def setup(self, conn) -> None: @@ -59,30 +68,33 @@ def setup(self, conn) -> None: created_at TIMESTAMP DEFAULT NOW() ) """) + # One order per user made JOIN, IN and EXISTS return identical row + # sets and identical plans, so the benchmark compared three + # spellings of the same thing. The fan-out only appears at 1:N. cur.execute(f""" INSERT INTO {ORDERS} (user_id, amount) - SELECT id, (random() * 500)::DECIMAL(10,2) - FROM users - WHERE random() < 0.3 - """) + SELECT u.id, (random() * 500)::DECIMAL(10,2) + FROM users u, generate_series(1, %s) g + WHERE random() < %s + """, (MAX_ORDERS_PER_USER, ORDER_PROBABILITY)) cur.execute(f"CREATE INDEX ON {ORDERS}(user_id)") cur.execute(f"ANALYZE {ORDERS}") conn.commit() def run(self, conn) -> BenchmarkResult: - series = {QUERY_JOIN: ([], []), QUERY_SUBQUERY: ([], []), QUERY_EXISTS: ([], [])} + series = {QUERY_JOIN: [], QUERY_SUBQUERY: [], QUERY_EXISTS: []} with conn.cursor() as cur: for threshold in THRESHOLDS: - for query, (times, rows_fetched) in series.items(): - rows, elapsed = measure(cur, query, (threshold,)) - times.append(elapsed) - rows_fetched.append(rows) + for query, measurements in series.items(): + measurements.append(measure(cur, query, (threshold,))) q1, q2, q3 = ( QueryResult( - name=name, query=query.strip(), - times=series[query][0], limits=THRESHOLDS, rows_fetched=series[query][1], + name=name, query=query.strip(), limits=THRESHOLDS, + times=[m.wall_ms for m in series[query]], + rows_fetched=[m.rows_fetched for m in series[query]], + server_times=[m.server_ms for m in series[query]], ) for name, query in ( ("JOIN", QUERY_JOIN), @@ -112,10 +124,14 @@ def _build_comparison(self, q1, q2, q3): for i, threshold in enumerate(q1.limits): rows.append({ "amount >": threshold, - "rows_matched": q1.rows_fetched[i], - "join": f"{q1.times[i]:.2f} ms", - "in_subquery": f"{q2.times[i]:.2f} ms", - "exists": f"{q3.times[i]:.2f} ms", + "join rows": q1.rows_fetched[i], + "in/exists rows": q2.rows_fetched[i], + "join (server)": format_ms(q1.server_times[i]), + "in (server)": format_ms(q2.server_times[i]), + "exists (server)": format_ms(q3.server_times[i]), + "join (total)": format_ms(q1.times[i]), + "in (total)": format_ms(q2.times[i]), + "exists (total)": format_ms(q3.times[i]), }) return pd.DataFrame(rows) diff --git a/benchmarks/pagination.py b/benchmarks/pagination.py index 4a75433..e278334 100644 --- a/benchmarks/pagination.py +++ b/benchmarks/pagination.py @@ -13,7 +13,9 @@ BenchmarkNotApplicable, BenchmarkResult, QueryResult, + format_ms, measure, + speedup, table_row_count, ) from benchmarks.registry import register @@ -52,26 +54,21 @@ def _offsets(self, total: int) -> list[int]: def run(self, conn) -> BenchmarkResult: offsets = self._offsets(table_row_count(conn)) - q1_times, q1_rows = [], [] - q2_times, q2_rows = [], [] - + m1, m2 = [], [] with conn.cursor() as cur: for offset in offsets: - rows, elapsed = measure(cur, QUERY_OFFSET, (PAGE_SIZE, offset)) - q1_times.append(elapsed) - q1_rows.append(rows) - - rows, elapsed = measure(cur, QUERY_KEYSET, (offset, PAGE_SIZE)) - q2_times.append(elapsed) - q2_rows.append(rows) + m1.append(measure(cur, QUERY_OFFSET, (PAGE_SIZE, offset))) + m2.append(measure(cur, QUERY_KEYSET, (offset, PAGE_SIZE))) q1 = QueryResult( - name="OFFSET", query=QUERY_OFFSET, - times=q1_times, limits=offsets, rows_fetched=q1_rows, + name="OFFSET", query=QUERY_OFFSET, limits=offsets, + times=[m.wall_ms for m in m1], rows_fetched=[m.rows_fetched for m in m1], + server_times=[m.server_ms for m in m1], ) q2 = QueryResult( - name="Keyset (WHERE id >)", query=QUERY_KEYSET, - times=q2_times, limits=offsets, rows_fetched=q2_rows, + name="Keyset (WHERE id >)", query=QUERY_KEYSET, limits=offsets, + times=[m.wall_ms for m in m2], rows_fetched=[m.rows_fetched for m in m2], + server_times=[m.server_ms for m in m2], ) deepest = offsets[-1] @@ -89,14 +86,15 @@ def run(self, conn) -> BenchmarkResult: def _build_comparison(self, q1, q2): rows = [] for i, offset in enumerate(q1.limits): - speedup = f"{q1.times[i] / q2.times[i]:.1f}x" if q2.times[i] > 0 else "N/A" rows.append({ "offset": offset, "page": offset // PAGE_SIZE + 1, - "rows_fetched": q1.rows_fetched[i], - "offset_ms": f"{q1.times[i]:.2f} ms", - "keyset_ms": f"{q2.times[i]:.2f} ms", - "speedup": speedup, + "rows": q1.rows_fetched[i], + "offset (total)": format_ms(q1.times[i]), + "offset (server)": format_ms(q1.server_times[i]), + "keyset (total)": format_ms(q2.times[i]), + "keyset (server)": format_ms(q2.server_times[i]), + "speedup (server)": speedup(q1.server_times[i], q2.server_times[i]), }) return pd.DataFrame(rows) diff --git a/benchmarks/select_star.py b/benchmarks/select_star.py index 134f509..c5759b8 100644 --- a/benchmarks/select_star.py +++ b/benchmarks/select_star.py @@ -12,7 +12,10 @@ BenchmarkNotApplicable, BenchmarkResult, QueryResult, + format_ms, measure, + plot_server_series, + speedup, table_row_count, ) from benchmarks.registry import register @@ -49,25 +52,21 @@ def setup(self, conn) -> None: def run(self, conn) -> BenchmarkResult: limits = self._limits(table_row_count(conn)) - q1_times, q2_times = [], [] - q1_rows, q2_rows = [], [] - + m1, m2 = [], [] with conn.cursor() as cursor: for limit in limits: - rows_1, t1 = measure(cursor, QUERY_ALL_COLUMNS, (limit,)) - rows_2, t2 = measure(cursor, QUERY_THREE_COLUMNS, (limit,)) - q1_times.append(t1) - q2_times.append(t2) - q1_rows.append(rows_1) - q2_rows.append(rows_2) + m1.append(measure(cursor, QUERY_ALL_COLUMNS, (limit,))) + m2.append(measure(cursor, QUERY_THREE_COLUMNS, (limit,))) q1 = QueryResult( - name=LABEL_ALL_COLUMNS, query=QUERY_ALL_COLUMNS, - times=q1_times, limits=limits, rows_fetched=q1_rows, + name=LABEL_ALL_COLUMNS, query=QUERY_ALL_COLUMNS, limits=limits, + times=[m.wall_ms for m in m1], rows_fetched=[m.rows_fetched for m in m1], + server_times=[m.server_ms for m in m1], ) q2 = QueryResult( - name=LABEL_THREE_COLUMNS, query=QUERY_THREE_COLUMNS, - times=q2_times, limits=limits, rows_fetched=q2_rows, + name=LABEL_THREE_COLUMNS, query=QUERY_THREE_COLUMNS, limits=limits, + times=[m.wall_ms for m in m2], rows_fetched=[m.rows_fetched for m in m2], + server_times=[m.server_ms for m in m2], ) return BenchmarkResult( @@ -80,13 +79,15 @@ def run(self, conn) -> BenchmarkResult: def _build_comparison(self, q1: QueryResult, q2: QueryResult) -> pd.DataFrame: rows = [] for i, limit in enumerate(q1.limits): - speedup = f"{q1.times[i] / q2.times[i]:.1f}x" if q2.times[i] > 0 else "N/A" rows.append({ "limit": limit, - "rows_fetched": q1.rows_fetched[i], - "select_star": f"{q1.times[i]:.2f} ms", - "select_columns": f"{q2.times[i]:.2f} ms", - "speedup": speedup, + "rows": q1.rows_fetched[i], + "select_star (total)": format_ms(q1.times[i]), + "select_star (server)": format_ms(q1.server_times[i]), + "3 cols (total)": format_ms(q2.times[i]), + "3 cols (server)": format_ms(q2.server_times[i]), + "speedup (total)": speedup(q1.times[i], q2.times[i]), + "speedup (server)": speedup(q1.server_times[i], q2.server_times[i]), }) return pd.DataFrame(rows) @@ -94,9 +95,11 @@ def _build_plot(self, q1: QueryResult, q2: QueryResult) -> io.BytesIO: fig = Figure(figsize=(10, 6)) canvas = FigureCanvasAgg(fig) ax = fig.add_subplot(111) - ax.plot(q1.limits, q1.times, marker="o", label=q1.name, color="#e74c3c") - ax.plot(q2.limits, q2.times, marker="s", label=q2.name, color="#2ecc71") - ax.set_title(f"{self.title} (median of {len(q1.limits)} points)") + ax.plot(q1.limits, q1.times, marker="o", label=f"{q1.name} — total", color="#e74c3c") + ax.plot(q2.limits, q2.times, marker="s", label=f"{q2.name} — total", color="#2ecc71") + plot_server_series(ax, q1, "#e74c3c") + plot_server_series(ax, q2, "#2ecc71") + ax.set_title(f"{self.title} — solid: total, dashed: PostgreSQL only") ax.set_xlabel("LIMIT (rows fetched)") ax.set_ylabel("Median execution time (ms)") ax.set_xticks(q1.limits) diff --git a/tests/test_benchmark.py b/tests/test_benchmark.py index c185cad..c837dfd 100644 --- a/tests/test_benchmark.py +++ b/tests/test_benchmark.py @@ -131,6 +131,7 @@ def test_select_star_build_comparison(): times=[10.0, 5.0], limits=[1000, 500], rows_fetched=[1000, 500], + server_times=[4.0, 2.0], ) q2 = QueryResult( name="Q2", @@ -138,14 +139,17 @@ def test_select_star_build_comparison(): times=[2.0, 1.0], limits=[1000, 500], rows_fetched=[1000, 500], + server_times=[1.0, 0.5], ) table = bm._build_comparison(q1, q2) assert isinstance(table, pd.DataFrame) assert len(table) == 2 - assert "10.00 ms" in table.iloc[0]["select_star"] - assert "5.0x" in table.iloc[0]["speedup"] + assert "10.00 ms" in table.iloc[0]["select_star (total)"] + assert "4.00 ms" in table.iloc[0]["select_star (server)"] + assert "5.0x" in table.iloc[0]["speedup (total)"] + assert "4.0x" in table.iloc[0]["speedup (server)"] def test_select_star_build_plot(): diff --git a/tests/test_integration.py b/tests/test_integration.py index 9b05525..992c8d9 100644 --- a/tests/test_integration.py +++ b/tests/test_integration.py @@ -180,3 +180,42 @@ def test_seed_fails_fast_instead_of_hanging_on_a_locked_table(conn): other.close() finally: blocker.close() + + +def test_join_benchmark_data_is_one_to_many(conn): + """With one order per user, JOIN never fans out and the three patterns + collapse to the same plan — the benchmark would compare nothing.""" + bm = get("join_vs_subquery") + bm.setup(conn) + try: + with conn.cursor() as cur: + cur.execute( + "SELECT max(c) FROM (" + " SELECT user_id, count(*) c FROM sqlperf_orders GROUP BY user_id" + ") t" + ) + assert cur.fetchone()[0] > 1, "orders must be 1:N for the comparison to mean anything" + + result = bm.run(conn) + finally: + bm.teardown(conn) + + join, in_subquery = result.queries[0], result.queries[1] + assert any(j > i for j, i in zip(join.rows_fetched, in_subquery.rows_fetched, strict=True)), ( + "JOIN must return more rows than IN/EXISTS somewhere, otherwise there is no fan-out" + ) + + +def test_every_benchmark_reports_server_side_timings(conn): + """Wall time is mostly client deserialisation; without the server number + a client-side cost reads as a database result.""" + for name in [bm.name for bm in all_benchmarks()]: + bm = get(name) + bm.setup(conn) + try: + result = bm.run(conn) + finally: + bm.teardown(conn) + for query in result.queries: + assert len(query.server_times) == len(query.times) + assert all(t is not None for t in query.server_times), f"{name}/{query.name}" diff --git a/tests/test_measure.py b/tests/test_measure.py index 6d46286..942618a 100644 --- a/tests/test_measure.py +++ b/tests/test_measure.py @@ -2,6 +2,12 @@ from benchmarks.base import REPETITIONS, measure +EXPLAIN_OUTPUT = [ + ("Seq Scan on users (cost=0.00..3273.00 rows=100000 width=143)",), + ("Planning Time: 0.041 ms",), + ("Execution Time: 3.90 ms",), +] + class FakeCursor: """Records every execute so we can assert on warm-up and repetitions.""" @@ -14,23 +20,29 @@ def execute(self, query, params=None): self.executed.append((query, params)) def fetchall(self): + if self.executed and self.executed[-1][0].startswith("EXPLAIN"): + return EXPLAIN_OUTPUT return self._rows + @property + def timed(self): + return [q for q, _ in self.executed if not q.startswith("EXPLAIN")] + def test_measure_discards_a_warmup_run_before_timing(): cursor = FakeCursor() measure(cursor, "SELECT 1", repetitions=3) - assert len(cursor.executed) == 4, "expected 1 warm-up + 3 timed runs" + assert len(cursor.timed) == 4, "expected 1 warm-up + 3 timed runs" def test_measure_returns_the_number_of_rows_fetched(): cursor = FakeCursor(rows=7) - rows, _ = measure(cursor, "SELECT 1") + result = measure(cursor, "SELECT 1") - assert rows == 7 + assert result.rows_fetched == 7 def test_measure_passes_params_through_on_every_run(): @@ -41,15 +53,53 @@ def test_measure_passes_params_through_on_every_run(): assert all(params == (42,) for _, params in cursor.executed) -def test_measure_reports_the_median_not_the_first_run(): +def test_measure_reports_the_median_wall_time_not_the_first_run(): """One slow cold run must not drag the reported time; mean would give 20.8ms.""" cursor = FakeCursor() - # start/end pairs in seconds -> deltas of 100ms, 1ms, 1ms, 1ms, 1ms ticks = iter([0, 0.100, 0, 0.001, 0, 0.001, 0, 0.001, 0, 0.001]) - _, elapsed = measure(cursor, "SELECT 1", repetitions=5, clock=lambda: next(ticks)) + result = measure(cursor, "SELECT 1", repetitions=5, clock=lambda: next(ticks)) + + assert result.wall_ms == pytest.approx(1.0) + + +def test_measure_reports_the_server_execution_time_separately(): + """Wall time is dominated by client deserialisation; the planner's own cost + only shows up in EXPLAIN.""" + cursor = FakeCursor() + + result = measure(cursor, "SELECT 1", repetitions=2) + + assert result.server_ms == pytest.approx(3.90) + + +def test_measure_asks_the_server_for_its_own_timing(): + cursor = FakeCursor() + + measure(cursor, "SELECT * FROM users", repetitions=2) + + explains = [q for q, _ in cursor.executed if q.startswith("EXPLAIN")] + assert len(explains) == 1 + assert "ANALYZE" in explains[0] + + +def test_measure_survives_a_server_that_reports_no_execution_time(): + cursor = FakeCursor() + cursor.fetchall = lambda: [("something unparseable",)] + + result = measure(cursor, "SELECT 1", repetitions=2) + + assert result.server_ms is None + + +def test_client_share_is_the_fraction_of_wall_time_spent_outside_postgres(): + cursor = FakeCursor() + ticks = iter([0, 0.100, 0, 0.100, 0, 0.100]) + + result = measure(cursor, "SELECT 1", repetitions=3, clock=lambda: next(ticks)) - assert elapsed == pytest.approx(1.0) + # 100ms wall, 3.90ms server -> 96.1% of the time is not the database + assert result.client_share == pytest.approx(0.961, abs=0.001) def test_default_repetitions_is_more_than_one():