2

I have a question related to an incident that happened on one of our Postgres DBs.

We have a backend service that keeps track of user's activity in some kind of online event. The service uses Postgres 12 as a database, and for this kind of event, there is one table (I'll call it user_event in the rest of the question) where the data is kept. The table had around 3500 transactions per second, mostly updates (out of which almost all were HOT updates - this could be an important bit). enter image description here

Here’s a separate graph for tuples inserted and deleted (deleted ones are 0) since it’s not visible in the pic above: enter image description here

Number of live tuples rose like this: enter image description here

The table usage started from ~11 and was doing fine during the day but around 18h table size went from ~3GB to >80GB in 2 hours. This caused the disk to almost reach its full capacity, so we had to disable the ongoing event and do a vacuum full, which reduced the size of the table from >80GB back to ~3GB.

Here are the size of the table with bloat estimates: enter image description here

* we calculate the bloat displayed on the second graph with this query

Table indexes didn’t grow that much: enter image description here

At that moment (around 20.30 - 21h), we suspected that autovacuum was the problem and that it needs to be more aggressive so we configured naptime of 30s (default is 1 min) and we set autovacuum_vacuum_scale_factor to 0.005 and autovacuum_vacuum_cost_delay to 0 (the last 2 params we’ve only set for the critical table). Before this changes, autovacuum were executing once in 60s before 18h and after 18h once in 2min (due to the growth of the table).

Maybe important info is that during the whole event, the vast majority of checkpoints were requested (not timed) with the frequency of once in 3-4 mins: enter image description here

After that, the issue didn’t repeat, but we are still unable to explain why and how this huge increase in table size happened. After a detailed inspection, autovacuum (and autoanalyze) did work the whole time on the table (we’ve confirmed this in metrics and logs).

To give you more context, we’ve noticed changing the dynamic in the buffers when the table started rapidly increasing (around 18h): enter image description here

Does anyone have an idea what/where to look for in order to explain this? If you need more information, I can provide it.

Additional data: user_event table scheme is this:

# \d user_event;
                          Table "public.user_event"
              Column              |           Type           | Collation | Nullable | Default 
----------------------------------+--------------------------+-----------+----------+---------
 id                               | uuid                     |           | not null | 
 event_id                         | text                     |           | not null | 
 user_id                          | bigint                   |           | not null | 
 server_id                        | integer                  |           | not null | 
 state                            | text                     |           | not null | 
 generator_type                   | text                     |           |          | 
 timestamp_when_claimable         | timestamp with time zone |           | not null | 
 claimeditems                     | jsonb                    |           | not null | 
 timestamp_when_energy_full       | timestamp with time zone |           | not null | 
 overflow_energy                  | integer                  |           | not null | 
 timestamp_when_energy_cost_reset | timestamp with time zone |           | not null | 
 grid                             | jsonb                    |           | not null | 
 refill_count                     | integer                  |           | not null | 
Indexes:
    "user_event_pkey" PRIMARY KEY, btree (id)
    "idx_event_id" btree (event_id)
    "idx_event_id_state" btree (event_id, state)
    "idx_login_id" btree (login_id)
    "idx_login_id_event_id" btree (login_id, event_id)

The Postgres version is 12, with the most important params:

  • shared_buffers: '6GB'
  • maintenance_work_mem: 1GB
  • max_wal_size: 10GB
  • min_wal_size: 1GB
  • checkpoint_timeout: '10min'
  • effective_cache_size: "58GB"
  • log_autovacuum_min_duration: 0
  • autovacuum_vacuum_scale_factor: 0.02
  • autovacuum_analyze_scale_factor: 0.01

The VM’s resources are:

  • 16 CPUs
  • 64 GB RAM
  • SSD disk of 250GB
4
  • I don't know what's unclear about that. You had bloat, and when you tuned autovacuum to run faster, the bloat was gone. So the problem is the number of updates (= dead tuples). You mention HOT. With HOT, there would be little need for VACUUM. Check pg_stat_user_tables if your updates are really HOT. Commented Sep 28, 2023 at 10:54
  • The first picture shows that roughly 99% of the updates were HOT (the graph shows the output of the pg_stat_user_tables). The most puzzling part is why this rapid growth started around 18h? Also, we have a graph (I can add it as well) showing dead tuples number, but we didn't see much increase in dead tuples after 18h - which is imo questioning whether bloat was actually the problem. Commented Sep 28, 2023 at 12:12
  • Ok, if the number of live tuples increases, that's a different affair. Something inserted a lot of data. I cannot tell you why you had lots of data coming in after 18:00, but it cannot be PostgreSQL's doing. Commented Sep 28, 2023 at 14:28
  • I'll put all my money on the pony "Someone had a snapshot held open, and this prevented old tuples (HOT or not) from being cleaned up."
    – jjanes
    Commented Sep 28, 2023 at 14:40

1 Answer 1

2

It is hard to know what your charts are actually showing. n_tup_hot_upd, for example, is a permanently increasing value, it only goes down when the system crashes or the stats gets reset. Yet your chart does not show it this way, so it must be plotting some kind of difference between consecutive snapshots. But in that case, is it also showing all the other lines on the same basis?

The first picture shows that roughly 99% of the updates were HOT

The important thing is not the percentage which were HOT, but the raw number which were not HOT. Your first chart doesn't really accentuate this aspect, but if you squint at it you can kind of see a gap opening up between the two lines right when the problem started occurring.

So the likely answer is that something was holding open a snapshot, which prevented HOT tuples from being pruned. Once the pages are full of unpruned HOT tuples, new versions need to go on new pages, defeating HOT. Updates on tuples put into those new pages would then qualify for HOT again, until those new pages again become full. So HOT never fully shuts off, its effectiveness just decays.

The non-HOT updates will trigger more vacuums to occur, but the vacuums can't actually do anything useful, because the same snapshot which defeats HOT update also defeats vacuuming.

The main things that would hold open a snapshot for a long time would be either a very long-running query, or a transaction in an isolation level greater than READ COMMITTED which has gone idle-in-transaction. These are easy to see in pg_stat_activity while they are occurring (query_start, xact_start, state), but can be hard to determine after the fact.

2
  • Sounds good. There is always this problem with charts like the ones in the question: you don't know what exactly was measured. There is this chart showing that the number of "live tuples" increased. But it does not say what a "live tuple" is supposed to be. With your explanation, it would be the number of dead tuples that increases. Commented Sep 29, 2023 at 2:59
  • wow you are correct, I've just found a couple of long autovacuum transactions (15mins, 30mins, 60mins, 40mins) of some other tables which obviously caused the issue! Thank you! We didn't notice this since we are not displaying autovacuum/autoanalyze transactions in our observability views for transaction length (Grafana) - we'll fix this. And, just to explain why HOT updates chart looks like that is because we are applying rate function on the permanently increasing value (which is actually calculating differences between snapshots in a specific time frame). Commented Sep 29, 2023 at 10:06

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.