Subject: Database creation performance drop going from pg 14 to pg 15+

From: "Mahdi Bahrami" <[email-masked]>
Date: Thu, 15 May 2025 19:58:50 +0330

This is about a performance issue / unexpected behavior that I found when investigating https://github.com/vapor/postgres-nio/issues/506.
The related message to this thread is 
https://github.com/vapor/postgres-nio/issues/506#issuecomment-2883158951.
As a TL;DR about that issue, a user reported a performance problem when going from postgres 13 to any postgres' higher, and upon my investigations, the main issue turned out to be the fact that pg 13 docker images default to md5 auth, and postgres 14+ default to scram-sha-256. The library had an unoptimized scram-sha-256 implementation, which has since been resolved, making the auth almost as fast as md5, so the main problem is resolved.

The other problem is what I have questions about. It's a performance regression noticed in pg 15 and higher, with pg 13 and 14 being faster than 15+, that i mentioned in https://github.com/vapor/postgres-nio/issues/506#issuecomment-2883158951.

To set things up, the project used to reproduce all these is https://github.com/finestructure/pg-perf-regression.git, branch `check-fixes`. You can run the benchmark using the `./run-perf-test.sh` script (a simple one). But you need to have a recent Swift installed (see https://swift.org, use swiftly) and docker running. Then try running the script using 
`./run-perf-test.sh 14 test1`
with `14` being the postgres version.

The problem can be seen in the 2 captures attached to this email. Each capture contains 2 runs of `test1`.
In the code in the repository, and also in the packet captures, you can see that each run of `test1`, runs the queries below in order, one by one:
first connection:
```
DROP DATABASE IF EXISTS spi_test WITH (FORCE)
```
```
CREATE DATABASE spi_test
```
second connection the same as first connection.
third connection:
```
DROP DATABASE IF EXISTS spi_test_snapshot WITH (FORCE)
```
```
CREATE DATABASE spi_test_snapshot TEMPLATE spi_test
```
all these only for the first run. As mentioned, there are 2 rounds in each capture.

Here is an image from each capture:

First one. pg 15. Last message is 50ms after the first message.
Second one. pg 14. Last message is 37ms after the first message.

All while the environment and all being the same. Same image arch, same code same everything. Official alpine docker images. Run on a M1 MacBook. I've even confirmed the messages in both captures are as identical as possible at Postgres level (e.g. obviously the md5 hashes of the authentication don't match).

The difference in the time comes from the `CREATE DATABASE spi_test` query. It appears that query takes 15ms in postgres 14 and 28ms in postgres 15 from the query-send till the response-send messages, which means almost twice as slow. The slowness comes after the library is done sending the query, which means the library cannot be at fault (taking all I explained above into account).

This issue is not necessarily a big deal to us, but can anyone please explain the why? Or a fix/workaround?
Maybe some kind of default setting changes between pg 14 and 15 that results in this performance regression?!

---

From: "Mahdi Bahrami" <[email-masked]>
Date: Tue, 27 May 2025 11:42:31 +0330

I had some more time/mood to mess around with this. Interestingly enough, psql CLI seems to be consistently slower than the Swift client (PostgresNIO: https://github.com/vapor/postgres-nio) that I was using. The new psql-CLI packet captures are attached.

Though it does appear that psql uses SimpleQuery by default, which makes sense considering it's a CLI tool. PostgresNIO uses ExtendedQuery by default which can explain the differences. PostgresNIO does not support SimpleQuery yet; I'm awaiting a review for a PR that adds that support: https://github.com/vapor/postgres-nio/pull/505.

The other notable thing is that I re-ran the scripts but with using psql CLI, and although things are slower (per the packet captures), they are at least consistent. I can't see any significant performance differences between Postgres versions when using psql CLI, which might mean that this performance degradation only happens under ExtendedQuery and not SimpleQuery.

Here's how I ran the commands that seem to be at fault when using PostgresNIO. I only ran the drop-db create-db commands, not the whole chain, which should still be sufficient:
```
PGPASSWORD=xxx psql -U spi_test -h 127.0.0.1 postgres -c "DROP DATABASE IF EXISTS spi_test WITH (FORCE);" -c "CREATE DATABASE spi_test;"
```

For checking this against multiple postgres versions and different auth mechanisms like in the original repo in the `run-perf-test.sh` script, I ran the commands through Docker CLI (podman to be precise, docker is an alias to podman here):
```
docker exec spi_test bash -c 'COMMAND_ABOVE'
```

For packet captures, I opened up a shell into the container and ran the psql command while having tcpdump capturing the packets.

Here's an image of an overview of the packet captures. The 2 on the left are the old ones with PostgresNIO, the 2 on the right are the new ones using psql. The postgres versions are mentioned in the Wireshark window names up there or down below.

As you can see in the image, the psql ones consistently take 63ms compared to the 37/51ms of when using PostgresNIO.
The StartupMessage is set as the time reference for all captures.
For clarity, in the image only the first connection is filtered-in from the PostgresNIO captures.

---

From: Álvaro Herrera <[email-masked]>
Date: Tue, 27 May 2025 17:07:12 +0200

On 2025-May-27, Mahdi Bahrami wrote:

> Here's how I ran the commands that seem to be at fault when using
> PostgresNIO. I only ran the drop-db create-db commands, not the whole
> chain, which should still be sufficient:
> ```

I wonder if this is related to the change to CREATE DATABASE in release 15.
Maybe you could test this with "CREATE DATABASE spi_test STRATEGY =
file_copy;" and see if that returns it to the original performance.
The new strategy is allegedly faster, but maybe in your case, for
whatever reason, it isn't.

I do wonder why is the database drop/create performance so critical,
though.  I mean, surely there are more relevant performance problems to
be concerned about.

-- 
Álvaro Herrera        Breisgau, Deutschland  —  https://www.EnterpriseDB.com/
"Tiene valor aquel que admite que es un cobarde" (Fernandel)

---

From: "Mahdi Bahrami" <[email-masked]>
Date: Wed, 28 May 2025 14:39:20 +0330

Thanks for the hint, that was exactly it! I also asked the original author of the issue and he has confirmed the performance of pg 15+ now matches those of pg 13/14.

As mentioned "This issue is not necessarily a big deal to us, but can anyone please explain the why?" so it was partially out of curiosity, and partially because of the way the author of the issue is using Postgres which apparently is sensitive to these milliseconds.

Not exactly sure what's their set up, but they did mention with the PostgresNIO SASL improvements which saves only some 10-20-30-40 milliseconds or so, their tests now run in 15s instead of 1m30s, which then it means they can now use pg versions higher than pg 13 and still have around the same performance.
I think they run tests in parallel, and they possibly recreate the whole DB once for each test.

---

From: Thomas Munro <[email-masked]>
Date: Wed, 28 May 2025 23:29:04 +1200

On Wed, May 28, 2025 at 11:09 PM Mahdi Bahrami <[email-masked]> wrote:
> their tests now run in 15s instead of 1m30s

Wow.  If/when they get to v18, they might also try setting
file_copy_method=clone when using strategy=file_copy.

---

From: "Mahdi Bahrami" <[email-masked]>
Date: Wed, 28 May 2025 15:45:02 +0330

To be clear the "15s instead of 1m30s" was related to another issue about SASL implementation of PostgresNIO being slow, not this CREATE DATABASE strategy change. I was just trying to explain that in their set up, these saved milliseconds do matter for whatever reason.

---

From: "Mahdi Bahrami" <[email-masked]>
Date: Thu, 05 Jun 2025 21:55:04 +0330

Here's what the OP of the PostgresNIO issue has mentioned about what performance impact usage of `file_copy` has in his setup (https://github.com/SwiftPackageIndex/SwiftPackageIndex-Server/pull/3812):

`Series: Default Strategy
Suite AllTests passed after 5.081 seconds
Suite AllTests passed after 5.274 seconds
Suite AllTests passed after 5.306 seconds
Suite AllTests passed after 5.224 seconds
Suite AllTests passed after 6.343 seconds
Suite AllTests passed after 5.450 seconds
Series: file_copy Strategy
Suite AllTests passed after 4.729 seconds
Suite AllTests passed after 4.755 seconds
Suite AllTests passed after 4.739 seconds
Suite AllTests passed after 4.772 seconds
Suite AllTests passed after 4.866 seconds
Suite AllTests passed after 4.855 seconds`

This is them running the tests in parallel multiple times with and without file_copy, just to benchmark.
Overall ~0.5-6s / ~10% speedup, which isn't too significant at this level, but is still a noticeable relative improvement.