DB reset too slow with PG 16 db

[finestructure]

First seen in #3278, using a PG 16 test db to run the tests makes them run really slowly (~6min vs 1.5min).

This is due to the function _resetDb, which TRUNCATEs all tables, taking much longer. I added

    let start = Date()
    defer { print("Resetting database took: \(Date().timeIntervalSince(start))s") }

to the start of the function and then ran the AnalyzeErrorTests (4 tests):

swift test --disable-automatic-resolution --filter AnalyzeErrorTests

With PG 13 we get

Resetting database took: 0.06859397888183594s
Resetting database took: 0.08555293083190918s
Resetting database took: 0.0502779483795166s
Resetting database took: 0.045484066009521484s
Resetting database took: 0.05070698261260986s

And with PG 16

Resetting database took: 0.3590719699859619s
Resetting database took: 0.44095301628112793s
Resetting database took: 0.3530939817428589s
Resetting database took: 0.34445297718048096s
Resetting database took: 0.3584989309310913s

i.e. about a factor of ~5-6 slower.

We can't stay on PG 13 forever but we can't accept a x5 regression in test speed, either. I've asked around and it looks like folks use a createdb strategy to create and restore db snapshots with a blank schema instead of truncating tables. That should solves this and might even be faster than the original version 🤞

Also notable: this test class has four tests, yet there are five log statements. For some reason we're running reset one extra time per test class. (That's because we call _resetDb recursively once in order to populate the table names cache.)

[finestructure]

In a first, crude attempt I can get this down to ~0.07s, which is close but not quite a fast as TRUNCATE 🤔

Resetting database took: 0.07318496704101562s
Resetting database took: 0.07433605194091797s
Resetting database took: 0.07159805297851562s
Resetting database took: 0.07246506214141846s

[finestructure]

That was actually not correct - I wasn't comparing like for like. The initial timings included refreshing of various views:

        try await RecentPackage.refresh(on: app.db)
        try await RecentRelease.refresh(on: app.db)
        try await Search.refresh(on: app.db)
        try await Stats.refresh(on: app.db)
        try await WeightedKeyword.refresh(on: app.db)

Once I account for that, I'm back to the same slow time:

Resetting database took: 0.371474027633667s
Resetting database took: 0.37249696254730225s
Resetting database took: 0.37803006172180176s
Resetting database took: 0.3674870729446411s

So it looks like it's the view refreshing that's slow with PG 16.

[finestructure]

The view refreshing is part of it but even without it, there are still big differences:

Local

• PG 13, create db: 52s
• PG 16, create db: 169s
• PG 13, truncate: 112s
• PG 16, truncate: 328s

CI

• PG 13, create db: 16.5m, 18m
• PG 16, create db: 22m, 21.5m
• PG 13, truncate: 17.5m, 18.5m
• PG 16, truncate: 25m, 25.5m

Where create db is the new mechanism to reset the db based on snapshots and truncate is the existing process.

It's clear that create db is a bit faster than truncate but even so it can't compensate for the performance loss switching from 13 to 16.

Also, and I'll re-test this, I believe the actual regression happened from 13 → 14.

I've diffed the db config in the docker images and tried a number of different memory/cache/jit settings and none of them have any noticeable effect.

Further things to try

• create an SQL query based benchmark to see if it's the db itself or PgNIO that's slower *)
• re-confirm that it's 13 → 14 that regresses

*) Gwynne mentioned 14 introduces "pipelining" and that might cause some interference with PostgresNIO. Will verify and check if Fabian if I see a regression due to PgNIO.

[finestructure]

Just one more note regarding view refreshing: The reason we did a blanket refresh in the truncate reset variant was that after wiping the tables, views still held on to outdated data. So in that sense it was required. However, all tests pass even when we don't do that and it's because all tests that deal with views also reset the views explicitly. That's not necessarily a safe assumption though, i.e. it means that these tests reply on implementation details and could easily fall in disrepair.

The create db approach is safer here - there is no need to refresh the views because they're pristine as part of the original snapshot.

So technically, the "best" comparison in terms of correctness is "PG 16, create db" vs "PG 13, truncate" - which unfortunately is still a significant regression going to 16.

[finestructure]

In terms of moving forward, I think we'll want to go ahead and move our CI to use PG 16 (i.e. merge #3278 with a slight tweak, see below). The regression is ~18m → 22m. That's not great but we should be testing the same db version as prod and that's the price to pay.

For local test running, we could stay on 13 for a moment longer until we figure out (and hopefully fix) the underlying issue.

[finestructure]

I've created a little SQL script with various queries that runs in ~1.7s on my machine against a docker container with a db snapshot from Sep 1.

perf-test.sql.zip

I've got PG 13 running on port 7432 and PG 16 running on port 6432:

❯ docker ps
CONTAINER ID   IMAGE                COMMAND                  CREATED             STATUS             PORTS                                       NAMES
c2edb01acd22   postgres:14-alpine   "docker-entrypoint.s…"   49 seconds ago      Up 48 seconds      0.0.0.0:8432->5432/tcp, :::8432->5432/tcp   spi_dev_14
44f1f9c05079   postgres:16-alpine   "docker-entrypoint.s…"   About an hour ago   Up About an hour   0.0.0.0:6432->5432/tcp, :::6432->5432/tcp   spi_dev
46bc3b8b2765   postgres:13-alpine   "docker-entrypoint.s…"   About an hour ago   Up About an hour   0.0.0.0:7432->5432/tcp, :::7432->5432/tcp   spi_dev_13

Running the script 20 times against each db yields:

Pg 16

❯ for i in (seq 20); env PGPASSWORD=xxx time psql -U spi_dev -d spi_dev --host localhost --port 6432 -f perf-test.sql > /dev/null; end
        1.66 real         0.01 user         0.01 sys
        1.58 real         0.01 user         0.00 sys
        1.64 real         0.01 user         0.00 sys
        1.62 real         0.01 user         0.00 sys
        1.65 real         0.01 user         0.00 sys
        1.68 real         0.01 user         0.00 sys
        1.88 real         0.01 user         0.00 sys
        1.77 real         0.01 user         0.00 sys
        1.71 real         0.01 user         0.01 sys
        1.68 real         0.01 user         0.01 sys
        1.61 real         0.01 user         0.01 sys
        1.61 real         0.01 user         0.01 sys
        1.62 real         0.01 user         0.00 sys
        1.70 real         0.01 user         0.00 sys
        1.69 real         0.01 user         0.00 sys
        1.61 real         0.01 user         0.00 sys
        1.63 real         0.01 user         0.00 sys
        1.61 real         0.01 user         0.00 sys
        1.60 real         0.01 user         0.01 sys
        1.63 real         0.01 user         0.00 sys

average: 1.66s

Pg 13

❯ for i in (seq 20); env PGPASSWORD=xxx time psql -U spi_dev -d spi_dev --host localhost --port 7432 -f perf-test.sql > /dev/null; end
        1.80 real         0.00 user         0.00 sys
        1.76 real         0.00 user         0.00 sys
        1.73 real         0.00 user         0.00 sys
        1.74 real         0.00 user         0.00 sys
        1.76 real         0.00 user         0.00 sys
        1.74 real         0.00 user         0.00 sys
        1.77 real         0.00 user         0.00 sys
        1.83 real         0.01 user         0.01 sys
        1.90 real         0.00 user         0.00 sys
        1.87 real         0.00 user         0.00 sys
        1.85 real         0.01 user         0.01 sys
        1.76 real         0.00 user         0.00 sys
        1.77 real         0.00 user         0.00 sys
        1.81 real         0.00 user         0.00 sys
        1.75 real         0.01 user         0.01 sys
        1.77 real         0.01 user         0.00 sys
        1.78 real         0.01 user         0.01 sys
        1.75 real         0.01 user         0.01 sys
        1.81 real         0.01 user         0.00 sys
        1.86 real         0.01 user         0.00 sys

average: 1.79s

Pg 14

❯ for i in (seq 20); env PGPASSWORD=xxx time psql -U spi_dev -d spi_dev --host localhost --port 8432 -f perf-test.sql > /dev/null; end
        1.67 real         0.01 user         0.01 sys
        1.66 real         0.01 user         0.00 sys
        1.63 real         0.01 user         0.00 sys
        1.62 real         0.01 user         0.00 sys
        1.63 real         0.01 user         0.00 sys
        1.63 real         0.01 user         0.00 sys
        1.61 real         0.01 user         0.00 sys
        1.62 real         0.01 user         0.00 sys
        1.61 real         0.01 user         0.00 sys
        1.64 real         0.01 user         0.00 sys
        1.66 real         0.01 user         0.00 sys
        1.61 real         0.01 user         0.00 sys
        1.61 real         0.01 user         0.00 sys
        1.61 real         0.01 user         0.00 sys
        1.61 real         0.01 user         0.00 sys
        1.65 real         0.01 user         0.00 sys
        1.72 real         0.01 user         0.00 sys
        1.71 real         0.01 user         0.00 sys
        1.70 real         0.01 user         0.00 sys
        1.71 real         0.01 user         0.00 sys

average: 1.65s

Postgres 16 is clearly faster than Postgres 13, as is Postgres 14.

I've run analyze prior to each sequence of perf tests.

[finestructure]

I've re-tested our test runs with PG 14. I'm dropping the "truncate" variant, because we've now moved to "createdb" as the way to reset the dbs and we don't need to carry that variant forward.

So to summarise, running our normal test suite I'm seeing the following run times against different versions of containerised Postgres dbs:

Pg 13: 52s
Pg 14: 162s, 163s
Pg 16: 169s

on a Mac Studio.

There's a clear regression going from Postgres 13 → 14.

This is not the case when running plain SQL against those db versions (with copies of our production data, so it's a real world scenario):

Pg 13: 1.79s
Pg 14: 1.65s
Pg 16: 1.66s

Values are the averages shown above.

[finestructure]

I've created a repo to test pure SQL and PostgresNIO performance similar to what I did above here:

https://github.com/finestructure/pg-perf-regression.git

When I run these tests on my machine I get the following results:

Pure SQL test:

❯ ./run-sql-perf-test.sh 
Testing DB on port 6432
        1.89 real         0.01 user         0.01 sys
        1.76 real         0.00 user         0.00 sys
        1.73 real         0.00 user         0.00 sys
        1.71 real         0.00 user         0.00 sys
        1.73 real         0.00 user         0.00 sys
        1.70 real         0.00 user         0.00 sys
        1.73 real         0.00 user         0.00 sys
        1.72 real         0.00 user         0.00 sys
        1.72 real         0.00 user         0.00 sys
        1.74 real         0.00 user         0.00 sys
Testing DB on port 7432
        1.66 real         0.01 user         0.00 sys
        1.60 real         0.01 user         0.00 sys
        1.59 real         0.01 user         0.00 sys
        1.58 real         0.01 user         0.00 sys
        1.59 real         0.01 user         0.00 sys
        1.58 real         0.01 user         0.00 sys
        1.57 real         0.01 user         0.00 sys
        1.61 real         0.01 user         0.00 sys
        1.61 real         0.01 user         0.00 sys
        1.67 real         0.01 user         0.01 sys
Testing DB on port 8432
        1.72 real         0.01 user         0.01 sys
        1.69 real         0.01 user         0.01 sys
        1.57 real         0.01 user         0.01 sys
        1.53 real         0.01 user         0.01 sys
        1.60 real         0.01 user         0.01 sys
        1.58 real         0.01 user         0.00 sys
        1.63 real         0.01 user         0.01 sys
        1.54 real         0.01 user         0.01 sys
        1.56 real         0.01 user         0.01 sys
        1.55 real         0.01 user         0.01 sys
~/D/pg-perf-regression on main took 50s 

PostgresNIO test:

❯ swift run
... [build output truncated] ...
Build of product 'pg-perf-regression' complete! (22.46s)
Testing DB on port 6432
    2.0167089700698853s
    1.8028069734573364s
    1.7660850286483765s
    1.7685949802398682s
    1.7620760202407837s
    1.7628109455108643s
    1.7799489498138428s
    1.7587820291519165s
    1.7744059562683105s
    1.8245229721069336s
Testing DB on port 7432
    1.7681560516357422s
    1.6751480102539062s
    1.6807630062103271s
    1.691336989402771s
    1.7377430200576782s
    1.6941779851913452s
    1.6852760314941406s
    1.7176259756088257s
    1.7921500205993652s
    1.7093110084533691s
Testing DB on port 8432
    1.7681989669799805s
    1.6809520721435547s
    1.660504937171936s
    1.6557459831237793s
    1.730875015258789s
    1.645946979522705s
    1.6529970169067383s
    1.6614480018615723s
    1.6534169912338257s
    1.6401259899139404s
~/D/pg-perf-regression on main took 1m29s 

The database versions are in ascending order: Pg 13 on port 6432, Pg 14 on port 7432, Pg 16 on port 8432.

It's clear in this test that PostgresNIO is as fast or at least almost as fast as pure psql and certainly doesn't look like the underlying problem I've been trying to diagnose.

To recap: the problem is that our test suite is more than 3 times slower when all I do is change the Postgres version in our test container. We're using the stock image, just as I did in the tests above.

I've attempted to create a similar test scenario in this https://github.com/finestructure/pg-perf-regression.git repository by taking 13 queries to create some sort of SQL work. The idea was that if I run this via psql as a baseline and compare running the same queries via PostgresNIO it would show if there's a regression in PostgresNIO when targeting certain Postgres versions.

The good news is that that is certainly not the case.

That leaves me with (at least) two possible explanations:

• The SQL test load is significantly different from what we do in our tests, or at the very least we do something else that is not captured by my SQL load test.
• There's an issue higher up the stack in Vapor or in our code that behaves dramatically differently depending on what Postgres version is being targeted.

[finestructure]

Next steps

• Create a single test that demonstrates the issue and runs significantly slower going from Pg 13 → 14
• Instrument different parts of it with timing info
• Remove all parts that perform the same to see where we're regressing

[finestructure]

I've created a break down from a single test and it looks like both snapshot creation and restoration are good candidates to dig deeper (>4x slow down). But just looking at test_analyze it's also x3 slower on its own.

https://www.icloud.com/numbers/0a9vt0AKU4mo51cZlUgHn_nhA#Issue_3360_perf_regression

[finestructure]

Interestingly, plugging the slow "create snapshot" function into the performance test project it doesn't show the same slow down:

[finestructure]

The problem is that I'm testing in slightly different ways.

The original figures from within our test suite are generated as follows:

• spin up db with target Pg version
• run the test 10 times via

for _ in {1..10}; do
    swift test --skip-build --disable-automatic-resolution --filter AnalyzerTests.test_analyze | grep "Elapsed:"
done

• the test's set up method I log the run time for createSnapshot
• repeat this with a different target Pg version

In the perf test project the procedure is

• spin up two dbs with Pg version 13 on port 6432 and Pg 16 on port 7432
• run the test 10 times via

    for port in [6432, 7432] {
        print("Testing DB on port \(port)")
        for _ in (1...10) {
            try await createSnapshot(port: port, original: "spi_dev", snapshot: "snapshot")
        }
    }

The crucial difference seems to be that in the first test, each timing of createSnapshot is run on a new db connection. In the perf project, subsequent iterations are run on an existing connection. That difference is actually visible in the plot where the first timings are higher.

Now the crucial test is the first one, because that's what we do (and have to do) in our setup: we're creating the snapshot with a new db connection. (I guess we could keep the connection alive but really this seems like an upstream regression.)

I'll adjust the standalone perf test to reflect this different test scenario.

[finestructure]

This is maddening. There's yet still more to it. When I run the standalone perf tests in an "outer loop" just like our tests:

swift build
exe="$(swift build --show-bin-path)"/pg-perf-regression

echo "Testing on port $PORT"

for _ in {1..10}; do
    $exe "$PORT"
done

I get

❯ ./run-perf-test.sh 6432
Building for debugging...
[1/1] Write swift-version-117DEE11B69C53C9.txt
Build complete! (0.20s)
Testing on port 6432
    0.46435093879699707
    0.2320500612258911
    0.24330389499664307
    0.2519960403442383
    0.24383902549743652
    0.22846710681915283
    0.23856902122497559
    0.24333500862121582
    0.23904001712799072
    0.25825202465057373
~/D/pg-perf-regression on create-schema-tests took 4s 
❯ ./run-perf-test.sh 7432
Building for debugging...
[1/1] Write swift-version-117DEE11B69C53C9.txt
Build complete! (0.21s)
Testing on port 7432
    0.3815929889678955
    0.2749119997024536
    0.2712209224700928
    0.2858840227127075
    0.2709510326385498
    0.27724504470825195
    0.28508102893829346
    0.26385200023651123
    0.2640920877456665
    0.2796880006790161

As for the "inner loop", I see a slowdown for Pg 14 but nowhere near the 3x I see in our tests. There must be something else happening in our tests that interferes with the pure PostgresNIO snapshot creation.

[finestructure]

I've managed to create a reproducer and pushed it to https://github.com/finestructure/pg-perf-regression.git

My measurements are here: https://www.icloud.com/numbers/0945R88oKsGdVM5kY89hT7eMA#Issue_3360_perf_regression

I'll update the PostgresNIO with details and close this issue here so we don't track in two places. The reproducer is pure PostgresNIO, so I think it should be tracked there exclusively.