Subject: benchmark results comparing versions 15.2 and 16

From: MARK CALLAGHAN <[email-masked]>
Date: Fri, 5 May 2023 10:45:12 -0700

Let me know if results like this shouldn't be posted here.

This is mostly a hobby project for me - my other hobby is removing
invasive weeds. I am happy to answer questions and run more tests, but
turnaround for answers won't be instant. Getting results from Linux perf
for these tests is on my TODO list. For now I am just re-running a subset
of these to get more certainty that the regressions are real and not noise.

These are results for the insert benchmark on a small server comparing
performance for versions 15.2 and 16. For version 16 I built from source at
git sha 1ab763fc.
https://github.com/postgres/postgres/commit/1ab763fc22adc88e5d779817e7b42b25a9dd7c9e

Late in the version 15 beta release cycle this benchmark found a
significant regression. I don't see anything significant this time, but
there are potential small regressions.

More detail on how I run the benchmark and the HW is here, the server is
small -- Beelink with 8 cores, 16G RAM and 1T NVMe SSD.
http://smalldatum.blogspot.com/2023/05/the-insert-benchmark-postgres-versions.html

Performance reports are linked below. But first, disclaimers:
* the goal is to determine whether there are CPU improvements or
regressions. To make that easier to spot I disable fsync on commit.
* my scripts compute CPU/operation where operation is a SQL statement.
However, CPU in this case is measured by vmstat and includes CPU from the
benchmark client and Postgres server
* the regressions here are small, usually less than 5% which means it can
be hard to distinguish between normal variance and a regression but the
results are repeatable
* the links below are to the Summary section which includes throughput
(absolute and relative). The relative throughput is the (throughput for PG
16 / throughput for PG 15.2) and
* I used the same compiler options for the builds of 15.2 and 16

Summary of the results:
* from r1 - insert-heavy (l.i0, l.i1) and create indexes (l.x) steps are
~2% slower in PG 16
* from r2 - create index (l.x) step is ~4% slower in PG 16
* from r3 - regressions are similar to r1
* from r4, r5 and r6 - regressions are mostly worse than r1, r2, r3. Note
r4, r5, r6 are the same workload as r1, r2, r3 except the database is
cached by PG for r1, r2, r3 so the r4, r5 and r6 benchmarks will do much
more copying from the OS page cache into the Postgres buffer pool.

I will repeat r1, r2, r4 and r5 but with the tests run in a different order
to confirm this isn't just noise.

Database cached by Postgres:
r1) 1 table, 1 client -
https://mdcallag.github.io/reports/23_05_04_ibench.beelink.pg16b.1u.1tno.cached/all.html#summary
r2) 4 tables, 4 clients -
https://mdcallag.github.io/reports/23_05_04_ibench.beelink.pg16b.4u.1tno.cached/all.html#summary
r3) 1 table, 4 clients -
https://mdcallag.github.io/reports/23_05_04_ibench.beelink.pg16b.4u.1tyes.cached/all.html#summary

Database cached by OS but not by Postgres:
r4) 1 table, 1 client -
https://mdcallag.github.io/reports/23_05_04_ibench.beelink.pg16b.1u.1tno.1g/all.html#summary
r5) 4 tables, 4 clients -
https://mdcallag.github.io/reports/23_05_04_ibench.beelink.pg16b.4u.1tno.1g/all.html#summary
r6) 1 table, 4 clients -
https://mdcallag.github.io/reports/23_05_04_ibench.beelink.pg16b.4u.1tyes.1g/all.html#summary

-- 
Mark Callaghan
[email-masked]

---

From: Andres Freund <[email-masked]>
Date: Fri, 5 May 2023 13:34:31 -0700

Hi,

On 2023-05-05 10:45:12 -0700, MARK CALLAGHAN wrote:
> invasive weeds.

Hah :)

> more copying from the OS page cache into the Postgres buffer pool.

One thing that's somewhat odd is that there's very marked changes in l.i0's
p99 latency for the four clients cases - but whether 15 or 16 are better
differs between the runs.

r2)
                                p99
20m.pg152_o3_native_lto.cx7     300
20m.pg16prebeta.cx7             23683

r3)
                                p99
20m.pg152_o3_native_lto.cx7     70245
20m.pg16prebeta.cx7             8191

r5)
                                p99
20m.pg152_o3_native_lto.cx7     11188
20m.pg16prebeta.cx7             72720

r6)
                                p99
20m.pg152_o3_native_lto.cx7     1898
20m.pg16prebeta.cx7             31666

I do wonder if there's something getting scheduled in some of these runs
increasing latency?

Or what we're seeing depends on the time between the start of the server and
the start of the benchmark? It is interesting that the per-second throughput
graph shows a lot of up/down at the end:
https://mdcallag.github.io/reports/23_05_04_ibench.beelink.pg16b.4u.1tyes.1g/tput.l.i0.html

Both 15 and 16 have one very high result at 70s, 15 then has one low, but 16
has two low results.

Greetings,

Andres Freund

---

From: Alexander Lakhin <[email-masked]>
Date: Mon, 8 May 2023 16:00:01 +0300

Hello Mark,

05.05.2023 20:45, MARK CALLAGHAN wrote:
> This is mostly a hobby project for me - my other hobby is removing invasive weeds. I am happy to answer questions and 
> run more tests, but turnaround for answers won't be instant. Getting results from Linux perf for these tests is on my 
> TODO list. For now I am just re-running a subset of these to get more certainty that the regressions are real and not 
> noise.
>

It's a very interesting topic to me, too. I had developed some scripts to
measure and compare postgres`s performance using miscellaneous public
benchmarks (ycsb, tpcds, benchmarksql_tpcc, htapbench, benchbase, gdprbench,
s64da-benchmark, ...). Having compared 15.3 (56e869a09) with master
(58f5edf84) I haven't seen significant regressions except a few minor ones.
First regression observed with a simple pgbench test:
pgbench -i benchdb
pgbench -c 10 -T 300 benchdb
(with default compilation options and fsync = off)

On master I get:
tps = 10349.826645 (without initial connection time)
On 15.3:
tps = 11296.064992 (without initial connection time)

This difference is confirmed by multiple test runs. `git bisect` for this
regression pointed at f193883fc.

Best regards,
Alexander

---

From: Alexander Lakhin <[email-masked]>
Date: Wed, 10 May 2023 16:00:01 +0300

08.05.2023 16:00, Alexander Lakhin wrote:
> ... Having compared 15.3 (56e869a09) with master

Another noticeable, but not critical performance degradation is revealed by
query 87 from TPC-DS (I use s64da-benchmark):
https://github.com/swarm64/s64da-benchmark-toolkit/blob/master/benchmarks/tpcds/queries/queries_10/87.sql

With `prepare_benchmark --scale-factor=2`, `run_benchmark --scale-factor=10`
I get on master:
2023-05-10 09:27:52,888 INFO    : finished 80/103: query 87 of stream  0: 2.26s OK
but on REL_15_STABLE:
2023-05-10 08:13:40,648 INFO    : finished 80/103: query 87 of stream  0: 1.94s OK

This time `git bisect` pointed at 3c6fc5820. Having compared execution plans
(both attached), I see the following differences (3c6fc5820~1 vs 3c6fc5820):
->  Subquery Scan on "*SELECT* 1"  (cost=149622.00..149958.68 rows=16834 width=21) (actual time=1018.606..1074.468 
rows=93891 loops=1)
  ->  Unique  (cost=149622.00..149790.34 rows=16834 width=17) (actual time=1018.604..1064.790 rows=93891 loops=1)
   ->  Sort  (cost=149622.00..149664.09 rows=16834 width=17) (actual time=1018.603..1052.591 rows=94199 loops=1)
    ->  Gather  (cost=146588.59..148440.33 rows=16834 width=17) (actual time=880.899..913.978 rows=94199 loops=1)
vs
->  Subquery Scan on "*SELECT* 1"  (cost=147576.79..149829.53 rows=16091 width=21) (actual time=1126.489..1366.751 
rows=93891 loops=1)
  ->  Unique  (cost=147576.79..149668.62 rows=16091 width=17) (actual time=1126.487..1356.938 rows=93891 loops=1)
   ->  Gather Merge  (cost=147576.79..149547.94 rows=16091 width=17) (actual time=1126.487..1345.253 rows=94204 loops=1)
    ->  Unique  (cost=146576.78..146737.69 rows=16091 width=17) (actual time=1124.426..1306.532 rows=47102 loops=2)
     ->  Sort  (cost=146576.78..146617.01 rows=16091 width=17) (actual time=1124.424..1245.110 rows=533434 loops=2)

->  Subquery Scan on "*SELECT* 2"  (cost=52259.82..52428.16 rows=8417 width=21) (actual time=653.640..676.879 rows=62744 
loops=1)
  ->  Unique  (cost=52259.82..52343.99 rows=8417 width=17) (actual time=653.639..670.405 rows=62744 loops=1)
   ->  Sort  (cost=52259.82..52280.86 rows=8417 width=17) (actual time=653.637..662.428 rows=62744 loops=1)
    ->  Gather  (cost=50785.20..51711.07 rows=8417 width=17) (actual time=562.158..571.737 rows=62744 loops=1)
     ->  HashAggregate  (cost=49785.20..49869.37 rows=8417 width=17) (actual time=538.263..544.336 rows=31372 loops=2)
      ->  Nested Loop  (cost=0.85..49722.07 rows=8417 width=17) (actual time=2.049..469.747 rows=284349 loops=2)
vs
->  Subquery Scan on "*SELECT* 2"  (cost=48503.68..49630.12 rows=8046 width=21) (actual time=700.050..828.388 rows=62744 
loops=1)
  ->  Unique  (cost=48503.68..49549.66 rows=8046 width=17) (actual time=700.047..821.836 rows=62744 loops=1)
   ->  Gather Merge  (cost=48503.68..49489.31 rows=8046 width=17) (actual time=700.047..814.136 rows=62744 loops=1)
    ->  Unique  (cost=47503.67..47584.13 rows=8046 width=17) (actual time=666.348..763.403 rows=31372 loops=2)
     ->  Sort  (cost=47503.67..47523.78 rows=8046 width=17) (actual time=666.347..730.336 rows=284349 loops=2)
      ->  Nested Loop  (cost=0.85..46981.72 rows=8046 width=17) (actual time=1.852..454.111 rows=284349 loops=2)

->  Subquery Scan on "*SELECT* 3"  (cost=50608.83..51568.70 rows=7165 width=21) (actual time=302.571..405.305 rows=23737 
loops=1)
  ->  Unique  (cost=50608.83..51497.05 rows=7165 width=17) (actual time=302.568..402.818 rows=23737 loops=1)
   ->  Gather Merge  (cost=50608.83..51443.31 rows=7165 width=17) (actual time=302.567..372.246 rows=287761 loops=1)
    ->  Sort  (cost=49608.81..49616.27 rows=2985 width=17) (actual time=298.204..310.075 rows=95920 loops=3)
     ->  Nested Loop  (cost=2570.65..49436.52 rows=2985 width=17) (actual time=3.205..229.192 rows=95920 loops=3)
vs
->  Subquery Scan on "*SELECT* 3"  (cost=50541.84..51329.11 rows=5708 width=21) (actual time=302.042..336.820 rows=23737 
loops=1)
  ->  Unique  (cost=50541.84..51272.03 rows=5708 width=17) (actual time=302.039..334.329 rows=23737 loops=1)
   ->  Gather Merge  (cost=50541.84..51229.22 rows=5708 width=17) (actual time=302.039..331.296 rows=24128 loops=1)
    ->  Unique  (cost=49541.81..49570.35 rows=2854 width=17) (actual time=298.771..320.560 rows=8043 loops=3)
     ->  Sort  (cost=49541.81..49548.95 rows=2854 width=17) (actual time=298.770..309.603 rows=95920 loops=3)
      ->  Nested Loop  (cost=2570.52..49378.01 rows=2854 width=17) (actual time=3.209..230.291 rows=95920 loops=3)

 From the commit message and the discussion [1], it's not clear to me, whether
this plan change is expected. Perhaps it's too minor issue to bring attention
to, but maybe this information could be useful for v16 performance analysis.

[1] https://postgr.es/m/CAApHDvo8Lz2H=[email-masked]

Best regards,
Alexander

---

From: David Rowley <[email-masked]>
Date: Thu, 11 May 2023 10:27:28 +1200

> (both attached), I see the following differences (3c6fc5820~1 vs 3c6fc5820):

Based on what you've sent, I'm uninspired to want to try to do
anything about it.  The patched version finds a plan that's cheaper.
The row estimates are miles off with both plans. I'm not sure what
we're supposed to do here. It's pretty hard to make changes to the
planner's path generation without risking that a bad plan is chosen
when it wasn't beforehand with bad row estimates.

Is the new plan still slower if you increase work_mem so that the sort
no longer goes to disk?  Maybe the planner would have picked Hash
Aggregate if the row estimates had been such that cost_tuplesort()
knew that the sort would have gone to disk.

David

---

From: Alexander Lakhin <[email-masked]>
Date: Thu, 11 May 2023 16:00:01 +0300

11.05.2023 01:27, David Rowley wrote:
> The row estimates are miles off with both plans.

I've made sure that s64da-benchmark performs analyze before running the
queries (pg_class.reltuples fields for tables in question contain actual
counts), so it seems that nothing can be done on the benchmark side to
improve those estimates.

> ... It's pretty hard to make changes to the

Yeah, I see. It's also interesting to me, which tests perform better after
that commit. It takes several hours to run all tests, so I can't present
results quickly, but I'll try to collect this information next week.

> knew that the sort would have gone to disk.

Yes, increasing work_mem to 50MB doesn't affect the plans (new plans
attached), though the sort method changed to quicksort. The former plan is
still executed slightly faster.

Best regards,
Alexander

---

From: Alexander Lakhin <[email-masked]>
Date: Fri, 7 Jul 2023 16:00:01 +0300

Hello David,

> results quickly, but I'll try to collect this information next week.

To my regret, I could not find such tests that week, so I decided to try
later, after reviewing my benchmark running infrastructure.

But for now, as Postgres Pro company graciously shared the benchmarking
infrastructure project [1], it's possible for anyone to confirm or deny my
results. (You can also see which tests were performed and how.)

Having done one more round of comprehensive testing, I still couldn't find
winning tests for commit 3c6fc5820 (but reassured that
test s64da_tpcds.query87 loses a little (and also s64da_tpcds.query38)).
So it seems to me that the tests I performed or their parameters is not
representative enough for that improvement, unfortunately.

[1] https://github.com/postgrespro/pg-mark

Best regards,
Alexander