Subject: Re: Why is this query touching 4gb of buffers?

From: hubert depesz lubaczewski <[email-masked]>
Date: Fri, 24 Oct 2025 13:19:03 +0200

On Fri, Oct 24, 2025 at 01:01:48PM +0200, hubert depesz lubaczewski wrote:
> Hi,
> I have weird-ish case, that I can't grok, or at least explain in
> hand-wavy way.

A bit more info. Due to how the database is setup we have MANY "copies"
of the same table - same name, same columns, different schema, different
(but similar) data.

So, I tested the problem on another instance of this table. And there
was something really, really weird.

(this query has distinct on two columns, but it doesn't seem to be relevant, and tests whether having it, or not, showed not to generate any reasonable differences).

First run of the query generated:

                                                                                QUERY PLAN
══════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════
 HashAggregate  (cost=181382.51..181745.19 rows=36268 width=16) (actual time=27962.826..27962.826 rows=0 loops=1)
   Group Key: communication_channel_id, root_account_id
   Batches: 1  Memory Usage: 1561kB
   Buffers: shared hit=4624 read=117838 dirtied=486
   ->  Index Scan using index_some_table_pending on some_table  (cost=0.42..178322.57 rows=611988 width=16) (actual time=27962.567..27962.567 rows=0 loops=1)
         Index Cond: (send_at <= '2025-10-23 12:35:48'::timestamp without time zone)
         Buffers: shared hit=4624 read=117838 dirtied=486
 Planning:
   Buffers: shared hit=174
 Planning Time: 1.863 ms
 Execution Time: 27963.620 ms
(11 rows)

Then, immediately I reran it, without reindex, without analyze, without anything. And I got:

                                                                            QUERY PLAN
══════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════
 HashAggregate  (cost=181388.32..181751.00 rows=36268 width=16) (actual time=0.653..0.653 rows=0 loops=1)
   Group Key: communication_channel_id, root_account_id
   Batches: 1  Memory Usage: 1561kB
   Buffers: shared hit=424
   ->  Index Scan using index_some_table_pending on some_table  (cost=0.42..178328.27 rows=612009 width=16) (actual time=0.438..0.438 rows=0 loops=1)
         Index Cond: (send_at <= '2025-10-23 12:35:48'::timestamp without time zone)
         Buffers: shared hit=424
 Planning Time: 0.123 ms
 Execution Time: 1.237 ms
(9 rows)

Time is irrelevant, the point is that we are going down from ~120k buffers
"touched" to 424 buffers. What is going on?

I tested the same case on yet another setup, and ran simlar query
multiple times in a row on secondary, and got:
Buffers: shared hit=113849 read=198047 => Execution Time: 1359.661 ms
Buffers: shared hit=311896 => Execution Time: 246.143 ms

But when I ran the query on primary server tghere was very visiolble
change in buffers accesses:

Buffers: shared hit=114893 read=197776 dirtied=5528 => Execution Time: 75863.479 ms
Buffers: shared hit=775 => Execution Time: 2.360 ms

This didn't change buffers "touches" on secondary, though.

What am I missing?

Best regards,

depesz

---

From: Tom Lane <[email-masked]>
Date: Fri, 24 Oct 2025 08:54:06 -0400

hubert depesz lubaczewski <[email-masked]> writes:
> ...

> "touched" to 424 buffers. What is going on?

The first execution probably had to set hint bits on a whole lot
of recently-deleted rows.

			regards, tom lane

---

From: hubert depesz lubaczewski <[email-masked]>
Date: Fri, 24 Oct 2025 14:56:12 +0200

> of recently-deleted rows.

But why it doesn't happen/help on secondary?

Subsequent runs on secondary still have to "touch" hundreds of thousands
of pages", even if I'll do the run on primary that would reset hint
bits.

So, on primary - reruning the query fixes the "how many pages we touch"
- but on secondary, the number generally doesn't change, at least
withint 15-20 minute window.

Best regards,

depesz

---

From: Tom Lane <[email-masked]>
Date: Fri, 24 Oct 2025 09:01:11 -0400

> But why it doesn't happen/help on secondary?

IIRC, secondaries aren't authorized to update hint bits for
themselves, they have to wait for the primary to do it and then
propagate the new data.  There might also be some question of
what the oldest open transaction is ...

			regards, tom lane

From: Tom Lane <[email-masked]>
To: [email-masked]
cc: PostgreSQL General <[email-masked]>
Subject: Re: Why is this query touching 4gb of buffers?
Comments: In-reply-to hubert depesz lubaczewski <[email-masked]>
	message dated "Fri, 24 Oct 2025 14:56:12 +0200"
Date: Fri, 24 Oct 2025 09:01:11 -0400
Archived-At: <https://www.postgresql.org/message-id/1755687.1761310871%40sss.pgh.pa.us>

> But why it doesn't happen/help on secondary?

IIRC, secondaries aren't authorized to update hint bits for
themselves, they have to wait for the primary to do it and then
propagate the new data.  There might also be some question of
what the oldest open transaction is ...

			regards, tom lane

---

From: hubert depesz lubaczewski <[email-masked]>
Date: Fri, 24 Oct 2025 15:18:44 +0200

> what the oldest open transaction is ...

OK. So tested this idea on yet another "setup".

We have single primary, and two streaming replicas. Before test I ran:
select now() - min(xact_start), now() - pg_last_xact_replay_timestamp() from pg_stat_activity

on both replicas, and got:

    ?column?     │    ?column?
═════════════════╪═════════════════
 00:00:00.003007 │ 00:00:00.003673
(1 row)

and

 ?column? │     ?column?
══════════╪══════════════════
 00:00:00 │ -00:00:00.006129
(1 row)

Then I ran the problematic query on replica 1 (the first one), and got
numbers:

Buffers: shared hit=21107
Execution Time: 18.621 ms

Subsequent runs on the replica showed the same buffers usage, and
similar time.

Then I ran this query twice on primary, and noticed improvement:
Buffers: shared hit=569 read=20927 dirtied=498
Execution Time: 2596.283 ms

and on 2nd run:

Buffers: shared hit=391
Execution Time: 2.015 ms

Awesome. Well, mostly.

Now, I waited ~ 1 minute, checked replication lag, and oldest transactions
replies, where all lags were < 1s, and longest transaction across
primary/secondary1/secondary2 was ~ 4s.

Then I re-ran the query on secondary 1 and got:
Buffers: shared hit=21107
Execution Time: 18.403 ms

Interestingly, on one "setup" running vacuum analyze of the table helped
execution on secondary, but on this one, it doesn't.

Best regards,

depesz