Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1pZSNz-00036Q-Hm for pgsql-hackers@arkaria.postgresql.org; Tue, 07 Mar 2023 08:09:27 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1pZSNx-0006AD-BY for pgsql-hackers@arkaria.postgresql.org; Tue, 07 Mar 2023 08:09:25 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1pZSNw-0006A4-Km for pgsql-hackers@lists.postgresql.org; Tue, 07 Mar 2023 08:09:25 +0000 Received: from mail-pf1-x42b.google.com ([2607:f8b0:4864:20::42b]) by makus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1pZSNt-0001yW-JV for pgsql-hackers@lists.postgresql.org; Tue, 07 Mar 2023 08:09:23 +0000 Received: by mail-pf1-x42b.google.com with SMTP id x7so5522472pff.7 for ; Tue, 07 Mar 2023 00:09:21 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20210112; t=1678176560; h=cc:to:subject:message-id:date:from:in-reply-to:references :mime-version:from:to:cc:subject:date:message-id:reply-to; bh=8p8eG2UuTwDWlKeRXJ9wEoU/NLi5koBLS5N77bRlA0U=; b=cA/c9BtLYqYV8ag+DzNcXvwrWqanaM0NAIvivbZ7k/q/IkJcojuXtD/8tU92n2RfQ+ WymcNmrvkqgzc7RVk6Ovz3Ic+dIKJq2DL7XmWn+oshmXhykGQD7lvaS5RtEw4gZMObzu dGWpeI2EDOC6mdj468J0NJZyAZmjvB4c+Dbuzbz5HD2NVoAmdGK25sveRpeZJg4f2Wxu TbcG2e7gioqQqeMjgxDvPpO0r5DLoJ08rs0AZnnX7Ge+dbAfY5f1FtfEv5jVX955WYBi Vubgm0zHbDjhSvRlr00ROLz61q5K5O5kGYdeLUfxOHTOFN8/arJCrmMwY03dnIdUJSr4 HWjw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; t=1678176560; h=cc:to:subject:message-id:date:from:in-reply-to:references :mime-version:x-gm-message-state:from:to:cc:subject:date:message-id :reply-to; bh=8p8eG2UuTwDWlKeRXJ9wEoU/NLi5koBLS5N77bRlA0U=; b=OkdM7rNYD9D2OLp5DgGpmOQIIuvKAJRHH2I+bZZZt3HKnkOW5XR8qnIelZPINgtYjz Oh4/kNDMQpl7ySXJZggtg30JvW+l9kl2FnghMpAZeOMjCEGJTBB6h0/kNt7HwypXEfuH d0gpdORbCAYpK2Es1dsQwtb9rvrQ91mFeQ7VDemo/gWegHjI+pbABqTA/xMxhT3Wa8Y8 oKnXyLCrFtJrMsFCfpKaJZM60PET3N2uDj3NLSMOaefHilAcMiM07qKZghcJKW6QeheH HVeRSaA3E612uIUXkHKRntNh99+lbPVxIb1Tz9MsuspXf1vQ/p4XeLxhn7hZ/oPYokDc rLFw== X-Gm-Message-State: AO0yUKV6S1WsyEPn1NSwAnRdc48OhA5+VkEsEDe8J5YOxen3FFUDlNmZ V7vSOP0lV0Bsy60aOiPUdnx+M7b98Y+DCaCseeo= X-Google-Smtp-Source: AK7set9u8+mwMhhO17z0noC04Q0/e+NJ6oWWV8mcX987Q+W7jAXexYgNNGtRwHpMiKguxpguLpH8215DOPkKeze2hOw= X-Received: by 2002:a05:6a00:1d9f:b0:5a8:aaa1:6c05 with SMTP id z31-20020a056a001d9f00b005a8aaa16c05mr7808600pfw.2.1678176560435; Tue, 07 Mar 2023 00:09:20 -0800 (PST) MIME-Version: 1.0 References: In-Reply-To: From: Pavel Stehule Date: Tue, 7 Mar 2023 09:08:43 +0100 Message-ID: Subject: Re: using memoize in in paralel query decreases performance To: David Rowley Cc: PostgreSQL Hackers Content-Type: multipart/alternative; boundary="000000000000c1584a05f64aed39" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --000000000000c1584a05f64aed39 Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable po 6. 3. 2023 v 22:52 odes=C3=ADlatel David Rowley n= apsal: > On Mon, 6 Mar 2023 at 21:55, Pavel Stehule > wrote: > > 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=3D285.69..41952.12 > rows=3D29021 width=3D16) (actual time=3D20.395..591.606 rows=3D20471 > loops=3D784) > Output: i.id, i.item_category_id > Recheck Cond: (i.item_category_id =3D ictc.sub_category_id) > Heap Blocks: exact=3D1590348 > Worker 0: actual time=3D20.128..591.426 rows=3D20471 loops=3D112 > Worker 1: actual time=3D20.243..591.627 rows=3D20471 loops=3D112 > Worker 2: actual time=3D20.318..591.660 rows=3D20471 loops=3D112 > Worker 3: actual time=3D21.180..591.644 rows=3D20471 loops=3D112 > Worker 4: actual time=3D20.226..591.357 rows=3D20471 loops=3D112 > Worker 5: actual time=3D20.597..591.418 rows=3D20471 loops=3D112 > -> Bitmap Index Scan on ixfk_ite_itemcategoryid > (cost=3D0.00..278.43 rows=3D29021 width=3D0) (actual time=3D14.851..14.85= 1 > rows=3D25362 loops=3D784) > Index Cond: (i.item_category_id =3D ictc.sub_category_id) > Worker 0: actual time=3D14.863..14.863 rows=3D25362 loops=3D112 > Worker 1: actual time=3D14.854..14.854 rows=3D25362 loops=3D112 > Worker 2: actual time=3D14.611..14.611 rows=3D25362 loops=3D112 > Worker 3: actual time=3D15.245..15.245 rows=3D25362 loops=3D112 > Worker 4: actual time=3D14.909..14.909 rows=3D25362 loops=3D112 > Worker 5: actual time=3D14.841..14.841 rows=3D25362 loops=3D112 > > > disabled memoize https://explain.depesz.com/s/P2rP > > -> Bitmap Heap Scan on public.item i (cost=3D285.69..41952.12 > rows=3D29021 width=3D16) (actual time=3D9.256..57.503 rows=3D20471 loops= =3D784) > Output: i.id, i.item_category_id > Recheck Cond: (i.item_category_id =3D ictc.sub_category_id) > Heap Blocks: exact=3D1590349 > Worker 0: actual time=3D9.422..58.420 rows=3D20471 loops=3D112 > Worker 1: actual time=3D9.449..57.539 rows=3D20471 loops=3D112 > Worker 2: actual time=3D9.751..58.129 rows=3D20471 loops=3D112 > Worker 3: actual time=3D9.620..57.484 rows=3D20471 loops=3D112 > Worker 4: actual time=3D8.940..57.911 rows=3D20471 loops=3D112 > Worker 5: actual time=3D9.454..57.488 rows=3D20471 loops=3D112 > -> Bitmap Index Scan on ixfk_ite_itemcategoryid > (cost=3D0.00..278.43 rows=3D29021 width=3D0) (actual time=3D4.581..4.581 > rows=3D25363 loops=3D784) > Index Cond: (i.item_category_id =3D ictc.sub_category_id) > Worker 0: actual time=3D4.846..4.846 rows=3D25363 loops=3D112 > Worker 1: actual time=3D4.734..4.734 rows=3D25363 loops=3D112 > Worker 2: actual time=3D4.803..4.803 rows=3D25363 loops=3D112 > Worker 3: actual time=3D4.959..4.959 rows=3D25363 loops=3D112 > Worker 4: actual time=3D4.402..4.402 rows=3D25363 loops=3D112 > Worker 5: actual time=3D4.778..4.778 rows=3D25363 loops=3D112 > > 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 =3D on; > and EXPLAIN (ANALYZE, BUFFERS) both queries. > https://explain.depesz.com/s/vhk0 https://explain.depesz.com/s/R5ju Regards Pavel > David > --000000000000c1584a05f64aed39 Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable


=
po 6. 3. 2023 v=C2=A022:52 odes=C3=AD= latel David Rowley <dgrowleyml@g= mail.com> napsal:
On Mon, 6 Mar 2023 at 21:55, Pavel Stehule <pavel.stehule@gmail.com>= wrote:
> 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.

=C2=A0 =C2=A0 =C2=A0 =C2=A0->=C2=A0 Bitmap Heap Scan on public.item i=C2= =A0 (cost=3D285.69..41952.12
rows=3D29021 width=3D16) (actual time=3D20.395..591.606 rows=3D20471
loops=3D784)
=C2=A0 =C2=A0 =C2=A0Output: i.id, i.item_category_id
=C2=A0 =C2=A0 =C2=A0Recheck Cond: (i.item_category_id =3D ictc.sub_category= _id)
=C2=A0 =C2=A0 =C2=A0Heap Blocks: exact=3D1590348
=C2=A0 =C2=A0 =C2=A0Worker 0:=C2=A0 actual time=3D20.128..591.426 rows=3D20= 471 loops=3D112
=C2=A0 =C2=A0 =C2=A0Worker 1:=C2=A0 actual time=3D20.243..591.627 rows=3D20= 471 loops=3D112
=C2=A0 =C2=A0 =C2=A0Worker 2:=C2=A0 actual time=3D20.318..591.660 rows=3D20= 471 loops=3D112
=C2=A0 =C2=A0 =C2=A0Worker 3:=C2=A0 actual time=3D21.180..591.644 rows=3D20= 471 loops=3D112
=C2=A0 =C2=A0 =C2=A0Worker 4:=C2=A0 actual time=3D20.226..591.357 rows=3D20= 471 loops=3D112
=C2=A0 =C2=A0 =C2=A0Worker 5:=C2=A0 actual time=3D20.597..591.418 rows=3D20= 471 loops=3D112
=C2=A0 =C2=A0 =C2=A0->=C2=A0 Bitmap Index Scan on ixfk_ite_itemcategoryi= d
(cost=3D0.00..278.43 rows=3D29021 width=3D0) (actual time=3D14.851..14.851<= br> rows=3D25362 loops=3D784)
=C2=A0 =C2=A0Index Cond: (i.item_category_id =3D ictc.sub_category_id)
=C2=A0 =C2=A0Worker 0:=C2=A0 actual time=3D14.863..14.863 rows=3D25362 loop= s=3D112
=C2=A0 =C2=A0Worker 1:=C2=A0 actual time=3D14.854..14.854 rows=3D25362 loop= s=3D112
=C2=A0 =C2=A0Worker 2:=C2=A0 actual time=3D14.611..14.611 rows=3D25362 loop= s=3D112
=C2=A0 =C2=A0Worker 3:=C2=A0 actual time=3D15.245..15.245 rows=3D25362 loop= s=3D112
=C2=A0 =C2=A0Worker 4:=C2=A0 actual time=3D14.909..14.909 rows=3D25362 loop= s=3D112
=C2=A0 =C2=A0Worker 5:=C2=A0 actual time=3D14.841..14.841 rows=3D25362 loop= s=3D112

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

->=C2=A0 Bitmap Heap Scan on public.item i=C2=A0 (cost=3D285.69..41952.1= 2
rows=3D29021 width=3D16) (actual time=3D9.256..57.503 rows=3D20471 loops=3D= 784)
=C2=A0 =C2=A0 =C2=A0 =C2=A0Output: i.id, i.item_category_id
=C2=A0 =C2=A0 =C2=A0 =C2=A0Recheck Cond: (i.item_category_id =3D ictc.sub_c= ategory_id)
=C2=A0 =C2=A0 =C2=A0 =C2=A0Heap Blocks: exact=3D1590349
=C2=A0 =C2=A0 =C2=A0 =C2=A0Worker 0:=C2=A0 actual time=3D9.422..58.420 rows= =3D20471 loops=3D112
=C2=A0 =C2=A0 =C2=A0 =C2=A0Worker 1:=C2=A0 actual time=3D9.449..57.539 rows= =3D20471 loops=3D112
=C2=A0 =C2=A0 =C2=A0 =C2=A0Worker 2:=C2=A0 actual time=3D9.751..58.129 rows= =3D20471 loops=3D112
=C2=A0 =C2=A0 =C2=A0 =C2=A0Worker 3:=C2=A0 actual time=3D9.620..57.484 rows= =3D20471 loops=3D112
=C2=A0 =C2=A0 =C2=A0 =C2=A0Worker 4:=C2=A0 actual time=3D8.940..57.911 rows= =3D20471 loops=3D112
=C2=A0 =C2=A0 =C2=A0 =C2=A0Worker 5:=C2=A0 actual time=3D9.454..57.488 rows= =3D20471 loops=3D112
=C2=A0 =C2=A0 =C2=A0 =C2=A0->=C2=A0 Bitmap Index Scan on ixfk_ite_itemca= tegoryid
(cost=3D0.00..278.43 rows=3D29021 width=3D0) (actual time=3D4.581..4.581 rows=3D25363 loops=3D784)
=C2=A0 =C2=A0 =C2=A0Index Cond: (i.item_category_id =3D ictc.sub_category_i= d)
=C2=A0 =C2=A0 =C2=A0Worker 0:=C2=A0 actual time=3D4.846..4.846 rows=3D25363= loops=3D112
=C2=A0 =C2=A0 =C2=A0Worker 1:=C2=A0 actual time=3D4.734..4.734 rows=3D25363= loops=3D112
=C2=A0 =C2=A0 =C2=A0Worker 2:=C2=A0 actual time=3D4.803..4.803 rows=3D25363= loops=3D112
=C2=A0 =C2=A0 =C2=A0Worker 3:=C2=A0 actual time=3D4.959..4.959 rows=3D25363= loops=3D112
=C2=A0 =C2=A0 =C2=A0Worker 4:=C2=A0 actual time=3D4.402..4.402 rows=3D25363= loops=3D112
=C2=A0 =C2=A0 =C2=A0Worker 5:=C2=A0 actual time=3D4.778..4.778 rows=3D25363= loops=3D112

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 =3D on;
and EXPLAIN (ANALYZE, BUFFERS) both queries.
Pavel


David
--000000000000c1584a05f64aed39--