BUG #17717: Regression in vacuumdb (15 is slower than 10/11 and possible memory issue)

The following bug has been logged on the website:

Bug reference: 17717
Logged by: Gunnar L
Email address: postgresql(at)taljaren(dot)se
PostgreSQL version: 15.0
Operating system: Ubuntu Linux
Description:

We have observed a significant slowdown in vacuumdb performance between
different versions of postgresql. And possibly also a memory issue.

We run a specific data model, where each customer has its own schema with
its own set of tables. Each database server hosts 16 databases, each
containing around 250 customer schemas. Due to postgres creating a new file
for each database object, we end up with around 5 million files on each
database server. This may or may not be related to the issue we're seeing
(new algorithms with new time complexity?)

We upgraded from postgresql 9.5 to postgresql 13, and noticed a significant
slowdown in how vacuumdb performs. Before, we could run a vacuumdb -a -z
each night, taking around 2 hours to complete. After the upgrade, we see a
constant 100% CPU utilization during the vacuumdb process (almost no I/O
activity), and vacuumdb cannot complete within a reasonable time. We're able
to vacuum about 3-4 databases each night.

We are able to recreate this issue, using a simple bash script to generate a
similar setup.

From local testing, here are our findings:

Concerning speed:
* Version 9.5, 10, 11 are fast (9.5 slower than 10 and 11)
* Version 12, 13, 14 are very, very slow
* Version 15 is faster (a lot faster than 12,13,14) but not nearly as fast
as 10 or 11.

Concerning memory usage:
* Version 15 is using a lot more shared memory OR it might not be releasing
it properly after vacuuming a db.

These are the timings for vacuuming the 16 dbs.

Version Seconds Completed
------------------------------
9.5 412 16/16
10 178 16/16
11 166 16/16
12 8319 1/16 or 2/16 (manually aborted)
13 18853 3/16 or 4/16 (manually aborted)
14 16857 3/16 or 4/16 (manually aborted)
15 617 1/16 (crashed!)
15 4158 6/16 (crashed! --shm-size=256mb)
15 9500 16/16 (--shm-size=4096mb)

The timing of the only successful run for postgres 15 is somewhat flaky,
since the machine was suspended for about 1-1.5 hours so 9500 is only an
estimate, but the first run (1 db completed in 10 minutes) gives that it is
faster than 12-14 but slower than 10 and 11 (3 minutes to complete
everything)

The following describes our setup
This is the script (called setup.sh) we’re using to populate the databases
(we give a port number as parameter)

##### start of setup.sh
export PGPASSWORD=mysecretpassword
PORT=$1

echo ""> tables_$PORT.sql
for schema in `seq -w 1 250`; do
echo "create schema schema$schema;" >> tables_$PORT.sql
for table in `seq -w 1 500`; do
echo "create table schema$schema.table$table (id int);" >>
tables_$PORT.sql
done
done

echo "Setting up db: 01"
createdb -h localhost -U postgres -p $PORT db01
psql -q -h localhost -U postgres -p $PORT db01 -f tables_$PORT.sql

# This seems to be the fastest way to create the databases
for db in `seq -w 2 16`; do
echo "Setting up db: $db"
createdb -h localhost -U postgres -p $PORT --template db01 db$db
done
####### end of setup.sh

To execute a test for a particular postgres version (in this example PG
9.5), we run the following. It will setup PG 9.5 on port 15432.

docker run --rm --name pg95 -e POSTGRES_PASSWORD=mysecretpassword -p
15432:5432 -d postgres:9.5
./setup.sh 15432
date; time docker exec -it pg95 bash -c "vacuumdb -a -z -U postgres"; date

(The date commands are added to keep track of when tasks were started).

Here are complete set of commands and output and comments
(We use different ports for different versions of PG)

date; time docker exec -it pg95 bash -c "vacuumdb -a -z -U postgres"; date
(The date commands since it takes some time to run)

time docker exec -it pg95 bash -c "vacuumdb -a -z -U postgres"
vacuumdb: vacuuming database "db01"
…<snip>...
vacuumdb: vacuuming database "db16"
vacuumdb: vacuuming database "postgres"
vacuumdb: vacuuming database "template1"

real 6m52,070s
user 0m0,048s
sys 0m0,029s

time docker exec -it pg10 bash -c "vacuumdb -a -z -U postgres"
vacuumdb: vacuuming database "db01"
…<snip>...
vacuumdb: vacuuming database "db16"
vacuumdb: vacuuming database "postgres"
vacuumdb: vacuuming database "template1"

real 2m58,354s
user 0m0,043s
sys 0m0,013s

time docker exec -it pg11 bash -c "vacuumdb -a -z -U postgres"
vacuumdb: vacuuming database "db01"
…<snip>...
vacuumdb: vacuuming database "db16"
vacuumdb: vacuuming database "postgres"
vacuumdb: vacuuming database "template1"

real 2m46,181s
user 0m0,047s
sys 0m0,012s

date; time docker exec -it pg12 bash -c "vacuumdb -a -z -U postgres"; date
lör 10 dec 2022 18:57:43 CET
vacuumdb: vacuuming database "db01"
vacuumdb: vacuuming database "db02"
^CCancel request sent
vacuumdb: error: vacuuming of table "schema241.table177" in database "db02"
failed: ERROR: canceling statement due to user request

real 138m39,600s
user 0m0,177s
sys 0m0,418s
lör 10 dec 2022 21:16:22 CET

date;time docker exec -it pg13 bash -c "vacuumdb -a -z -U postgres"
lör 10 dec 2022 07:22:32 CET
vacuumdb: vacuuming database "db01"
vacuumdb: vacuuming database "db02"
vacuumdb: vacuuming database "db03"
vacuumdb: vacuuming database "db04"
^CCancel request sent

real 314m13,172s
user 0m0,551s
sys 0m0,663s
lör 10 dec 2022 12:37:03 CET

date;time docker exec -it pg14 bash -c "vacuumdb -a -z -U postgres"; date
lör 10 dec 2022 14:15:37 CET
vacuumdb: vacuuming database "db01"
vacuumdb: vacuuming database "db02"
vacuumdb: vacuuming database "db03"
vacuumdb: vacuuming database "db04"
^CCancel request sent

real 280m57,172s
user 0m0,586s
sys 0m0,559s
lör 10 dec 2022 18:56:34 CET

date;time docker exec -it pg15 bash -c "vacuumdb -a -z -U postgres"; date
lör 10 dec 2022 12:50:25 CET
vacuumdb: vacuuming database "db01"
vacuumdb: vacuuming database "db02"
vacuumdb: error: processing of database "db02" failed: ERROR: could not
resize shared memory segment "/PostgreSQL.2952321776" to 27894720 bytes: No
space left on device

real 10m17,913s
user 0m0,030s
sys 0m0,049s
lör 10 dec 2022 13:00:43 CET

# it was faster, but we need to extend shared memory to make it work

docker run --rm --name pg15 --shm-size=256mb -e
POSTGRES_PASSWORD=mysecretpassword -p 55555:5432 -d postgres:15

date;time docker exec -it pg15 bash -c "vacuumdb -a -z -U postgres"; date
mån 12 dec 2022 08:56:17 CET
vacuumdb: vacuuming database "db01"
…<snip>...
vacuumdb: vacuuming database "db07"
vacuumdb: error: processing of database "db07" failed: ERROR: could not
resize shared memory segment "/PostgreSQL.1003084622" to 27894720 bytes: No
space left on device

real 69m18,345s
user 0m0,217s
sys 0m0,086s
mån 12 dec 2022 10:05:36 CET

docker run --rm --name pg15 --shm-size=4096mb -e
POSTGRES_PASSWORD=mysecretpassword -p 55555:5432 -d postgres:15

date;time docker exec -it pg15 bash -c "vacuumdb -a -z -U postgres"; date
mån 12 dec 2022 11:16:11 CET
vacuumdb: vacuuming database "db01"
…<snip>...
vacuumdb: vacuuming database "db16"
vacuumdb: vacuuming database "postgres"
vacuumdb: vacuuming database "template1"

real 232m46,168s
user 0m0,227s
sys 0m0,467s
mån 12 dec 2022 15:08:57 CET

Here is the hardware that was used
AMD Ryzen 7 PRO 5850U with Radeon Graphics
8 Cores, 16 threads

$ free
total used free shared buff/cache
available
Mem: 28562376 5549716 752624 1088488 22260036
21499752
Swap: 999420 325792 673628

Disk: NVMe device, Samsung SSD 980 1TB