Subject: Re: Help with query optimizer

From: David Mullineux <[email-masked]>
Date: Tue, 1 Oct 2024 09:36:12 +0100

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, <[email-masked]> 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 = '<
> [email-masked]
> >'::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)
>

---

From: Laurenz Albe <[email-masked]>
Date: Tue, 01 Oct 2024 12:39:02 +0200

On Tue, 2024-10-01 at 09:36 +0100, David Mullineux wrote:
> > [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