Postgres performing SEQ scan for specific user

All we need is an easy explanation of the problem, so here it is.

I am trying to see why the following query is taking so long to execute (around 5min) for a specific user but for others with the same number of rows involved it is taking 2 / 3 seconds

There is one main table ‘lengths’ with FK to ‘sessions’ table, the lengths table has a lengths_idx index on session_id and stroke_type columns that is normally used here

I can see that it is not using the lengths_idx index on the ‘lengths’ table for this specific user, could this be problem with the index / statistics for this table?

Postgresql 9.6 running on Amazon RDS

SELECT x.sess_id, round(count(x.*) * x.size,2)
FROM ( 
    SELECT l.session_id as sess_id, 
            l.stroke_type, 
            s.pool_size as size,row_number() OVER (ORDER BY l.session_id, l.stroke_type, l.length_number) - l.length_number AS grp 
    FROM lengths as l, user_sessions as us, sessions as s 
    WHERE l.session_id = us.session_id 
    AND us.user_id = 1234 
    AND l.session_id = s.session_id     
    AND CAST(l.stroke_type as text) = CAST('free' as text) 
) x 
GROUP BY x.sess_id, x.stroke_type, grp, x.size 
ORDER BY count(x.*) DESC LIMIT 1

QUERY EXPLAIN FOR FAST EXECUTION (INDEX SCAN):

Limit  (cost=5341076.22..5341076.23 rows=1 width=61) (actual time=2817.451..2817.452 rows=1 loops=1)
  ->  Sort  (cost=5341076.22..5341077.08 rows=342 width=61) (actual time=2817.449..2817.449 rows=1 loops=1)
        Sort Key: (count(x.*)) DESC
        Sort Method: top-N heapsort  Memory: 25kB
        ->  GroupAggregate  (cost=5341062.54..5341074.51 rows=342 width=61) (actual time=2776.621..2817.029 rows=1136 loops=1)
              Group Key: x.sess_id, x.stroke_type, x.grp, x.size
              ->  Sort  (cost=5341062.54..5341063.40 rows=342 width=66) (actual time=2776.573..2793.144 rows=57154 loops=1)
                    Sort Key: x.sess_id, x.stroke_type, x.grp, x.size
                    Sort Method: external sort  Disk: 4248kB
                    ->  Subquery Scan on x  (cost=5341036.18..5341048.15 rows=342 width=66) (actual time=2627.123..2710.884 rows=57154 loops=1)
                          ->  WindowAgg  (cost=5341036.18..5341044.73 rows=342 width=25) (actual time=2627.108..2679.127 rows=57154 loops=1)
                                ->  Sort  (cost=5341036.18..5341037.03 rows=342 width=17) (actual time=2627.091..2644.249 rows=57154 loops=1)
                                      Sort Key: l.session_id, l.stroke_type, l.length_number
                                      Sort Method: external sort  Disk: 1512kB
                                      ->  Nested Loop  (cost=1.43..5341021.79 rows=342 width=17) (actual time=3.403..2571.724 rows=57154 loops=1)
                                            Join Filter: (us.session_id = l.session_id)
                                            ->  Nested Loop  (cost=0.86..13212.89 rows=1367 width=13) (actual time=1.854..494.049 rows=1079 loops=1)
                                                  ->  Index Only Scan using user_sessions_pkey on user_sessions us  (cost=0.43..1911.49 rows=1367 width=4) (actual time=0.947..86.638 rows=1079 loops=1)
                                                        Index Cond: (user_id = 2055)
                                                        Heap Fetches: 290
                                                  ->  Index Scan using sessions_pkey on sessions s  (cost=0.43..8.26 rows=1 width=9) (actual time=0.374..0.376 rows=1 loops=1079)
                                                        Index Cond: (session_id = us.session_id)
                                            ->  Index Scan using lengths_idx on lengths l  (cost=0.57..3897.30 rows=12 width=12) (actual time=1.208..1.899 rows=53 loops=1079)
                                                  Index Cond: (session_id = s.session_id)
                                                  Filter: ((stroke_type)::text = 'free'::text)
                                                  Rows Removed by Filter: 0
Planning time: 3.090 ms
Execution time: 2819.171 ms

QUERY EXPLAIN FOR SLOW EXECUTION (SEQ SCAN):

Limit  (cost=5759727.25..5759727.25 rows=1 width=61) (actual time=315354.229..315354.231 rows=1 loops=1)
  ->  Sort  (cost=5759727.25..5759728.36 rows=444 width=61) (actual time=315354.228..315354.228 rows=1 loops=1)
        Sort Key: (count(x.*)) DESC
        Sort Method: top-N heapsort  Memory: 25kB
        ->  GroupAggregate  (cost=5759709.49..5759725.03 rows=444 width=61) (actual time=315304.470..315353.719 rows=1094 loops=1)
              Group Key: x.sess_id, x.stroke_type, x.grp, x.size
              ->  Sort  (cost=5759709.49..5759710.60 rows=444 width=66) (actual time=315304.374..315324.696 rows=54090 loops=1)
                    Sort Key: x.sess_id, x.stroke_type, x.grp, x.size
                    Sort Method: external sort  Disk: 4016kB
                    ->  Subquery Scan on x  (cost=5759674.42..5759689.96 rows=444 width=66) (actual time=315123.778..315226.785 rows=54090 loops=1)
                          ->  WindowAgg  (cost=5759674.42..5759685.52 rows=444 width=25) (actual time=315123.762..315189.061 rows=54090 loops=1)
                                ->  Sort  (cost=5759674.42..5759675.53 rows=444 width=17) (actual time=315123.744..315147.132 rows=54090 loops=1)
                                      Sort Key: l.session_id, l.stroke_type, l.length_number
                                      Sort Method: external sort  Disk: 1432kB
                                      ->  Nested Loop  (cost=2484.15..5759654.90 rows=444 width=17) (actual time=251.322..315047.897 rows=54090 loops=1)
                                            ->  Hash Join  (cost=2483.72..5756479.95 rows=444 width=16) (actual time=250.846..312922.269 rows=54090 loops=1)
                                                  Hash Cond: (l.session_id = us.session_id)
                                                  ->  Seq Scan on lengths l  (cost=0.00..5750146.58 rows=1025390 width=12) (actual time=0.458..282569.670 rows=101216939 loops=1)
                                                        Filter: ((stroke_type)::text = 'free'::text)
                                                        Rows Removed by Filter: 103123974
                                                  ->  Hash  (cost=2461.52..2461.52 rows=1776 width=4) (actual time=118.626..118.626 rows=1059 loops=1)
                                                        Buckets: 2048  Batches: 1  Memory Usage: 54kB
                                                        ->  Index Only Scan using user_sessions_pkey on user_sessions us  (cost=0.43..2461.52 rows=1776 width=4) (actual time=0.963..118.151 rows=1059 loops=1)
                                                              Index Cond: (user_id = 43266)
                                                              Heap Fetches: 446
                                            ->  Index Scan using sessions_pkey on sessions s  (cost=0.43..7.14 rows=1 width=9) (actual time=0.037..0.038 rows=1 loops=54090)
                                                  Index Cond: (session_id = l.session_id)
Planning time: 0.572 ms
Execution time: 315356.321 ms

How to solve :

I know you bored from this bug, So we are here to help you! Take a deep breath and look at the explanation of your problem. We have many solutions to this problem, But we recommend you to use the first method because it is tested & true method that will 100% work for you.

Method 1

The estimates on lengths are pretty bad.

Try to get fresh statistics for the table using ANALYZE. If that alone is not enough, increase the detail:

ALTER TABLE lenghts ALTER stroke_type SET STATISTICS 1000;
ANALYZE lengths;

Note: Use and implement method 1 because this method fully tested our system.
Thank you 🙂

All methods was sourced from stackoverflow.com or stackexchange.com, is licensed under cc by-sa 2.5, cc by-sa 3.0 and cc by-sa 4.0

Leave a Reply