po 2. 5. 2022 v 23:48 odesílatel David Rowley <dgrowle...@gmail.com> napsal:
> On Mon, 2 May 2022 at 21:00, Pavel Stehule <pavel.steh...@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 > 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 >
