Thread: Re: Help with query optimizer

Re: Help with query optimizer

From

David Mullineux

Date:

01 October 2024, 11:36:12

Hi,
Its usually helpful to give some details on what 'slow' means and then define what 'fast enough ' means. Just so we know when to stop optimizing.
You should also help by giving the DDL of those.tables and any indexes they have etc..
The plan shows me that there are expensive seq scans on 2 tables : conversations and tasks.

So it would be good to get the pg_stats items for the columns used on those filters on those tables.

I would then look at what indexes you have on those tables to find out if some are not being used and why.( lots of reasons why ).

thanks

On Tue, 1 Oct 2024, 08:53 Siraj G, <tosiraj.g@gmail.com> wrote:

Hello Experts!

Can you please help with the attached query as it is taking time to execute. The execution plan for the same is below:
Thank you!

Nested Loop Left Join (cost=8176.99..168603.11 rows=1 width=294) (actual time=3301.886..3303.715 rows=0 loops=1)
Join Filter: (conversation.id = "jobReminders"."conversationId")
Buffers: shared hit=743696 read=78069 dirtied=16 written=10
I/O Timings: shared read=7224.068 write=0.287
-> Gather (cost=8176.99..168472.90 rows=1 width=246) (actual time=3301.885..3303.711 rows=0 loops=1)
Workers Planned: 2
Workers Launched: 2
Buffers: shared hit=743696 read=78069 dirtied=16 written=10
I/O Timings: shared read=7224.068 write=0.287
-> Nested Loop (cost=7176.99..167472.80 rows=1 width=246) (actual time=3286.866..3286.874 rows=0 loops=3)
Buffers: shared hit=743696 read=78069 dirtied=16 written=10
I/O Timings: shared read=7224.068 write=0.287
-> Nested Loop (cost=7176.56..61685.83 rows=59320 width=174) (actual time=68.447..1978.593 rows=57917 loops=3)
Buffers: shared hit=284214 read=56135 dirtied=11 written=9
I/O Timings: shared read=4546.889 write=0.242
-> Hash Join (cost=7176.13..20450.20 rows=15571 width=142) (actual time=68.196..211.016 rows=17903 loops=3)
Hash Cond: (conversation."mailBoxId" = "mailBox".id)
Buffers: shared hit=7428 read=11254 dirtied=9 written=3
I/O Timings: shared read=85.214 write=0.085
-> Parallel Hash Join (cost=6944.87..20143.53 rows=26942 width=118) (actual time=67.736..197.476 rows=21937 loops=3)
Hash Cond: (conversation."taskId" = task.id)
Buffers: shared hit=6678 read=11254 dirtied=9 written=3
I/O Timings: shared read=85.214 write=0.085
-> Parallel Seq Scan on conversations conversation (cost=0.00..13029.34 rows=64502 width=102) (actual time=0.017..79.191 rows=51677 loops=3)
Filter: ((NOT "isCompose") AND ("parentConversationId" IS NULL) AND (id <> '559702f9-55a8-47c7-9b5c-93b29baabf3d'::uuid))
Rows Removed by Filter: 622
Buffers: shared hit=3605 read=8608 dirtied=5 written=3
I/O Timings: shared read=57.862 write=0.085
-> Parallel Hash (cost=6583.67..6583.67 rows=28896 width=16) (actual time=67.046..67.047 rows=22266 loops=3)
Buckets: 131072 Batches: 1 Memory Usage: 4224kB
Buffers: shared hit=3073 read=2646 dirtied=4
I/O Timings: shared read=27.352
-> Parallel Seq Scan on tasks task (cost=0.00..6583.67 rows=28896 width=16) (actual time=0.015..48.469 rows=22266 loops=3)
Filter: (("deletedAt" IS NULL) AND (type = 'MESSAGE'::enum_tasks_type))
Rows Removed by Filter: 32166
Buffers: shared hit=3073 read=2646 dirtied=4
I/O Timings: shared read=27.352
-> Hash (cost=230.80..230.80 rows=37 width=24) (actual time=0.382..0.383 rows=37 loops=3)
Buckets: 1024 Batches: 1 Memory Usage: 11kB
Buffers: shared hit=690
-> Seq Scan on "mailBoxes" "mailBox" (cost=0.00..230.80 rows=37 width=24) (actual time=0.021..0.367 rows=37 loops=3)
Filter: (status = ANY ('{ACTIVE,SYNCING}'::"enum_mailBoxes_status"[]))
Rows Removed by Filter: 27
Buffers: shared hit=690
-> Index Scan using idx_message_fk_conversation_id on messages (cost=0.42..2.53 rows=12 width=48) (actual time=0.035..0.096 rows=3 loops=53708)
Index Cond: ("conversationId" = conversation.id)
Buffers: shared hit=276786 read=44881 dirtied=2 written=6
I/O Timings: shared read=4461.675 write=0.156
-> Index Scan using "mailMessages_pkey" on "mailMessages" "messages->mailMessage" (cost=0.43..1.78 rows=1 width=88) (actual time=0.022..0.022 rows=0 loops=173750)
Index Cond: (id = messages."mailMessageId")
Filter: (("mailId")::text = '<CAMWt+ZZk_vSuuRU7Wzw76wh4JQLd2i3ZKh7h2+ES4jsjMHsYJQ@mail.gmail.com>'::text)
Rows Removed by Filter: 1
Buffers: shared hit=459482 read=21934 dirtied=5 written=1
I/O Timings: shared read=2677.179 write=0.045
-> Seq Scan on "jobReminders" (cost=0.00..129.90 rows=25 width=48) (never executed)
Filter: (status = 'PENDING'::"enum_jobReminders_status")
Planning:
Buffers: shared hit=105 read=1
I/O Timings: shared read=0.010
Planning Time: 2.250 ms
Execution Time: 3303.810 ms
(61 rows)

Re: Help with query optimizer

From

Laurenz Albe

Date:

01 October 2024, 13:39:02

On Tue, 2024-10-01 at 09:36 +0100, David Mullineux wrote:
> > On Tue, 1 Oct 2024, 08:53 Siraj G, <tosiraj.g@gmail.com> wrote:
> > Can you please help with the attached query as it is taking time to
> > execute. The execution plan for the same is below:
> >
> > [EXPLAIN (ANALYZE, BUFFERS) output]
>
> Its usually helpful to give some details on what 'slow' means and then define what
> 'fast enough ' means. Just so we know when to stop optimizing.
> You should also help by giving the DDL of those.tables and any indexes they have etc..

Table definitions and the actual query text would be most helpful, yes.

The PostgreSQL version is essential too.

> The plan shows me that there are expensive seq scans on 2 tables : conversations and tasks.

Those sequential scans are quite cheap; there is nothing to optimize.
The time is spent in two index scans that are repeated a lot, because they
are on the inner side of a nested loop:

- the index scan on "messages" is repeated 53708 times
- the index scan on "mailMessages" is repeated 173750 times


Yours,
Laurenz Albe