Date: Wed, 19 Jan 2022 13:52:55 +0000 (UTC)
From: Ludwig Isaac Lim <ludz_lim@yahoo.com>
To: "pgsql-performance@postgresql.org" <pgsql-performance@postgresql.org>
Message-ID: <1017307461.1415193.1642600375850@mail.yahoo.com>
Subject: PostgreSQL 12.8 Same Query Same Execution Plan Different Time
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: quoted-printable
References: <1017307461.1415193.1642600375850.ref@mail.yahoo.com>
Content-Length: 8044
Archived-At: 
 <https://www.postgresql.org/message-id/1017307461.1415193.1642600375850%40mail.yahoo.com>
Precedence: bulk

Hello:

I ran 2 same queries on PostgreSQL 12.8 machine running in AWS RDS, the fir=
st time I ran the query

the query plan was:

GroupAggregate=C2=A0=C2=A0(cost=3D455652.07..455664.99 rows=3D340 width=3D1=
6) (actual time=3D124047.119..124048.777 rows=3D294 loops=3D1)
=C2=A0=C2=A0 Group Key: dvh.history_date
=C2=A0=C2=A0 ->=C2=A0=C2=A0Sort=C2=A0=C2=A0(cost=3D455652.07..455655.24 row=
s=3D1269 width=3D8) (actual time=3D124046.989..124047.857 rows=3D7780 loops=
=3D1)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Sort Key: dvh.history_date
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Sort Method: quicksort=C2=
=A0=C2=A0Memory: 557kB
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 ->=C2=A0=C2=A0Nested Loop=
=C2=A0=C2=A0(cost=3D13708.92..455586.66 rows=3D1269 width=3D8) (actual time=
=3D12.228..124039.597 rows=3D7780 loops=3D1)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0 ->=C2=A0=C2=A0HashAggregate=C2=A0=C2=A0(cost=3D13708.35..13746.45=
 rows=3D3810 width=3D4) (actual time=3D12.210..21.629 rows=3D6119 loops=3D1=
)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Group Key: pdv.id
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 ->=C2=A0=C2=A0Nested Loop=C2=
=A0=C2=A0(cost=3D0.84..13698.83 rows=3D3810 width=3D4) (actual time=3D0.038=
..10.650 rows=3D6119 loops=3D1)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=
=C2=A0 ->=C2=A0=C2=A0Index Scan using idx_pc_device_acct_num on pc_devices=
=C2=A0=C2=A0(cost=3D0.42..565.32 rows=3D506 width=3D4) (actual time=3D0.014=
..0.193 rows=3D396 loops=3D1)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Index Cond: ((account_number)::t=
ext =3D 'AB32823833'::text)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=
=C2=A0 ->=C2=A0=C2=A0Index Scan using pdv_uindex on pdv=C2=A0=C2=A0(cost=3D=
0.42..25.73 rows=3D23 width=3D8) (actual time=3D0.007..0.024 rows=3D15 loop=
s=3D396)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Index Cond: (pc_device_id =3D pc=
_devices.id)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0 ->=C2=A0=C2=A0Index Scan using idx_pc_dvh_dvh_id on pdv_history d=
vh=C2=A0=C2=A0(cost=3D0.57..115.96 rows=3D1 width=3D12) (actual time=3D0.34=
2..20.265 rows=3D1 loops=3D6119)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Index Cond: (pdv_id =3D pdv.i=
d)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Filter: (status_changed AND (=
status_id =3D 1))
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Rows Removed by Filter: 187
Planning Time: 1.050 ms
Execution Time: 124048.850 ms


After that, I reran the same query again. The plan is basically the same:


GroupAggregate=C2=A0=C2=A0(cost=3D455652.07..455664.99 rows=3D340 width=3D1=
6) (actual time=3D12180.624..12182.286 rows=3D294 loops=3D1)
=C2=A0=C2=A0 Group Key: dvh.history_date
=C2=A0=C2=A0 ->=C2=A0=C2=A0Sort=C2=A0=C2=A0(cost=3D455652.07..455655.24 row=
s=3D1269 width=3D8) (actual time=3D12180.493..12181.363 rows=3D7780 loops=
=3D1)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Sort Key: dvh.history_date
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Sort Method: quicksort=C2=
=A0=C2=A0Memory: 557kB
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 ->=C2=A0=C2=A0Nested Loop=
=C2=A0=C2=A0(cost=3D13708.92..455586.66 rows=3D1269 width=3D8) (actual time=
=3D1709.341..12177.249 rows=3D7780 loops=3D1)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0 ->=C2=A0=C2=A0HashAggregate=C2=A0=C2=A0(cost=3D13708.35..13746.45=
 rows=3D3810 width=3D4) (actual time=3D1709.319..1713.171 rows=3D6119 loops=
=3D1)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Group Key: pdv.id
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 ->=C2=A0=C2=A0Nested Loop=C2=
=A0=C2=A0(cost=3D0.84..13698.83 rows=3D3810 width=3D4) (actual time=3D0.379=
..1706.606 rows=3D6119 loops=3D1)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=
=C2=A0 ->=C2=A0=C2=A0Index Scan using idx_pc_device_acct_num on pc_devices=
=C2=A0=C2=A0(cost=3D0.42..565.32 rows=3D506 width=3D4) (actual time=3D0.013=
..0.279 rows=3D396 loops=3D1)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Index Cond: ((account_number)::t=
ext =3D 'AB32823833'::text)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=
=C2=A0 ->=C2=A0=C2=A0Index Scan using pdv_uindex on pdv=C2=A0=C2=A0(cost=3D=
0.42..25.73 rows=3D23 width=3D8) (actual time=3D0.289..4.306 rows=3D15 loop=
s=3D396)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Index Cond: (pc_device_id =3D pc=
_devices.id)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0 ->=C2=A0=C2=A0Index Scan using idx_pc_dvh_dvh_id on pdv_history d=
vh=C2=A0=C2=A0(cost=3D0.57..115.96 rows=3D1 width=3D12) (actual time=3D0.06=
3..1.709 rows=3D1 loops=3D6119)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Index Cond: (pdv_id =3D pdv.i=
d)
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Filter: (status_changed AND (=
status_id =3D 1))
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=
=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Rows Removed by Filter: 187
Planning Time: 1.262 ms
Execution Time: 12182.361 ms


But the gap in the execution time between the two same queries is quite hug=
e : 2 minutes vs 12 seconds.

I noticed that different is actually in=C2=A0Nested Loop=C2=A0join. One is =
taking 2 minutes, other is taking 12 seconds. I find this puzzling as I ass=
ume the nested loop should be done in memory.

The disk is=C2=A0gp2 SDD=C2=A0so I'm even more baffled by this. What could =
be the factors that affect the speed of nested loop. I notice for that both=
 loops the=C2=A0rows=C2=A0is 7780 and=C2=A0loops=C2=A0is 1. I don't think t=
hose are big numbers

It was only after the running the 2 queries that I realize I could do=C2=A0=
EXPLAIN (ANALYZE, BUFFERS), but I couldn't reproduce the slowness.

Below are other information that might be relevant:

The database has been vacuum analyzed before running the queries.

Platform : AWS RDS
PG version : 12.8
effective_cache_size : 7.9 GB (7935800kB)
shared_buffers : 3.9 GB (3967896kB)
work_mem : 64MB
random_page_cost : 1.1
Instance type : db.m6g.xlarge (4 vCPUs / 32 GB RAM)
Database is idle. I'm the only one running the query
version : PostgreSQL 12.8 on aarch64-unknown-linux-gnu, compiled by gcc (GC=
C) 7.3.1 20180712 (Red Hat 7.3.1-6), 64-bit

Thanks,
Ludwig