Re: Query running longer

[veem v <veema0000@xxxxxxxxx>]

On Fri, 2 Feb 2024 at 02:43, Laurenz Albe <laurenz.albe@xxxxxxxxxxx> wrote:

On Fri, 2024-02-02 at 02:27 +0530, veem v wrote:
> We have the below query which is running for ~45 seconds on postgres aurora reader instance.
> I have captured the explain analyze. Want to understand, where exactly the resources are
> getting spent and if we can be able to optimize it further.

Aurora <> PostgreSQL, but here is what I can see:

- The index scan on SCHEMA1."TAB2" has to check 2 million extra
  rows because "work_mem" is too small.  Almost the complete time
  is spent there.

- You may be getting a bad plan, because the statistics on
  SCHEMA1.TAB4 are either out of date or not detailed enough,
  which makes PostgreSQL underestimate the result size.

Thank you so much.

I can read and understand the execution plan in Oracle database easily and can also interpret database parameters too. But new to postgres, are there some good resources to quickly get up to speed to understand the postgres execution path here and also various key parameters(like for e.g. one you mentioned as work_mem)?

As you mentioned below, So wondering how you got to know, if this is the step where majority of the DB resources get spent. And as total time the query ran was ~45 seconds, and out of that how much time it spent in this step, how can i get that? And to fix this one line with regards to TAB2, should we increase "work_mem" here?

- The index scan on SCHEMA1."TAB2" has to check 2 million extra
  rows because "work_mem" is too small.  Almost the complete time
  is spent there.

 ->  Parallel Bitmap Heap Scan on SCHEMA1.""TAB2"" TAB2  (cost=84860.50..13040301.00 rows=1175611 width=80) (actual time=713.054..26942.082 rows=956249 loops=5)"
"                     Output: TAB2.TAB2_time, TAB2.PRI, TAB2.AID"
 Recheck Cond: (TAB2.MID = 'XXXXX'::numeric)
 Rows Removed by Index Recheck: 2137395
 Filter: ((TAB2.TAB2_time >= '2024-01-01 00:00:00+00'::timestamp with time zone) AND (TAB2.TAB2_time <= '2024-01-31 00:00:00+00'::timestamp with time zone))
 Heap Blocks: exact=5300 lossy=782577
 Buffers: shared hit=1651569 read=2245157
 I/O Timings: shared/local read=29063.286  

Another point you mentioned as below , for this , should we run vacuum analyze on the table TAB4?

- You may be getting a bad plan, because the statistics on
  SCHEMA1.TAB4 are either out of date or not detailed enough,
  which makes PostgreSQL underestimate the result size.
  

Output: TAB4.PRI
 Buckets: 262144 (originally 2048)  Batches: 1 (originally 1)  Memory Usage: 13936kB
 Buffers: shared hit=134917
 Worker 0:  actual time=214.981..214.982 rows=27779 loops=1
Buffers: shared hit=27133
 Worker 1:  actual time=215.455..215.456 rows=27805 loops=1
Buffers: shared hit=27159
 Worker 2:  actual time=215.774..215.774 rows=27330 loops=1
Buffers: shared hit=26706
 Worker 3:  actual time=215.776..215.777 rows=26880 loops=1
Buffers: shared hit=26245
 ->  Parallel Bitmap Heap Scan on SCHEMA1.TAB4 TAB4  (cost=26.39..7042.63 rows=1049 width=37) (actual time=23.650..201.606 rows=27613 loops=5)
Output: TAB4.PRI
Recheck Cond: ((TAB4.TAB4_code)::text = 'XX'::text)
Rows Removed by Index Recheck: 616610
Heap Blocks: exact=11978 lossy=15624
Buffers: shared hit=134917
Worker 0:  actual time=20.627..199.852 rows=27779 loops=1
 Buffers: shared hit=27133
Worker 1:  actual time=21.065..199.786 rows=27805 loops=1
 Buffers: shared hit=27159
Worker 2:  actual time=21.445..198.582 rows=27330 loops=1
 Buffers: shared hit=26706
Worker 3:  actual time=21.470..195.915 rows=26880 loops=1
 Buffers: shared hit=26245
->  Bitmap Index Scan on TAB4_idx1  (cost=0.00..25.95 rows=1784 width=0) (actual time=23.938..23.938 rows=138067 loops=1)
 Index Cond: ((TAB4.TAB4_code)::text = 'XX'::text)
 Buffers: shared hit=72