RE: BUG #15922: Simple select with multiple exists filters returnsduplicates from a primary key field - Mailing list pgsql-bugs

Update so far: I did manage to go and replace all the UUIDs with random ones and it's still doing it, so I do have a
sanitizedversion now. No real luck with trimming down the record count though. When deleting too many records it would
changethe query plan to something not broken. Even after replacing the UUIDs and not deleting anything I ran analyze
andit came up clean, and I had to vacuum analyze for it to pick the broken plan again. (That example pasted below) The
dumpfile is at least consistently doing the same thing where immediately after load the plan chosen gives a consistent
answer,but once analyzed it gives the bad duplicates. As it stands the dump file is 130 MB (30MB zipped), is that too
bigto send in to you?
 



mnr=> analyze n, n2a, n2h;
ANALYZE
Time: 13152.868 ms (00:13.153)
mnr=> select count(*), count(distinct id) from n where exists (select 1 from n2h where n_id = n.id) and exists (select
1from n2a where n_id = n.id and a_id = '23ce1ae4-eb99-486a-924e-2fe74180a884');
 
 count | count
-------+-------
 6,531 | 6,531
(1 row)

Time: 14685.529 ms (00:14.686)
mnr=> explain analyze verbose select count(*), count(distinct id) from n where exists (select 1 from n2h where n_id =
n.id)and exists (select 1 from n2a where n_id = n.id and a_id = '23ce1ae4-eb99-486a-924e-2fe74180a884');
 
                                                                        QUERY PLAN

-----------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=57772.45..57772.46 rows=1 width=16) (actual time=877.457..877.457 rows=1 loops=1)
   Output: count(*), count(DISTINCT n.id)
   ->  Gather  (cost=6251.99..57749.48 rows=4595 width=16) (actual time=568.882..890.117 rows=6531 loops=1)
         Output: n.id
         Workers Planned: 2
         Workers Launched: 2
         ->  Nested Loop  (cost=5251.99..56289.98 rows=1915 width=16) (actual time=451.244..752.614 rows=2177 loops=3)
               Output: n.id
               Inner Unique: true
               Join Filter: (n2h.n_id = n2a.n_id)
               Worker 0: actual time=372.423..675.329 rows=2007 loops=1
               Worker 1: actual time=415.902..719.048 rows=2483 loops=1
               ->  Parallel Hash Semi Join  (cost=5251.43..15379.95 rows=23878 width=32) (actual time=67.824..159.168
rows=20442loops=3)
 
                     Output: n.id, n2h.n_id
                     Hash Cond: (n.id = n2h.n_id)
                     Worker 0: actual time=0.718..86.042 rows=18097 loops=1
                     Worker 1: actual time=26.684..123.731 rows=21898 loops=1
                     ->  Parallel Seq Scan on bug_test.n  (cost=0.00..9461.62 rows=152862 width=16) (actual
time=30.176..69.082rows=122290 loops=3)
 
                           Output: n.id
                           Worker 0: actual time=0.456..29.446 rows=107115 loops=1
                           Worker 1: actual time=25.198..58.556 rows=137270 loops=1
                     ->  Parallel Hash  (cost=4740.08..4740.08 rows=40908 width=16) (actual time=29.188..29.189
rows=32727loops=3)
 
                           Output: n2h.n_id
                           Buckets: 131072  Batches: 1  Memory Usage: 5632kB
                           Worker 0: actual time=0.049..0.049 rows=0 loops=1
                           Worker 1: actual time=0.052..0.052 rows=0 loops=1
                           ->  Parallel Seq Scan on bug_test.n2h  (cost=0.00..4740.08 rows=40908 width=16) (actual
time=22.989..61.789rows=98180 loops=1)
 
                                 Output: n2h.n_id
               ->  Index Only Scan using n2a_pkey on bug_test.n2a  (cost=0.55..1.70 rows=1 width=16) (actual
time=0.027..0.027rows=0 loops=61325)
 
                     Output: n2a.n_id, n2a.a_id
                     Index Cond: ((n2a.n_id = n.id) AND (n2a.a_id = '23ce1ae4-eb99-486a-924e-2fe74180a884'::uuid))
                     Heap Fetches: 6531
                     Worker 0: actual time=0.031..0.031 rows=0 loops=18097
                     Worker 1: actual time=0.025..0.025 rows=0 loops=21898
 Planning Time: 0.940 ms
 Execution Time: 896.125 ms
(36 rows)

Time: 898.028 ms
mnr=> vacuum full freeze verbose analyze n, n2a, n2h;
INFO:  vacuuming "bug_test.n"
INFO:  "n": found 0 removable, 366869 nonremovable row versions in 7933 pages
DETAIL:  0 dead row versions cannot be removed yet.
CPU: user: 0.10 s, system: 0.12 s, elapsed: 0.71 s.
INFO:  analyzing "bug_test.n"
INFO:  "n": scanned 1984 of 1984 pages, containing 366869 live rows and 0 dead rows; 30000 rows in sample, 366869
estimatedtotal rows
 
INFO:  vacuuming "bug_test.n2a"
INFO:  "n2a": found 3093218 removable, 1546626 nonremovable row versions in 56861 pages
DETAIL:  0 dead row versions cannot be removed yet.
CPU: user: 1.01 s, system: 0.96 s, elapsed: 3.92 s.
INFO:  analyzing "bug_test.n2a"
INFO:  "n2a": scanned 11373 of 11373 pages, containing 1546626 live rows and 0 dead rows; 30000 rows in sample, 1546626
estimatedtotal rows
 
INFO:  vacuuming "bug_test.n2h"
INFO:  "n2h": found 96 removable, 98180 nonremovable row versions in 4331 pages
DETAIL:  0 dead row versions cannot be removed yet.
CPU: user: 0.06 s, system: 0.03 s, elapsed: 0.24 s.
INFO:  analyzing "bug_test.n2h"
INFO:  "n2h": scanned 722 of 722 pages, containing 98180 live rows and 0 dead rows; 30000 rows in sample, 98180
estimatedtotal rows
 
VACUUM
Time: 30115.734 ms (00:30.116)
mnr=> select count(*), count(distinct id) from n where exists (select 1 from n2h where n_id = n.id) and exists (select
1from n2a where n_id = n.id and a_id = '23ce1ae4-eb99-486a-924e-2fe74180a884');
 
 count | count
-------+-------
 8,858 | 6,531
(1 row)

Time: 193.787 ms
mnr=> explain analyze verbose select count(*), count(distinct id) from n where exists (select 1 from n2h where n_id =
n.id)and exists (select 1 from n2a where n_id = n.id and a_id = '23ce1ae4-eb99-486a-924e-2fe74180a884');
 
                                                                                   QUERY PLAN

--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=22165.61..22165.62 rows=1 width=16) (actual time=209.476..209.477 rows=1 loops=1)
   Output: count(*), count(DISTINCT n.id)
   ->  Gather  (cost=8697.91..22141.26 rows=4871 width=16) (actual time=80.311..247.967 rows=8858 loops=1)
         Output: n.id
         Workers Planned: 2
         Workers Launched: 2
         ->  Nested Loop  (cost=7697.91..20654.16 rows=2030 width=16) (actual time=25.238..47.870 rows=2953 loops=3)
               Output: n.id
               Inner Unique: true
               Worker 0: actual time=0.135..0.135 rows=0 loops=1
               Worker 1: actual time=0.174..0.174 rows=0 loops=1
               ->  Parallel Hash Join  (cost=7697.49..19295.63 rows=2007 width=32) (actual time=25.229..31.540
rows=2953loops=3)
 
                     Output: n2a.n_id, n2h.n_id
                     Hash Cond: (n2a.n_id = n2h.n_id)
                     Worker 0: actual time=0.135..0.135 rows=0 loops=1
                     Worker 1: actual time=0.173..0.173 rows=0 loops=1
                     ->  Parallel Bitmap Heap Scan on bug_test.n2a  (cost=1001.75..12536.94 rows=12975 width=16)
(actualtime=2.951..6.906 rows=30578 loops=1)
 
                           Output: n2a.n_id, n2a.a_id
                           Recheck Cond: (n2a.a_id = '23ce1ae4-eb99-486a-924e-2fe74180a884'::uuid)
                           Heap Blocks: exact=226
                           ->  Bitmap Index Scan on n2a_a_id_n_id_idx  (cost=0.00..993.97 rows=31139 width=0) (actual
time=2.904..2.905rows=30578 loops=1)
 
                                 Index Cond: (n2a.a_id = '23ce1ae4-eb99-486a-924e-2fe74180a884'::uuid)
                     ->  Parallel Hash  (cost=6184.38..6184.38 rows=40908 width=16) (actual time=23.653..23.654
rows=32727loops=3)
 
                           Output: n2h.n_id
                           Buckets: 131072  Batches: 1  Memory Usage: 5632kB
                           Worker 0: actual time=0.041..0.041 rows=0 loops=1
                           Worker 1: actual time=0.040..0.040 rows=0 loops=1
                           ->  Parallel Index Only Scan using n2h_pkey on bug_test.n2h  (cost=0.42..6184.38 rows=40908
width=16)(actual time=0.022..49.775 rows=98180 loops=1)
 
                                 Output: n2h.n_id
                                 Heap Fetches: 98180
               ->  Index Only Scan using n_pkey on bug_test.n  (cost=0.42..0.68 rows=1 width=16) (actual
time=0.004..0.004rows=1 loops=8858)
 
                     Output: n.id
                     Index Cond: (n.id = n2h.n_id)
                     Heap Fetches: 8858
 Planning Time: 0.567 ms
 Execution Time: 255.986 ms
(36 rows)

Time: 257.446 ms
mnr=>



David Raymond | Associate Quality Analyst - MPU Addressing | TomTom | Lebanon, NH, United States
e-mail: david.raymond@tomtom.com  | office +1 603 306 8498 | www.tomtom.com






-----Original Message-----
From: David Raymond 
Sent: Tuesday, July 23, 2019 2:15 PM
To: Tom Lane <tgl@sss.pgh.pa.us>
Cc: pgsql-bugs@lists.postgresql.org
Subject: RE: BUG #15922: Simple select with multiple exists filters returns duplicates from a primary key field

Dropping the two foreign key constrains didn't seem to alter the plan. Doing the "SET max_parallel_workers_per_gather =
0;"thing did alter it and it's giving consistent results.
 

I'll see if I can manufacture a smaller dataset that produces similar results. Since I cut it down to just UUIDs I
don'tthink there'd be a problem with sending that other than the size of it all.
 


mnr=> select count(*), count(distinct id) from n where exists (select 1 from n2h where n_id = n.id) and exists (select
1
 from n2a where n_id = n.id and a_id = '00005831-4900-1200-0000-0000773ae45f');
 count | count
-------+-------
 8,858 | 6,531
(1 row)

Time: 151.132 ms
mnr=> set max_parallel_workers_per_gather = 0;
SET
Time: 0.234 ms
mnr=> select count(*), count(distinct id) from n where exists (select 1 from n2h where n_id = n.id) and exists (select
1from n2a where n_id = n.id and a_id = '00005831-4900-1200-0000-0000773ae45f');
 
 count | count
-------+-------
 6,531 | 6,531
(1 row)

Time: 457.642 ms
mnr=> explain analyze verbose select count(*), count(distinct id) from n where exists (select 1 from n2h where n_id =
n.id)and exists (select 1 from n2a where n_id = n.id and a_id = '00005831-4900-1200-0000-0000773ae45f');
 
                                                                         QUERY PLAN

------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=24232.21..24232.22 rows=1 width=16) (actual time=499.999..499.999 rows=1 loops=1)
   Output: count(*), count(DISTINCT n.id)
   ->  Hash Semi Join  (cost=16556.91..24208.38 rows=4766 width=16) (actual time=98.205..495.173 rows=6531 loops=1)
         Output: n.id
         Hash Cond: (n.id = n2h.n_id)
         ->  Hash Join  (cost=13145.86..19761.59 rows=30750 width=32) (actual time=59.001..133.273 rows=30578 loops=1)
               Output: n.id, n2a.n_id
               Inner Unique: true
               Hash Cond: (n.id = n2a.n_id)
               ->  Seq Scan on bug_test.n  (cost=0.00..5652.69 rows=366869 width=16) (actual time=0.016..36.268
rows=366869loops=1)
 
                     Output: n.id
               ->  Hash  (cost=12757.91..12757.91 rows=31036 width=16) (actual time=16.897..16.897 rows=30578 loops=1)
                     Output: n2a.n_id
                     Buckets: 32768  Batches: 1  Memory Usage: 1690kB
                     ->  Bitmap Heap Scan on bug_test.n2a  (cost=996.96..12757.91 rows=31036 width=16) (actual
time=2.533..10.997rows=30578 loops=1)
 
                           Output: n2a.n_id
                           Recheck Cond: (n2a.a_id = '00005831-4900-1200-0000-0000773ae45f'::uuid)
                           Heap Blocks: exact=2814
                           ->  Bitmap Index Scan on n2a_a_id_n_id_idx  (cost=0.00..989.20 rows=31036 width=0) (actual
time=2.190..2.190rows=30578 loops=1)
 
                                 Index Cond: (n2a.a_id = '00005831-4900-1200-0000-0000773ae45f'::uuid)
         ->  Hash  (cost=1703.80..1703.80 rows=98180 width=16) (actual time=37.623..37.623 rows=98180 loops=1)
               Output: n2h.n_id
               Buckets: 131072  Batches: 2  Memory Usage: 3325kB
               ->  Seq Scan on bug_test.n2h  (cost=0.00..1703.80 rows=98180 width=16) (actual time=0.019..15.656
rows=98180loops=1)
 
                     Output: n2h.n_id
 Planning Time: 0.760 ms
 Execution Time: 500.745 ms
(27 rows)

Time: 502.287 ms
mnr=>




David Raymond | Associate Quality Analyst - MPU Addressing | TomTom | Lebanon, NH, United States
e-mail: david.raymond@tomtom.com  | office +1 603 306 8498 | www.tomtom.com






-----Original Message-----
From: Tom Lane <tgl@sss.pgh.pa.us> 
Sent: Tuesday, July 23, 2019 1:52 PM
To: David Raymond <David.Raymond@tomtom.com>
Cc: pgsql-bugs@lists.postgresql.org
Subject: Re: BUG #15922: Simple select with multiple exists filters returns duplicates from a primary key field

PG Bug reporting form <noreply@postgresql.org> writes:
> I have a case where I'm doing a simple select from a table but I'm getting
> returned duplicates from its primary key field when I have two different
> exists statements in the where clause.

Hm.  Seems like pretty clearly a planner bug --- the second plan seems
to be missing the de-duplication step that's done by the HashAggregate
in the first plan.  But I don't want to try to reproduce it with just
the info in this report.  Can you generate dummy or sanitized data to
make a self-contained test case that reproduces the problem?

It'd be useful to know also if the problem goes away if you disable
parallel query (SET max_parallel_workers_per_gather = 0, for instance).

Also, does the issue go away if you drop either or both of the foreign
key constraints?

            regards, tom lane