Postgresql Aggregate Query With Sort Very Slow

Question

I have a simple aggregate query that is running very slowly (198s) on a table with ~4.6mil rows, can anyone suggest how to optimise?

SELECT u.user_id,u.firstname,u.surname,u.image_url,p.pool_name, count(s.session_id) as totalSwims,sum(s.total_time_in_seconds) as totalTotalTime
from sessions as s 
left join user_sessions as us on us.session_id = s.session_id 
left join users as u on u.user_id = us.user_id 
left join user_prefs as up on up.user_id = u.user_id 
left join pools as p on p.pool_id = u.local_pool 
where p.client_id = 1 
and s.requires_checking is false 
and s.swim_rating > 10 
and us.user_id is not null 
and s.date_swam > '2023-03-01 01:59:54.962+00' 
and s.date_swam < '2023-03-31 23:13:54.962+00' 
and up.enable_public_leaderboards is true 
and u.disabled is false 
group by u.user_id, p.pool_name, p.client_id
order by sum(s.total_time_in_seconds) desc
limit 20

I already have indexes on sessions.total_time_in_seconds and all other columns referenced in the predicates

Here is the EXPLAIN ANALYSE output

    Limit  (cost=50602.15..50602.20 rows=20 width=136) (actual time=198521.950..198522.027 rows=20 loops=1)
      
.....original plan truncated to make space for updated below.....
                                                                  ->  Seq Scan on public.pools p  (cost=0.00..235.00 rows=62 width=33) (actual time=0.018..0.794 rows=61 loops=3)
                                                                        Output: p.pool_name, p.client_id, p.pool_id
                                                                        Filter: (p.client_id = 1)
                                                                        Rows Removed by Filter: 5674
                                                                        Buffers: shared hit=486
                                                                        Worker 0:  actual time=0.018..0.651 rows=61 loops=1
                                                                          Buffers: shared hit=162
                                                                        Worker 1:  actual time=0.019..0.790 rows=61 loops=1
                                                                          Buffers: shared hit=162
                                                      ->  Index Scan using user_prefs_pkey on public.user_prefs up  (cost=0.42..3.77 rows=1 width=4) (actual time=0.079..0.079 rows=0 loops=61372)
                                                            Output: up.user_id
                                                            Index Cond: (up.user_id = u.user_id)
                                                            Filter: (up.enable_public_leaderboards IS TRUE)
                                                            Rows Removed by Filter: 1
                                                            Buffers: shared hit=239339 read=6309 dirtied=59
                                                            I/O Timings: read=4577.017
                                                            Worker 0:  actual time=0.071..0.071 rows=0 loops=20288
                                                              Buffers: shared hit=79332 read=1879 dirtied=18
                                                              I/O Timings: read=1354.770
                                                            Worker 1:  actual time=0.081..0.081 rows=0 loops=20803
                                                              Buffers: shared hit=81068 read=2195 dirtied=18
                                                              I/O Timings: read=1605.396
                                                ->  Index Only Scan using user_sessions_pkey on public.user_sessions us  (cost=0.43..140.52 rows=154 width=8) (actual time=0.619..1.525 rows=73 loops=11592)
                                                      Output: us.user_id, us.session_id
                                                      Index Cond: ((us.user_id = u.user_id) AND (us.user_id IS NOT NULL))
                                                      Heap Fetches: 488381
                                                      Buffers: shared hit=498091 read=18665
                                                      I/O Timings: read=16850.427
                                                      Worker 0:  actual time=0.634..1.555 rows=74 loops=3830
                                                        Buffers: shared hit=167709 read=6288
                                                        I/O Timings: read=5689.264
                                                      Worker 1:  actual time=0.624..1.549 rows=73 loops=3790
                                                        Buffers: shared hit=164737 read=6208
                                                        I/O Timings: read=5598.264
                                          ->  Index Scan using sessions_pkey on public.sessions s  (cost=0.43..4.00 rows=1 width=10) (actual time=0.676..0.676 rows=0 loops=845589)
                                                Output: s.session_id, s.total_time_in_seconds
                                                Index Cond: (s.session_id = us.session_id)
                                                Filter: ((s.requires_checking IS FALSE) AND (s.swim_rating > 10) AND (s.date_swam > '2023-03-01 01:59:54.962+00'::timestamp with time zone) AND (s.date_swam < '2023-03-31 23:13:54.962+00'::timestamp with time zone))
                                                Rows Removed by Filter: 1
                                                Buffers: shared hit=2781702 read=603474
                                                I/O Timings: read=566006.666
                                                Worker 0:  actual time=0.672..0.672 rows=0 loops=283876
                                                  Buffers: shared hit=934791 read=201659
                                                  I/O Timings: read=188758.695
                                                Worker 1:  actual time=0.694..0.694 rows=0 loops=274793
                                                  Buffers: shared hit=899420 read=200690
                                                  I/O Timings: read=188736.806
    Planning:
      Buffers: shared hit=111
    Planning Time: 2.271 ms
    Execution Time: 198522.110 ms

-------------UPDATE-------------

As per suggestion I added a partial index on date_swam where swim_rating > 10. I then dropped the session_id primary key index to force the planner to use the new index, it gives the following plan (updated a second time!)....

Limit  (cost=107902.84..107902.89 rows=20 width=140) (actual 

time=13760.459..13802.105 rows=20 loops=1)
  Output: u.user_id, u.firstname, u.surname, u.image_url, p.pool_name, (count(s.session_id)), (sum(s.total_time_in_seconds)), p.client_id, p.pool_id
  Buffers: shared hit=771807 read=27894 dirtied=52, temp read=23232 written=23668
  I/O Timings: read=38115.334
  ->  Sort  (cost=107902.84..107902.94 rows=43 width=140) (actual time=13760.458..13802.101 rows=20 loops=1)
        Output: u.user_id, u.firstname, u.surname, u.image_url, p.pool_name, (count(s.session_id)), (sum(s.total_time_in_seconds)), p.client_id, p.pool_id
        Sort Key: (sum(s.total_time_in_seconds)) DESC
        Sort Method: top-N heapsort  Memory: 33kB
        Buffers: shared hit=771807 read=27894 dirtied=52, temp read=23232 written=23668
        I/O Timings: read=38115.334
        ->  Finalize GroupAggregate  (cost=107896.10..107901.69 rows=43 width=140) (actual time=13748.876..13801.273 rows=1476 loops=1)
              Output: u.user_id, u.firstname, u.surname, u.image_url, p.pool_name, count(s.session_id), sum(s.total_time_in_seconds), p.client_id, p.pool_id
              Group Key: u.user_id, p.pool_id
              Buffers: shared hit=771807 read=27894 dirtied=52, temp read=23232 written=23668
              I/O Timings: read=38115.334
              ->  Gather Merge  (cost=107896.10..107900.71 rows=36 width=140) (actual time=13748.858..13797.814 rows=3340 loops=1)
                    Output: u.user_id, p.pool_id, u.firstname, u.surname, u.image_url, p.pool_name, (PARTIAL count(s.session_id)), (PARTIAL sum(s.total_time_in_seconds)), p.client_id
                    Workers Planned: 2
                    Workers Launched: 2
                    Buffers: shared hit=771807 read=27894 dirtied=52, temp read=23232 written=23668
                    I/O Timings: read=38115.334
                    ->  Partial GroupAggregate  (cost=106896.08..106896.53 rows=18 width=140) (actual time=13743.988..13746.974 rows=1113 loops=3)
                          Output: u.user_id, p.pool_id, u.firstname, u.surname, u.image_url, p.pool_name, PARTIAL count(s.session_id), PARTIAL sum(s.total_time_in_seconds), p.client_id
                          Group Key: u.user_id, p.pool_id
                          Buffers: shared hit=771807 read=27894 dirtied=52, temp read=23232 written=23668
                          I/O Timings: read=38115.334
                          Worker 0:  actual time=13741.803..13744.770 rows=1123 loops=1
                            Buffers: shared hit=262454 read=9464 dirtied=14, temp read=7403 written=7316
                            I/O Timings: read=12590.170
                          Worker 1:  actual time=13742.976..13745.801 rows=1035 loops=1
                            Buffers: shared hit=258266 read=9090 dirtied=26, temp read=7763 written=8300
                            I/O Timings: read=12656.606
                          ->  Sort  (cost=106896.08..106896.12 rows=18 width=110) (actual time=13743.971..13744.390 rows=3256 loops=3)
                                Output: u.user_id, p.pool_id, u.firstname, u.surname, u.image_url, p.pool_name, s.session_id, s.total_time_in_seconds, p.client_id
                                Sort Key: u.user_id, p.pool_id
                                Sort Method: quicksort  Memory: 811kB
                                Buffers: shared hit=771807 read=27894 dirtied=52, temp read=23232 written=23668
                                I/O Timings: read=38115.334
                                Worker 0:  actual time=13741.780..13742.171 rows=3221 loops=1
                                  Sort Method: quicksort  Memory: 701kB
                                  Buffers: shared hit=262454 read=9464 dirtied=14, temp read=7403 written=7316
                                  I/O Timings: read=12590.170
                                Worker 1:  actual time=13742.958..13743.323 rows=2736 loops=1
                                  Sort Method: quicksort  Memory: 608kB
                                  Buffers: shared hit=258266 read=9090 dirtied=26, temp read=7763 written=8300
                                  I/O Timings: read=12656.606
                                ->  Parallel Hash Join  (cost=34085.80..106895.70 rows=18 width=110) (actual time=13647.907..13741.713 rows=3256 loops=3)
                                      Output: u.user_id, p.pool_id, u.firstname, u.surname, u.image_url, p.pool_name, s.session_id, s.total_time_in_seconds, p.client_id
                                      Hash Cond: (s.session_id = us.session_id)
                                      Buffers: shared hit=771793 read=27894 dirtied=52, temp read=23232 written=23668
                                      I/O Timings: read=38115.334
                                      Worker 0:  actual time=13655.793..13739.514 rows=3221 loops=1
                                        Buffers: shared hit=262447 read=9464 dirtied=14, temp read=7403 written=7316
                                        I/O Timings: read=12590.170
                                      Worker 1:  actual time=13644.134..13741.201 rows=2736 loops=1
                                        Buffers: shared hit=258259 read=9090 dirtied=26, temp read=7763 written=8300
                                        I/O Timings: read=12656.606
                                      ->  Parallel Bitmap Heap Scan on public.sessions s  (cost=447.58..73224.60 rows=8746 width=10) (actual time=7.704..24.683 rows=15126 loops=3)
                                            Output: s.session_id, s.total_time_in_seconds
                                            Recheck Cond: ((s.date_swam > '2023-03-01 01:59:54.962+00'::timestamp with time zone) AND (s.date_swam < '2023-03-31 23:13:54.962+00'::timestamp with time zone) AND (s.requires_checking IS FALSE) AND (s.swim_rating > 10))
                                            Heap Blocks: exact=7524
                                            Buffers: shared hit=19743
                                            Worker 0:  actual time=6.706..17.200 rows=7148 loops=1
                                              Buffers: shared hit=3877
                                            Worker 1:  actual time=8.199..27.980 rows=20303 loops=1
                                              Buffers: shared hit=8214
                                            ->  Bitmap Index Scan on sessions_date_swam_idx  (cost=0.00..442.33 rows=20990 width=0) (actual time=4.946..4.946 rows=47051 loops=1)
                                                  Index Cond: ((s.date_swam > '2023-03-01 01:59:54.962+00'::timestamp with time zone) AND (s.date_swam < '2023-03-31 23:13:54.962+00'::timestamp with time zone))
                                                  Buffers: shared hit=131
                                                  Worker 1:  actual time=4.946..4.946 rows=47051 loops=1
                                                    Buffers: shared hit=131
                                      ->  Parallel Hash  (cost=33585.40..33585.40 rows=4226 width=104) (actual time=13599.941..13599.945 rows=283349 loops=3)
                                            Output: us.session_id, u.user_id, u.firstname, u.surname, u.image_url, p.pool_name, p.client_id, p.pool_id
                                            Buckets: 32768 (originally 16384)  Batches: 32 (originally 1)  Memory Usage: 4032kB
                                            Buffers: shared hit=752034 read=27894 dirtied=52, temp read=10015 written=23284
                                            I/O Timings: read=38115.334
                                            Worker 0:  actual time=13599.432..13599.437 rows=288936 loops=1
                                              Buffers: shared hit=258562 read=9464 dirtied=14, temp read=2720 written=7188
                                              I/O Timings: read=12590.170
                                            Worker 1:  actual time=13597.604..13597.609 rows=285810 loops=1
                                              Buffers: shared hit=250037 read=9090 dirtied=26, temp read=3648 written=8172
                                              I/O Timings: read=12656.606
                                            ->  Nested Loop  (cost=239.54..33585.40 rows=4226 width=104) (actual time=6.219..13166.722 rows=283349 loops=3)
                                                  Output: us.session_id, u.user_id, u.firstname, u.surname, u.image_url, p.pool_name, p.client_id, p.pool_id
                                                  Buffers: shared hit=752034 read=27894 dirtied=52
                                                  I/O Timings: read=38115.334
                                                  Worker 0:  actual time=3.284..13087.841 rows=288936 loops=1
                                                    Buffers: shared hit=258562 read=9464 dirtied=14
                                                    I/O Timings: read=12590.170
                                                  Worker 1:  actual time=7.931..13106.351 rows=285810 loops=1
                                                    Buffers: shared hit=250037 read=9090 dirtied=26
                                                    I/O Timings: read=12656.606
                                                  ->  Nested Loop  (cost=239.11..15989.40 rows=124 width=104) (actual time=5.013..1891.004 rows=3880 loops=3)
                                                        Output: u.user_id, u.firstname, u.surname, u.image_url, up.user_id, p.pool_name, p.client_id, p.pool_id
                                                        Inner Unique: true
                                                        Buffers: shared hit=254626 read=4579 dirtied=52
                                                        I/O Timings: read=5183.492
                                                        Worker 0:  actual time=1.601..1793.850 rows=4041 loops=1
                                                          Buffers: shared hit=90103 read=1608 dirtied=14
                                                          I/O Timings: read=1612.670
                                                        Worker 1:  actual time=6.604..2114.870 rows=3960 loops=1
                                                          Buffers: shared hit=83066 read=1497 dirtied=26
                                                          I/O Timings: read=1968.382
                                                        ->  Hash Join  (cost=238.69..13655.78 rows=624 width=100) (actual time=0.954..42.871 rows=20490 loops=3)
                                                              Output: u.user_id, u.firstname, u.surname, u.image_url, p.pool_name, p.client_id, p.pool_id
                                                              Inner Unique: true
                                                              Hash Cond: (u.local_pool = p.pool_id)
                                                              Buffers: shared hit=13161
                                                              Worker 0:  actual time=0.980..45.020 rows=21799 loops=1
                                                                Buffers: shared hit=4452
                                                              Worker 1:  actual time=0.778..40.547 rows=19986 loops=1
                                                                Buffers: shared hit=4573
                                                              ->  Parallel Seq Scan on public.users u  (cost=0.00..13263.23 rows=58571 width=71) (actual time=0.007..27.779 rows=46880 loops=3)
                                                                    Output: u.user_id, u.firstname, u.surname, u.image_url, u.local_pool
                                                                    Filter: (u.disabled IS FALSE)
                                                                    Rows Removed by Filter: 664
                                                                    Buffers: shared hit=12669
                                                                    Worker 0:  actual time=0.006..29.047 rows=49923 loops=1
                                                                      Buffers: shared hit=4288
                                                                    Worker 1:  actual time=0.005..25.210 rows=45846 loops=1
                                                                      Buffers: shared hit=4409
                                                              ->  Hash  (cost=237.90..237.90 rows=63 width=33) (actual time=0.931..0.932 rows=61 loops=3)
                                                                    Output: p.pool_name, p.client_id, p.pool_id
                                                                    Buckets: 1024  Batches: 1  Memory Usage: 12kB
                                                                    Buffers: shared hit=492
                                                                    Worker 0:  actual time=0.961..0.962 rows=61 loops=1
                                                                      Buffers: shared hit=164
                                                                    Worker 1:  actual time=0.761..0.762 rows=61 loops=1
                                                                      Buffers: shared hit=164
                                                                    ->  Seq Scan on public.pools p  (cost=0.00..237.90 rows=63 width=33) (actual time=0.018..0.905 rows=61 loops=3)
                                                                          Output: p.pool_name, p.client_id, p.pool_id
                                                                          Filter: (p.client_id = 1)
                                                                          Rows Removed by Filter: 5682
                                                                          Buffers: shared hit=492
                                                                          Worker 0:  actual time=0.022..0.931 rows=61 loops=1
                                                                            Buffers: shared hit=164
                                                                          Worker 1:  actual time=0.018..0.738 rows=61 loops=1
                                                                            Buffers: shared hit=164
                                                        ->  Index Scan using user_prefs_pkey on public.user_prefs up  (cost=0.42..3.74 rows=1 width=4) (actual time=0.090..0.090 rows=0 loops=61471)
                                                              Output: up.user_id
                                                              Index Cond: (up.user_id = u.user_id)
                                                              Filter: (up.enable_public_leaderboards IS TRUE)
                                                              Rows Removed by Filter: 1
                                                              Buffers: shared hit=241465 read=4579 dirtied=52
                                                              I/O Timings: read=5183.492
                                                              Worker 0:  actual time=0.080..0.080 rows=0 loops=21799
                                                                Buffers: shared hit=85651 read=1608 dirtied=14
                                                                I/O Timings: read=1612.670
                                                              Worker 1:  actual time=0.103..0.103 rows=0 loops=19986
                                                                Buffers: shared hit=78493 read=1497 dirtied=26
                                                                I/O Timings: read=1968.382
                                                  ->  Index Only Scan using user_sessions_pkey on public.user_sessions us  (cost=0.43..140.35 rows=155 width=8) (actual time=0.788..2.892 rows=73 loops=11640)
                                                        Output: us.user_id, us.session_id
                                                        Index Cond: ((us.user_id = u.user_id) AND (us.user_id IS NOT NULL))
                                                        Heap Fetches: 492751
                                                        Buffers: shared hit=497408 read=23315
                                                        I/O Timings: read=32931.842
                                                        Worker 0:  actual time=0.774..2.781 rows=72 loops=4041
                                                          Buffers: shared hit=168459 read=7856
                                                          I/O Timings: read=10977.501
                                                        Worker 1:  actual time=0.727..2.761 rows=72 loops=3960
                                                          Buffers: shared hit=166971 read=7593
                                                          I/O Timings: read=10688.224
Planning:
  Buffers: shared hit=101
Planning Time: 1.549 ms
Execution Time: 13802.195 ms

Answer 1

All of your left joins are pointless, as the NULLed values would just get filtered out later due to p.client_id = 1 condition. The planner is not confused by this and just converts them to inner joins, but the humans you are asking for help (as well as yourself) might be confused by it. If you are going to do inner joins, you should just write them as inner joins.

The sort here takes essentially no time, it is fetching the rows in order to sort them which takes the time. In particular, your index scan is kicked almost a million times, but returns zero rows the vast majority of those times.

->  Nested Loop  (cost=237.06..49595.28 rows=17 width=106) (actual time=7.643..198430.995 rows=3082 loops=3)
    ->  Nested Loop  (cost=236.63..33180.53 rows=4102 width=100) (actual time=2.244..7667.042 rows=281863 loops=3)
        ...
    ->  Index Scan using sessions_pkey on public.sessions s  (cost=0.43..4.00 rows=1 width=10) (actual time=0.676..0.676 rows=0 loops=845589)
       Output: s.session_id, s.total_time_in_seconds
       Index Cond: (s.session_id = us.session_id)
       Filter: ((s.requires_checking IS FALSE) AND (s.swim_rating > 10) AND (s.date_swam > '2023-03-01 01:59:54.962+00'::timestamp with time zone) AND (s.date_swam < '2023-03-31 23:13:54.962+00'::timestamp with time zone))

Presumably the filter is the thing causing most of those to fail. It might be faster if this table were the one driving the whole plan, rather than sitting at the tail end throwing away most of the data after laboriously fetching it. To promote that, you would want a multicolumn index tailored to the filter. Unfortunatley, having two different inequality conditions makes perfect tailoring here very hard. So, what is more selective, the swim_rating condition or the date_swam condition? There is no way we can tell that just from the info reported in the plan.

If the swim_rating is always compared against 10 (never some different number) then you could create an index tailored just to that:

create index on sessions (date_swam) where requires_checking IS FALSE AND swim_rating > 10

Your new plan is doing what I thought it should with that index, but it is still hash joining it to another node, instead of using it to drive a nested loop. It could be that you have a missing index which would be necessary to do the nested loop, or it could be just because it still thinks the hash joined plan is faster than the big pile of nested loops to index scans I was envisioning. You would try again with enable_hashjoin=off to see if you can get the plan I was thinking of.

But now I see that your IO seems to be very slow and poorly cached. So maybe the plan I am thinking of will also be slow, because it would generate a lot of random IO. Which makes me think your server is just inadequate to the job, or perhaps is vastly overloaded.

In particular, the parallel seq scan on "users" returns only 5 rows per millisecond (or 15, once parallel workers are included) and only about 14 rows per page. Either those tuples are quite wide, or the table is quite bloated. And even accounting for the size, it is still very slow. 26511 ms to read 12667 8K pages is only about 3MB/s. Which is pretty shocking for sequential reads on any vaguely modern hardware.

Answer 2

You have lots of users matching the conditions and lots of sessions matching the requested conditions, but much less user_sessions that match both. Try to force postgres to filter out sessions and users first, then join them with an hash join.

I suggest:

create index on pools (client_id);
create index on users (local_pool);
create index on user_sessions  (session_id, user_id);
create index on sessions (date_swam, session_id, total_time_in_seconds) where requires_checking IS FALSE AND swim_rating > 10;

This should help postgresql by starting in locating the right pools, getting to the users with that local_pool.

Also, this should help filtering the sessions that satisfy the right conditions.

I would then rewrite the SELECT in this way, trying to force postgres into using those indexes

SELECT usp.user_id,usp.firstname,usp.surname,usp.image_url,usp.pool_name, count(s.session_id) as totalSwims,sum(s.total_time_in_seconds) as totalTotalTime
from (select session_id, total_time_in_seconds, user_id from sessions join user_sessions us on us.session_id = session.session_id where requires_checking is false 
and swim_rating > 10 
and date_swam > '2023-03-01 01:59:54.962+00' 
and date_swam < '2023-03-31 23:13:54.962+00' 
and us.user_id is not null 
) as s 
join 
(select u.user_id, u.firstname,u.surname,u.image_url p.pool_name, p.client_id from users as u  
join user_prefs as up on up.user_id = u.user_id 
join pools as p on p.pool_id = u.local_pool 
where p.client_id = 1 
and up.enable_public_leaderboards is true 
and u.disabled is false) as usp on usp.user_id = s.user_id
group by usp.user_id, usp.pool_name, usp.client_id
order by sum(s.total_time_in_seconds) desc
limit 20