Thread: BUG #17330: EXPLAIN hangs and very long query plans

The following bug has been logged on the website:

Bug reference:      17330
Logged by:          Strahinja Kustudic
Email address:      strahinjak@nordeus.com
PostgreSQL version: 10.19
Operating system:   CentOS 7
Description:       

 The issue is that in Docker EXPLAIN runs forever, it never
finishes, like the issue we had on the replica. This means I have a 100%
repro of the issue and I can do whatever you tell me to do to find out what
caused it.

On Thu, Dec 9, 2021 at 10:28 AM PG Bug reporting form <noreply@postgresql.org> wrote:

The following bug has been logged on the website:

Bug reference:      17330
Logged by:          Strahinja Kustudic
Email address:      strahinjak@nordeus.com
PostgreSQL version: 10.19
Operating system:   CentOS 7
Description:       

 

 The issue is that in Docker EXPLAIN runs forever, it never
finishes, like the issue we had on the replica. This means I have a 100%
repro of the issue and I can do whatever you tell me to do to find out what
caused it.

Is this 100% CPU bound?  'perf top -p <pid>' would probably be my first tool to use here.

Sounds like a problem with get_actual_variable_range(), which can scan
indexes at plan time to determine minimum or maximum values.

This actually has been improved quite a bit since Postgres 10. So as
Jeff said, seems like you might benefit from upgrading to a newer
major version. v11 has improved things in this exact area.

On Fri, Dec 10, 2021 at 2:36 AM Peter Geoghegan <pg@bowt.ie> wrote:

Sounds like a problem with get_actual_variable_range(), which can scan
indexes at plan time to determine minimum or maximum values.

This actually has been improved quite a bit since Postgres 10. So as
Jeff said, seems like you might benefit from upgrading to a newer
major version. v11 has improved things in this exact area.

On my Docker instance when I execute EXPLAIN it starts reading a lot of data. The indexes of the biggest table the query reads are 50GB, so my guess is that it reads those indexes.

I allowed EXPLAIN in Docker to finish and it took almost 500 seconds and it was reading data all the time. After I reindexed the biggest table, EXPLAIN finished instantly. Can the index corruption cause this?

Note that this started happening in production after we deleted a few million rows from the biggest table.

Regards,

Strahinja

On Fri, Dec 10, 2021 at 10:53 AM Pavel Stehule <pavel.stehule@gmail.com> wrote:

Hi

pá 10. 12. 2021 v 10:25 odesílatel Strahinja Kustudić <strahinjak@nordeus.com> napsal:

On Fri, Dec 10, 2021 at 2:36 AM Peter Geoghegan <pg@bowt.ie> wrote:

Sounds like a problem with get_actual_variable_range(), which can scan
indexes at plan time to determine minimum or maximum values.

This actually has been improved quite a bit since Postgres 10. So as
Jeff said, seems like you might benefit from upgrading to a newer
major version. v11 has improved things in this exact area.

On my Docker instance when I execute EXPLAIN it starts reading a lot of data. The indexes of the biggest table the query reads are 50GB, so my guess is that it reads those indexes.

I allowed EXPLAIN in Docker to finish and it took almost 500 seconds and it was reading data all the time. After I reindexed the biggest table, EXPLAIN finished instantly. Can the index corruption cause this?

The index can be bloated.

Is bloat just enough to make it slower, or the index needs to be corrupted?

 

Note that this started happening in production after we deleted a few million rows from the biggest table.

it is maybe same issue

https://www.postgresql.org/message-id/9ADAF560-F331-4AF8-A28A-F005070C3187%40yandex.ru

Looks similar because there were deletes after which query plans went to a few seconds.

I just upgraded Postgres to 12 with pg_upgrade, did ANALYZE of the whole DB and the issue is similar, but EXPLAIN now finishes in 19 seconds instead of 500 seconds, which means the issue is still there. Here is the whole EXPLAIN ANALYZE (I added ANALYZE so that it displays planning duration):

Sort  (cost=1946.04..1946.16 rows=46 width=642) (actual time=10.929..10.932 rows=20 loops=1)
   Sort Key: m.delivery_start DESC
   Sort Method: quicksort  Memory: 44kB
   ->  Nested Loop Left Join  (cost=10.19..1944.77 rows=46 width=642) (actual time=2.305..10.401 rows=20 loops=1)
         Join Filter: ((c.game_name = csu.game_name) AND (um.user_id = csu.user_id) AND (c.id = csu.campaign_id))
         Filter: ((c.id IS NULL) OR (c.active AND (now() >= c.campaign_start) AND ((now() <= c.campaign_end) OR (c.campaign_end IS NULL)) AND ((c.segment_ids <@ '{5632,-2,2,5634,9731,5640,5641,9738,13,3599,5648,5655,13343,5
664,13344,13345,13346,13347,13348,13350,13351,13352,5673,13353,13354,1067,13355,13356,13357,13358,13359,5680,13360,6705,13361,13362,13363,13364,13365,13366,5687,13367,13368,13369,20538,13370,13371,13372,13373,6718,13374,190
07,19008,13378,5699,13379,13380,19013,3142,3143,19015,13385,5707,6731,20555,19019,3149,19021,3150,591,19023,592,19024,6737,19027,19028,5717,6743,17496,19033,13402,19035,6750,17502,19039,17504,19041,19043,19044,17508,6757,17
510,19047,104,19048,17512,17514,7788,6764,621,19053,623,19055,7792,625,19059,7796,1141,19061,19063,7800,19064,5241,19067,19068,3713,19073,1667,19075,1668,19079,19081,19083,19084,5262,19087,19088,8338,8339,7828,19093,20631,1
9095,20632,20633,12955,19099,19101,19103,19104,19107,19108,19113,19115,8876,19119,3760,19121,19123,19124,3785,4814,16605,4324,16622,16623,21253,21254,4359,21258,5901,5915,4900,22832,22835,22836,9013,3895,3902,1865,1866,1379
,1380,4978,7027,13685,14203,2428,2429,21887,21888,4485,22932,22933,21911,21417,432,434,20418,968,969,470,7642,991,992,10209,1512,1513,23024,9201,9207,23032,9208,9214}'::integer[]) OR (csu.user_id = '-XXXXXXXXXXXXXXXXXX'::b
igint))))
         Rows Removed by Filter: 11
         ->  Nested Loop  (cost=10.03..1910.89 rows=163 width=696) (actual time=2.029..10.092 rows=31 loops=1)
               ->  Hash Left Join  (cost=9.46..695.80 rows=61 width=684) (actual time=0.729..5.991 rows=55 loops=1)
                     Hash Cond: ((m.game_name = c.game_name) AND (m.campaign_id = c.id))
                     ->  Index Scan using mail_pkey on mail m  (cost=0.27..686.29 rows=61 width=552) (actual time=0.297..5.524 rows=55 loops=1)
                           Filter: (active AND (game_name = 'topeleven'::game_name) AND (now() >= delivery_start) AND ((now() <= delivery_end) OR (delivery_end IS NULL)))
                           Rows Removed by Filter: 97
                     ->  Hash  (cost=7.83..7.83 rows=91 width=136) (actual time=0.411..0.412 rows=91 loops=1)
                           Buckets: 1024  Batches: 1  Memory Usage: 26kB
                           ->  Seq Scan on campaign c  (cost=0.00..7.83 rows=91 width=136) (actual time=0.265..0.371 rows=91 loops=1)
                                 Filter: (game_name = 'topeleven'::game_name)
                                 Rows Removed by Filter: 55
               ->  Index Scan using user_mail_pkey on user_mail um  (cost=0.57..19.88 rows=4 width=24) (actual time=0.074..0.074 rows=1 loops=55)
                     Index Cond: ((user_id = '-XXXXXXXXXXXXXXXXXX'::bigint) AND (game_name = 'topeleven'::game_name) AND (mail_id = m.id))
                     Filter: ((m.mail_type <> 'question'::mail_type) OR (mail_status <> 'completed'::mail_status))
         ->  Materialize  (cost=0.15..28.18 rows=1 width=16) (actual time=0.009..0.009 rows=0 loops=31)
               ->  Index Only Scan using campaign_static_users_pkey on campaign_static_users csu  (cost=0.15..28.17 rows=1 width=16) (actual time=0.266..0.266 rows=0 loops=1)
                     Index Cond: ((user_id = '-XXXXXXXXXXXXXXXXXX'::bigint) AND (game_name = 'topeleven'::game_name))
                     Heap Fetches: 0
 Planning Time: 19408.862 ms
 Execution Time: 10.978 ms
(27 rows)

Just to mention again, reindexing the biggest table fixes the issue, but I'm more curious why did this happen and how can we prevent it from happening again? Or is it already fixed so that it cannot happen in the future?

Regards,

Strahinja

bloat != corruption.  The problem you're dealing with here is a whole lot
of dead index entries at the very end of the index range (could be either
the lowest or highest entries).  The planner is wasting time scanning
through those to find the extremal non-dead value for a range estimate.
REINDEX got rid of the dead entries; a VACUUM would have done as well.

As noted upthread, more recent PG versions are a bit smarter about
such cases.