Subject: using memoize in in paralel query decreases performance

From: Pavel Stehule <[email-masked]>
Date: Mon, 6 Mar 2023 08:33:42 +0100

Hi

In one query I can see very big overhead of memoize node - unfortunately
with hits = 0

The Estimate is almost very good. See details in attachment

Regards

Pavel

---

From: David Rowley <[email-masked]>
Date: Mon, 6 Mar 2023 21:16:41 +1300

On Mon, 6 Mar 2023 at 20:34, Pavel Stehule <[email-masked]> wrote:
> In one query I can see very big overhead of memoize node - unfortunately with hits = 0
>

Are you able to share the version number for this?

Also, it would be good to see EXPLAIN ANALYZE *VERBOSE* for the
memorize plan so we can see the timings for the parallel workers.

The results of:

EXPLAIN ANALYZE
SELECT DISTINCT  ictc.sub_category_id
FROM ixfk_ictc_subcategoryid ictc
INNER JOIN item i ON i.item_category_id = ictc.sub_category_id
WHERE ictc.super_category_id = ANY
('{47124,49426,49488,47040,47128}'::bigint[]);

would also be useful. That should give an idea of the ndistinct
estimate.  I guess memorize thinks there are fewer unique values than
the 112 that were found.  There's probably not much to be done about
that. The slowness of the parallel workers seems like a more
interesting thing to understand.

David

---

From: Pavel Stehule <[email-masked]>
Date: Mon, 6 Mar 2023 09:54:59 +0100

> Are you able to share the version number for this?

15.1 - upgrade on 15.2 is planned this month

> memorize plan so we can see the timings for the parallel workers.

default https://explain.depesz.com/s/fnBe
disabled memoize https://explain.depesz.com/s/P2rP

> ('{47124,49426,49488,47040,47128}'::bigint[]);
https://explain.depesz.com/s/OtCl

---

From: David Rowley <[email-masked]>
Date: Tue, 7 Mar 2023 10:52:08 +1300

> default https://explain.depesz.com/s/fnBe

It looks like the slowness is coming from the Bitmap Index scan and
Bitmap heap scan rather than Memoize.

       ->  Bitmap Heap Scan on public.item i  (cost=285.69..41952.12
rows=29021 width=16) (actual time=20.395..591.606 rows=20471
loops=784)
     Output: i.id, i.item_category_id
     Recheck Cond: (i.item_category_id = ictc.sub_category_id)
     Heap Blocks: exact=1590348
     Worker 0:  actual time=20.128..591.426 rows=20471 loops=112
     Worker 1:  actual time=20.243..591.627 rows=20471 loops=112
     Worker 2:  actual time=20.318..591.660 rows=20471 loops=112
     Worker 3:  actual time=21.180..591.644 rows=20471 loops=112
     Worker 4:  actual time=20.226..591.357 rows=20471 loops=112
     Worker 5:  actual time=20.597..591.418 rows=20471 loops=112
     ->  Bitmap Index Scan on ixfk_ite_itemcategoryid
(cost=0.00..278.43 rows=29021 width=0) (actual time=14.851..14.851
rows=25362 loops=784)
   Index Cond: (i.item_category_id = ictc.sub_category_id)
   Worker 0:  actual time=14.863..14.863 rows=25362 loops=112
   Worker 1:  actual time=14.854..14.854 rows=25362 loops=112
   Worker 2:  actual time=14.611..14.611 rows=25362 loops=112
   Worker 3:  actual time=15.245..15.245 rows=25362 loops=112
   Worker 4:  actual time=14.909..14.909 rows=25362 loops=112
   Worker 5:  actual time=14.841..14.841 rows=25362 loops=112

> disabled memoize https://explain.depesz.com/s/P2rP

->  Bitmap Heap Scan on public.item i  (cost=285.69..41952.12
rows=29021 width=16) (actual time=9.256..57.503 rows=20471 loops=784)
       Output: i.id, i.item_category_id
       Recheck Cond: (i.item_category_id = ictc.sub_category_id)
       Heap Blocks: exact=1590349
       Worker 0:  actual time=9.422..58.420 rows=20471 loops=112
       Worker 1:  actual time=9.449..57.539 rows=20471 loops=112
       Worker 2:  actual time=9.751..58.129 rows=20471 loops=112
       Worker 3:  actual time=9.620..57.484 rows=20471 loops=112
       Worker 4:  actual time=8.940..57.911 rows=20471 loops=112
       Worker 5:  actual time=9.454..57.488 rows=20471 loops=112
       ->  Bitmap Index Scan on ixfk_ite_itemcategoryid
(cost=0.00..278.43 rows=29021 width=0) (actual time=4.581..4.581
rows=25363 loops=784)
     Index Cond: (i.item_category_id = ictc.sub_category_id)
     Worker 0:  actual time=4.846..4.846 rows=25363 loops=112
     Worker 1:  actual time=4.734..4.734 rows=25363 loops=112
     Worker 2:  actual time=4.803..4.803 rows=25363 loops=112
     Worker 3:  actual time=4.959..4.959 rows=25363 loops=112
     Worker 4:  actual time=4.402..4.402 rows=25363 loops=112
     Worker 5:  actual time=4.778..4.778 rows=25363 loops=112

I wonder if the additional work_mem required for Memoize is just doing
something like causing kernel page cache evictions and leading to
fewer buffers for ixfk_ite_itemcategoryid and the item table being
cached in the kernel page cache.

Maybe you could get an idea of that if you SET track_io_timing = on;
and EXPLAIN (ANALYZE, BUFFERS) both queries.

David