MIME-Version: 1.0
References: <b3d80961-c2e5-38cc-6a32-61886cdf766d@gmail.com>
 <CAFiTN-v1yDvU=X+hwfJ+55=sbgDj=_kuvbduEG-F7=BjpWcnuw@mail.gmail.com>
 <efcb213c-c87c-41f0-85b7-7fa8079df807@enterprisedb.com> <CAA=D8a1ZGWTk0RDH-LyU==RsE-217T29eprS-NBhyj+eLHyRrQ@mail.gmail.com>
In-Reply-To: <CAA=D8a1ZGWTk0RDH-LyU==RsE-217T29eprS-NBhyj+eLHyRrQ@mail.gmail.com>
From: Melanie Plageman <melanieplageman@gmail.com>
Date: Mon, 25 Mar 2024 17:11:20 -0400
Message-ID: <CAAKRu_YjBPfGp85ehY1t9NN=R9pB9k=6rztaeVkAm-OeTqUK4g@mail.gmail.com>
Subject: Re: Parallel Bitmap Heap Scan reports per-worker stats in EXPLAIN ANALYZE
To: Donghang Lin <donghanglin@gmail.com>
Cc: Tomas Vondra <tomas.vondra@enterprisedb.com>, Dilip Kumar <dilipbalaut@gmail.com>, 
	David Geier <geidav.pg@gmail.com>, 
	PostgreSQL Developers <pgsql-hackers@lists.postgresql.org>, hlinnaka@iki.fi
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
Archived-At: <https://www.postgresql.org/message-id/CAAKRu_YjBPfGp85ehY1t9NN%3DR9pB9k%3D6rztaeVkAm-OeTqUK4g%40mail.gmail.com>
Precedence: bulk

On Mon, Mar 25, 2024 at 2:29=E2=80=AFAM Donghang Lin <donghanglin@gmail.com=
> wrote:
>
>
> > On Sat, Feb 17, 2024 at 2:31=E2=80=AFPM Tomas Vondra <tomas.vondra@ente=
rprisedb.com> wrote:
> > 2) Leader vs. worker counters
> >
> > It seems to me this does nothing to add the per-worker values from "Hea=
p
> > Blocks" into the leader, which means we get stuff like this:
> >
> >     Heap Blocks: exact=3D102 lossy=3D10995
> >     Worker 0:  actual time=3D50.559..209.773 rows=3D215253 loops=3D1
> >        Heap Blocks: exact=3D207 lossy=3D19354
> >     Worker 1:  actual time=3D50.543..211.387 rows=3D162934 loops=3D1
> >        Heap Blocks: exact=3D161 lossy=3D14636
> >
> > I think this is wrong / confusing, and inconsistent with what we do for
> > other nodes. It's also inconsistent with how we deal e.g. with BUFFERS,
> > where we *do* add the values to the leader:
> >
> >     Heap Blocks: exact=3D125 lossy=3D10789
> >     Buffers: shared hit=3D11 read=3D45420
> >     Worker 0:  actual time=3D51.419..221.904 rows=3D150437 loops=3D1
> >       Heap Blocks: exact=3D136 lossy=3D13541
> >       Buffers: shared hit=3D4 read=3D13541
> >     Worker 1:  actual time=3D56.610..222.469 rows=3D229738 loops=3D1
> >       Heap Blocks: exact=3D209 lossy=3D20655
> >       Buffers: shared hit=3D4 read=3D20655
> >
> > Here it's not entirely obvious, because leader participates in the
> > execution, but once we disable leader participation, it's clearer:
> >
> >     Buffers: shared hit=3D7 read=3D45421
> >     Worker 0:  actual time=3D28.540..247.683 rows=3D309112 loops=3D1
> >       Heap Blocks: exact=3D282 lossy=3D27806
> >       Buffers: shared hit=3D4 read=3D28241
> >     Worker 1:  actual time=3D24.290..251.993 rows=3D190815 loops=3D1
> >       Heap Blocks: exact=3D188 lossy=3D17179
> >       Buffers: shared hit=3D3 read=3D17180
> >
> > Not only is "Buffers" clearly a sum of per-worker stats, but the "Heap
> > Blocks" simply disappeared because the leader does nothing and we don't
> > print zeros.
>
> Heap Blocks is specific to Bitmap Heap Scan. It seems that node specific =
stats
> do not aggregate workers' stats into leaders for some existing nodes. For=
 example,
> Memorize node for Hits, Misses, etc
>
>    ->  Nested Loop (actual rows=3D166667 loops=3D3)
>          ->  Parallel Seq Scan on t (actual rows=3D33333 loops=3D3)
>          ->  Memoize (actual rows=3D5 loops=3D100000)
>                Cache Key: t.j
>                Cache Mode: logical
>                Hits: 32991  Misses: 5  Evictions: 0  Overflows: 0  Memory=
 Usage: 2kB
>                Worker 0:  Hits: 33551  Misses: 5  Evictions: 0  Overflows=
: 0  Memory Usage: 2kB
>                Worker 1:  Hits: 33443  Misses: 5  Evictions: 0  Overflows=
: 0  Memory Usage: 2kB
>                ->  Index Scan using uj on u (actual rows=3D5 loops=3D15)
>                      Index Cond: (j =3D t.j)
>
> Sort, HashAggregate also do the same stuff.
>
> > 3) I'm not sure dealing with various EXPLAIN flags may not be entirely
> > correct. Consider this:
> >
> > EXPLAIN (ANALYZE):
> >
> >    ->  Parallel Bitmap Heap Scan on t  (...)
> >          Recheck Cond: (a < 5000)
> >          Rows Removed by Index Recheck: 246882
> >          Worker 0:  Heap Blocks: exact=3D168 lossy=3D15648
> >          Worker 1:  Heap Blocks: exact=3D302 lossy=3D29337
> >
> > EXPLAIN (ANALYZE, VERBOSE):
> >
> >    ->  Parallel Bitmap Heap Scan on public.t  (...)
> >          Recheck Cond: (t.a < 5000)
> >          Rows Removed by Index Recheck: 246882
> >          Worker 0:  actual time=3D35.067..300.882 rows=3D282108 loops=
=3D1
> >            Heap Blocks: exact=3D257 lossy=3D25358
> >          Worker 1:  actual time=3D32.827..302.224 rows=3D217819 loops=
=3D1
> >            Heap Blocks: exact=3D213 lossy=3D19627
> >
> > EXPLAIN (ANALYZE, BUFFERS):
> >
> >    ->  Parallel Bitmap Heap Scan on t  (...)
> >          Recheck Cond: (a < 5000)
> >          Rows Removed by Index Recheck: 246882
> >          Buffers: shared hit=3D7 read=3D45421
> >          Worker 0:  Heap Blocks: exact=3D236 lossy=3D21870
> >          Worker 1:  Heap Blocks: exact=3D234 lossy=3D23115
> >
> > EXPLAIN (ANALYZE, VERBOSE, BUFFERS):
> >
> >    ->  Parallel Bitmap Heap Scan on public.t  (...)
> >          Recheck Cond: (t.a < 5000)
> >          Rows Removed by Index Recheck: 246882
> >          Buffers: shared hit=3D7 read=3D45421
> >          Worker 0:  actual time=3D28.265..260.381 rows=3D261264 loops=
=3D1
> >            Heap Blocks: exact=3D260 lossy=3D23477
> >            Buffers: shared hit=3D3 read=3D23478
> >          Worker 1:  actual time=3D28.224..261.627 rows=3D238663 loops=
=3D1
> >            Heap Blocks: exact=3D210 lossy=3D21508
> >            Buffers: shared hit=3D4 read=3D21943
> >
> > Why should the per-worker buffer info be shown when combined with the
> > VERBOSE flag, and not just with BUFFERS, when the patch shows the
> > per-worker info always?
> >
>
> It seems that the general explain print framework requires verbose mode t=
o show per worker stats.
> For example, how Buffers hits, JIT are printed. While in some specific no=
des which involves parallelism,
> they always show worker blocks. This is why we see that some worker block=
s don't have buffers
> stats in non verbose mode. There are several existing nodes have the same=
 issue as what this
> patch does: memorize, sort, hashaggregate.

I don't think passing explain the BUFFERS option should impact what is
shown for bitmap heap scan lossy/exact. BUFFERS has to do with buffer
usage. "Heap Blocks" here is actually more accurately "Bitmap Blocks".
1) it is not heap specific, so at least changing it to "Table Blocks"
would be better and 2) the meaning is about whether or not the blocks
were represented lossily in the bitmap -- yes, those blocks that we
are talking about are table blocks (in contrast to index blocks), but
the important part is the bitmap.

So, BUFFERS shouldn't cause this info to show.

As for whether or not the leader number should be inclusive of all the
worker numbers, if there is a combination of options in which
per-worker stats are not  displayed, then the leader count should be
inclusive of the worker numbers. However, if the worker numbers are
always displayed, I think it is okay for the leader number to only
display its own count. Though I agree with Tomas that that can be
confusing when parallel_leader_participation is off. You end up
without a topline number.

As for whether or not per-worker stats should be displayed by default
or only with VERBOSE, it sounds like there are two different
precedents. I don't have a strong feeling one way or the other.
Whichever is most consistent.
Donghang, could you list again which plan nodes and explain options
always print per-worker stats and which only do with the VERBOSE
option?

I think there is an issue with the worker counts on rescan though. I
was playing around with this patch with one of the regression test
suite tables:

drop table if exists tenk1;
drop table if exists tenk2;
CREATE TABLE tenk1 (
    unique1        int4,
    unique2        int4,
    two            int4,
    four        int4,
    ten            int4,
    twenty        int4,
    hundred        int4,
    thousand    int4,
    twothousand    int4,
    fivethous    int4,
    tenthous    int4,
    odd            int4,
    even        int4,
    stringu1    name,
    stringu2    name,
    string4        name
) with (autovacuum_enabled =3D false);

COPY tenk1 FROM '/[source directory]/src/test/regress/data/tenk.data';

CREATE TABLE tenk2 AS SELECT * FROM tenk1;
CREATE INDEX tenk1_hundred ON tenk1 USING btree(hundred int4_ops);
VACUUM ANALYZE tenk1;
VACUUM ANALYZE tenk2;

set enable_seqscan to off;
set enable_indexscan to off;
set enable_hashjoin to off;
set enable_mergejoin to off;
set enable_material to off;
set parallel_setup_cost=3D0;
set parallel_tuple_cost=3D0;
set min_parallel_table_scan_size=3D0;
set max_parallel_workers_per_gather=3D2;
set parallel_leader_participation =3D off;
explain (analyze, costs off, verbose)
    select count(*) from tenk1, tenk2 where tenk1.hundred > 1 and
tenk2.thousand=3D0;

I don't think the worker counts are getting carried across rescans.
For this query, with parallel_leader_participation, you can see the
leader has a high number of exact heap blocks (there are 30 rescans,
so it is the sum across all of those). But the workers have low
counts. That might be normal because maybe they did less work, but if
you set parallel_leader_participation =3D off, you see the worker
numbers are still small. I did some logging and I do see workers with
counts of lossy/exact not making it into the final count. I haven't
had time to debug more, but it is worth looking into.

parallel_leader_participation =3D on
---------------------------------------------------------------------------=
--------------------
 Aggregate (actual time=3D62.321..63.178 rows=3D1 loops=3D1)
   Output: count(*)
   ->  Nested Loop (actual time=3D2.058..55.202 rows=3D98000 loops=3D1)
         ->  Seq Scan on public.tenk2 (actual time=3D0.182..3.699 rows=3D10=
 loops=3D1)
               Output: tenk2.unique1 ...
               Filter: (tenk2.thousand =3D 0)
               Rows Removed by Filter: 9990
         ->  Gather (actual time=3D1.706..4.142 rows=3D9800 loops=3D10)
               Workers Planned: 2
               Workers Launched: 2
               ->  Parallel Bitmap Heap Scan on public.tenk1 (actual
time=3D0.365..0.958 rows=3D3267 loops=3D30)
                     Recheck Cond: (tenk1.hundred > 1)
                     Heap Blocks: exact=3D1801
                     Worker 0:  actual time=3D0.033..0.414 rows=3D1993 loop=
s=3D10
                       Heap Blocks: exact=3D78 lossy=3D0
                     Worker 1:  actual time=3D0.032..0.550 rows=3D2684 loop=
s=3D10
                       Heap Blocks: exact=3D86 lossy=3D0
                     ->  Bitmap Index Scan on tenk1_hundred (actual
time=3D0.972..0.972 rows=3D9800 loops=3D10)
                           Index Cond: (tenk1.hundred > 1)

parallel_leader_participation =3D off
---------------------------------------------------------------------------=
--------------------
 Aggregate (actual time=3D84.502..84.977 rows=3D1 loops=3D1)
   Output: count(*)
   ->  Nested Loop (actual time=3D6.185..77.085 rows=3D98000 loops=3D1)
         ->  Seq Scan on public.tenk2 (actual time=3D0.182..3.709 rows=3D10=
 loops=3D1)
               Output: tenk2.unique1...
               Filter: (tenk2.thousand =3D 0)
               Rows Removed by Filter: 9990
         ->  Gather (actual time=3D5.265..6.355 rows=3D9800 loops=3D10)
               Workers Planned: 2
               Workers Launched: 2
               ->  Parallel Bitmap Heap Scan on public.tenk1 (actual
time=3D0.951..1.863 rows=3D4900 loops=3D20)
                     Recheck Cond: (tenk1.hundred > 1)
                     Worker 0:  actual time=3D0.794..1.705 rows=3D4909 loop=
s=3D10
                       Heap Blocks: exact=3D168 lossy=3D0
                     Worker 1:  actual time=3D1.108..2.021 rows=3D4891 loop=
s=3D10
                       Heap Blocks: exact=3D177 lossy=3D0
                     ->  Bitmap Index Scan on tenk1_hundred (actual
time=3D1.024..1.024 rows=3D9800 loops=3D10)
                           Index Cond: (tenk1.hundred > 1)
                           Worker 1:  actual time=3D1.024..1.024
rows=3D9800 loops=3D10

- Melanie