Re: strange slow query - lost lot of time somewhere - Mailing list pgsql-hackers
| From | Pavel Stehule |
|---|---|
| Subject | Re: strange slow query - lost lot of time somewhere |
| Date | |
| Msg-id | CAFj8pRAjU0FFYUkC6bk8x4jB9NHu+k5NM7=iaB1iQTWV38q3=A@mail.gmail.com Whole thread Raw |
| In response to | Re: strange slow query - lost lot of time somewhere (Pavel Stehule <pavel.stehule@gmail.com>) |
| Responses |
Re: strange slow query - lost lot of time somewhere
|
| List | pgsql-hackers |
út 3. 5. 2022 v 6:09 odesílatel Pavel Stehule <pavel.stehule@gmail.com> napsal:
po 2. 5. 2022 v 23:48 odesílatel David Rowley <dgrowleyml@gmail.com> napsal:On Mon, 2 May 2022 at 21:00, Pavel Stehule <pavel.stehule@gmail.com> wrote:
> I found a query that is significantly slower with more memory
Can you clarify what you mean here? More memory was installed on the
machine? or work_mem was increased? or?
> plan 1 - fast https://explain.depesz.com/s/XM1f
>
> plan 2 - slow https://explain.depesz.com/s/2rBw
If it was work_mem you increased, it seems strange that the plan would
switch over to using a Nested Loop / Memoize plan. Only 91 rows are
estimated on the outer side of the join. It's hard to imagine that
work_mem was so low that the Memoize costing code thought there would
ever be cache evictions.
> Strange - the time of last row is +/- same, but execution time is 10x worse
>
> It looks like slow environment cleaning
Can you also show EXPLAIN for the Memoize plan without ANALYZE?yes - it is strange - it is just slow without execution┌──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
│ QUERY PLAN │
├──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┤
│ Nested Loop Anti Join (cost=59.62..3168.15 rows=1 width=16) │
│ -> Nested Loop Anti Join (cost=59.34..3165.24 rows=1 width=16) │
│ -> Nested Loop Semi Join (cost=58.48..3133.09 rows=1 width=16) │
│ -> Bitmap Heap Scan on item itembo0_ (cost=57.34..2708.22 rows=11 width=16) │
│ Recheck Cond: ((ending_time IS NULL) OR ((status_id = ANY ('{1,4,5}'::bigint[])) AND (CURRENT_TIMESTAMP < ending_time) AND (starting_time <= CURRENT_TIMESTAMP))) │
│ Filter: ((to_expose_date IS NULL) AND (status_id = ANY ('{1,4,5}'::bigint[])) AND (starting_time <= CURRENT_TIMESTAMP) AND ((ending_time IS NULL) OR (CURRENT_TIMESTAMP < ending_time))) │
│ -> BitmapOr (cost=57.34..57.34 rows=1751 width=0) │
│ -> Bitmap Index Scan on stehule354 (cost=0.00..2.08 rows=1 width=0) │
│ Index Cond: (ending_time IS NULL) │
│ -> Bitmap Index Scan on stehule1010 (cost=0.00..55.26 rows=1751 width=0) │
│ Index Cond: ((status_id = ANY ('{1,4,5}'::bigint[])) AND (ending_time > CURRENT_TIMESTAMP) AND (starting_time <= CURRENT_TIMESTAMP)) │
│ -> Nested Loop (cost=1.14..37.71 rows=91 width=8) │
│ -> Index Only Scan using uq_isi_itemid_itemimageid on item_share_image itemsharei2__1 (cost=0.57..3.80 rows=91 width=16) │
│ Index Cond: (item_id = itembo0_.id) │
│ -> Memoize (cost=0.57..2.09 rows=1 width=8) │
│ Cache Key: itemsharei2__1.item_image_id │
│ Cache Mode: logical │
│ -> Index Only Scan using pk_item_image on item_image itemimageb3__1 (cost=0.56..2.08 rows=1 width=8) │
│ Index Cond: (id = itemsharei2__1.item_image_id) │
│ -> Nested Loop (cost=0.85..32.14 rows=1 width=8) │
│ -> Index Only Scan using uq_isi_itemid_itemimageid on item_share_image itemsharei2_ (cost=0.57..3.80 rows=91 width=16) │
│ Index Cond: (item_id = itembo0_.id) │
│ -> Memoize (cost=0.29..1.72 rows=1 width=8) │
│ Cache Key: itemsharei2_.item_image_id │
│ Cache Mode: logical │
│ -> Index Only Scan using stehule3001 on item_image itemimageb3_ (cost=0.28..1.71 rows=1 width=8) │
│ Index Cond: (id = itemsharei2_.item_image_id) │
│ -> Index Only Scan using ixfk_ima_itemid on item_missing_attribute itemmissin1_ (cost=0.28..1.66 rows=1 width=8) │
│ Index Cond: (item_id = itembo0_.id) │
└──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
(29 řádek)
Čas: 420,392 ms
there is really something strange (see attached file). Looks so this issue is much more related to planning time than execution time
Does the slowness present every time that plan is executed?looks yes
Can you show the EXPLAIN ANALYZE of the nested loop plan with
enable_memoize = off? You may ned to disable hash and merge join.┌─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
│ QUERY PLAN │
├─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┤
│ Nested Loop Anti Join (cost=1093.22..4488.89 rows=1 width=16) (actual time=5.723..60.470 rows=13 loops=1) │
│ -> Nested Loop Anti Join (cost=1092.94..4485.97 rows=1 width=16) (actual time=5.165..60.368 rows=41 loops=1) │
│ -> Gather (cost=1001.70..4391.26 rows=1 width=16) (actual time=1.909..56.913 rows=41 loops=1) │
│ Workers Planned: 2 │
│ Workers Launched: 2 │
│ -> Nested Loop Semi Join (cost=1.70..3391.16 rows=1 width=16) (actual time=22.032..39.253 rows=14 loops=3) │
│ -> Parallel Index Only Scan using stehule1010 on item itembo0_ (cost=0.57..2422.83 rows=5 width=16) (actual time=21.785..38.851 rows=14 loops=3) │
│ Index Cond: ((status_id = ANY ('{1,4,5}'::bigint[])) AND (starting_time <= CURRENT_TIMESTAMP)) │
│ Filter: ((to_expose_date IS NULL) AND ((ending_time IS NULL) OR (CURRENT_TIMESTAMP < ending_time))) │
│ Rows Removed by Filter: 1589 │
│ Heap Fetches: 21 │
│ -> Nested Loop (cost=1.13..192.76 rows=91 width=8) (actual time=0.029..0.029 rows=1 loops=41) │
│ -> Index Only Scan using uq_isi_itemid_itemimageid on item_share_image itemsharei2__1 (cost=0.57..3.80 rows=91 width=16) (actual time=0.015..0.015 rows=1 loops=41) │
│ Index Cond: (item_id = itembo0_.id) │
│ Heap Fetches: 2 │
│ -> Index Only Scan using pk_item_image on item_image itemimageb3__1 (cost=0.56..2.08 rows=1 width=8) (actual time=0.013..0.013 rows=1 loops=41) │
│ Index Cond: (id = itemsharei2__1.item_image_id) │
│ Heap Fetches: 2 │
│ -> Hash Join (cost=91.24..94.71 rows=1 width=8) (actual time=0.084..0.084 rows=0 loops=41) │
│ Hash Cond: (itemsharei2_.item_image_id = itemimageb3_.id) │
│ -> Index Only Scan using uq_isi_itemid_itemimageid on item_share_image itemsharei2_ (cost=0.57..3.80 rows=91 width=16) (actual time=0.003..0.004 rows=6 loops=41) │
│ Index Cond: (item_id = itembo0_.id) │
│ Heap Fetches: 2 │
│ -> Hash (cost=67.41..67.41 rows=1861 width=8) (actual time=3.213..3.214 rows=3950 loops=1) │
│ Buckets: 4096 (originally 2048) Batches: 1 (originally 1) Memory Usage: 187kB │
│ -> Index Only Scan using stehule3001 on item_image itemimageb3_ (cost=0.28..67.41 rows=1861 width=8) (actual time=0.029..2.479 rows=3950 loops=1) │
│ Heap Fetches: 2203 │
│ -> Index Only Scan using ixfk_ima_itemid on item_missing_attribute itemmissin1_ (cost=0.28..1.66 rows=1 width=8) (actual time=0.002..0.002 rows=1 loops=41) │
│ Index Cond: (item_id = itembo0_.id) │
│ Heap Fetches: 0 │
│ Planning Time: 1.471 ms │
│ Execution Time: 60.570 ms │
└─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
(32 řádek)
Čas: 62,982 ms
David
Attachment
pgsql-hackers by date: