Introduction
Last mouth, I noticed something puzzling at work. This is a story of weird DB performance and PostgreSQL internal mechanism. Let me give you the context.
The repository where all the migrations are stored, has a CI/CD setup. When a change is made and the MR/PR merged, a pipeline is triggered. The pipeline, among other things, applies the change to several environments. Among which: acceptance and production. In that order, clearly. Flyway is used to manage the DB migrations and a callback is registered to make sure permissions are all right. Flyway allows that in a simple way.
Now, what caught my eye was the the pipeline job that applies the changes was taking 6 seconds on production and 25 on acceptance. Every single time. Bizarre.
Investigation
The first thing was to look at the log, but the output of Flyway is buffered, so the timestamp present there were of no use. I could not pinpoint from the logs alone if there was one instruction to take longer. Thus, believing that the migration per se was fine and there was no problem there, I went after the afterMigrate code. I could test the SQL statements on the incriminated slow DB instance. Indeed, running the afterMigrate function was taking 25 minutes. Puzzling.
This thing was bothering me as it caused several discomfort despite not being a blocker per se.
- Longer waiting time for developers to push their changes
- Higher changes of something going wrong if we have to wait longer
- Waste of resources to run the pipeline
And why 25? Always. So I had a quick look at the historical data for the repository's pipelines. When I did that, I also found out that this got worse in time. 3 months ago it took around 12 minutes.
Analysis
In a methodical way, I started to rule out possible causes.
hardware
The starting point was the hardware. But both acceptance and production have the same hardware (EC2 instance).
Queries
AWS provides a more than decent overview of what is running on your RDS instance. On the performance insight on AWS you can check the current state of things.
I could see that the vacuum command on pgtoast tables was blocked because of the lock of the afterMigrate. To be precise, it gets continuously blocked because of the locks the afterMigrate takes.
So, what afterMigrate does, really? It simply granting permission. Resetting permissions by revoking them and re-granting them.
Cardinality problem?
As a first thing, I quickly check the amount of data that was being handled. But that was a red herring.
Then, I went checking if the tables were bloated. A dear colleague supported me in this process. Just running vacuum on the tables did nothing. With the knowledge that it went from 12 to 25 minutes in 3 months, it must be due to the amount of data and some tables being bloated.
I read a bit more about how the PostgreSQL stores some data. the dependencies among objects, how vacuum works and something about statistics in general.
That led me to check the n_dead_tup
SELECT relname, n_live_tup, n_dead_tup
FROM pg_stat_all_tables
WHERE schemaname = 'pg_catalog'
AND relname IN (
'pg_namespace',
'pg_depend',
'pg_shdepend',
'pg_auth_members'
)
ORDER BY n_dead_tup DESC;
relname | n_live_tup | n_dead_tup
-----------------+------------+------------
pg_shdepend | 20480 | 2777564
pg_namespace | 29 | 94038
pg_depend | 16827 | 1262
pg_auth_members | 0 | 0
(4 rows)That n_dead_tup looked suspiciously high. I think that the solution may be to vacuum those tables. But, if you remember, I have been seeing vacuuming being run continuously without having any effect. Actually, it has been burning CPU cycles on acceptance.
For the sake of it, I wanted to check the vacuum output. Something like the following snippet.
SELECT format('VACUUM VERBOSE ANALYZE %I.%I;', table_schema, table_name)
FROM information_schema.tables
WHERE table_schema IN ('pg_catalog')
AND table_type = 'BASE TABLE' \gexec- Attempt number 1
- Running vacuum verbose analyzie on tiqets and any other ns beside
pg_catalogandinformation_schema. No effect.
- Running vacuum verbose analyzie on tiqets and any other ns beside
- Attempt number 2
- Running vacuum verbose on
pg_catalog. No effect.
- Running vacuum verbose on
- Attempt number 3
- Looking at the aws console, for the top waits showed that
Vacuumis timing out. TimoutVacuumDelay. More information here
- Looking at the aws console, for the top waits showed that
It looks like the autovacuum is pausing itself because it is reaching the vacuum_cost_limit or autovacuum_vacuum_cost_limit. The second one in our case. In itself, this is a sign of tables being bloated.
Why that happens is a sort of wild guess. I found a collection of possible causes is gathered in https://pganalyze.com/docs/checks/vacuum/xmin_horizon
The most likely in our case is the logical slot with a very old xmin. For the sake of completeness, the xmin is an a mechanism used by PostgreSQL to guarantee transaction sanity.
Each transaction has a unique ID, so that changes due to a transaction (possibly dead tuples) may be kept if there is anything that needs a xmin of a certain value (or greater. That’s why the name contains the word min).
So, my idea is that there is a process somewhere that is holding an old xmin. So I looked into all the possible places and found some replication_slots that wanted an old xmin.
A must read is the PostgreSQL documentation on its concurrency model. Basically, the DB keeps copies of the data for each transaction. Each transaction has an ID too. With quite some complexity, it is possible to guarantee that the level of isolation defined in the SQL language are met.
Taking a step back, I would like to emphasize what a replication slot is. The summary is that the DB keeps some downstream processes up to date with the changes (aka the WAL). So processes can receive updates on what is being changed. People can implements Change Data Capture (CDC).
The tricky part is that even if the slots are inactive, they will still hold vacuuming back from cleaning up dead tuples.
SELECT slot_name,
active,
xmin,
catalog_xmin
FROM pg_replication_slots;
slot_name | active | xmin | catalog_xmin
-----------------------------------------------------------------+--------+------+--------------
7ncmvpcd5ngwrnk6_133766519_ae8a8fc4_4b48_43ff_bad7_7173e85b090d | t | | 291331505
kvrxsmoi2ffctdzk_133766519_8556222b_6918_4a04_8259_c275e7b03c9c | f | | 251591856
tappostgres | f | | 253363994
(3 rows)SELECT
relname,
relfrozenxid,
age(relfrozenxid) AS frozen_xid_age
FROM pg_class
WHERE relname ilike 'pg_%';
relname | relfrozenxid | frozen_xid_age
------------------------------------------------+--------------+----------------
pg_toast_129484727_index | 0 | 2147483647
pg_toast_129484727 | 291156246 | 175417
pg_toast_133959727 | 291155349 | 176314
pg_toast_133959727_index | 0 | 2147483647
pg_toast_133975038 | 291156062 | 175601
pg_toast_133960743 | 291156184 | 175479
pg_toast_133960743_index | 0 | 2147483647
pg_toast_133960862 | 291156061 | 175602
pg_toast_133960862_index | 0 | 2147483647
pg_toast_133975038_index | 0 | 2147483647
pg_statistic | 202323599 | 89008064
pg_type | 202030167 | 89301496
pg_largeobject | 200000556 | 91331107
pg_largeobject_loid_pn_index | 0 | 2147483647
pg_toast_133828622 | 269026333 | 22305330
pg_toast_133828601 | 269026348 | 22305315
pg_toast_133828601_index | 0 | 2147483647
pg_toast_1255 | 251576275 | 39755388
pg_toast_1247 | 251591856 | 39739807You can see how the relfrozenxid for some tables (291156246) is way higher than the catalog_xmin for two inactive slots. Values are 253363994, 251591856.
Now, knowing that those were inactive and belonged to processes that were not anymore present in our ecosystem, I proceeded to remove them.
For instance, tappostgres was a dead process from Meltano.
SELECT slot_name, database, xmin, catalog_xmin, active
FROM pg_replication_slots
ORDER BY age(xmin),https://www.postgresql.org/docs/current/runtime-config-replication.html#GUC-IDLE-REPLICATION-SLOT-TIMEOUT
age(catalog_xmin) DESC;
slot_name | database | xmin | catalog_xmin | active
-----------------------------------------------------------------+-----------------------+------+--------------+--------
kvrxsmoi2ffctdzk_133766519_8556222b_6918_4a04_8259_c275e7b03c9c | eks_tiqets_acceptance | | 251591856 | f
tappostgres | eks_tiqets_acceptance | | 253363994 | f
7ncmvpcd5ngwrnk6_133766519_ae8a8fc4_4b48_43ff_bad7_7173e85b090d | eks_tiqets_acceptance | | 291447094 | t
(3 rows)
eks_tiqets_acceptance=> SELECT pg_drop_replication_slot('tappostgres');
pg_drop_replication_slot
--------------------------
(1 row)
eks_tiqets_acceptance=> SELECT pg_drop_replication_slot('kvrxsmoi2ffctdzk_133766519_8556222b_6918_4a04_8259_c275e7b03c9c');
pg_drop_replication_slot
--------------------------
(1 row)The moment replication slot were gone, vacuum was able to clean up the dead rows and immediately improve bloat-ness of some tables.
Now running the afterMigrate section only took 6 minutes. Clearly, there are still tables in different schemas that needs to be properly vacuumed. But overall, the situation is much better.
Conclusion
Lesson learnt: keep your house tight. Monitor your replication slots. Not all connector remove the replication slot during shutdown or as a clean up when crashing.
Tip: Postgres 18 introduced the option idle_replication_slot_timeout (doc here) that allows to remove a replication slot that has been inactive for longer than the value specified.