BUG #13908: Query returns too few rows

seth-p@outlook.com wrote:

The following bug has been logged on the website:

Bug reference: 13908
Logged by: Seth
Email address: seth-p@outlook.com
PostgreSQL version: 9.5.0
Operating system: Windows 10
Description:

Below is a copy of a long-ish email I wrote detailing the problem. If it
doesn't come through in a reasonable format, please let me know where I can
email it. Thanks --Seth

Here's the copy Seth sent with better formatting.

--------------------------

I've only recently started using Postgresql, and have encountered what I believe to be a bug in Postgresql 9.5 on Windows 10.
Below are 6 queries that are identical except for (a) the date range in the WHERE clause, and (b) whether or not they include DISTINCT. This is as simple as I could get the queries while still reproducing the bug. The following table summarizes the number of rows returned by each query:

-----------------------------------------------------------------------------------------------------------------------------------
-- Date Range | # rows without DISTINCT | # rows with DISTINCT | Notes |
------------------------------------------------------------------------------|----------------------------------------------------
-- 2005-03-01 - 2005-07-30 | (A) 415,983 | (A-D) 416,075 | DISTINCT *increases* the number of rows returned! |
-- 2005-03-01 - 2005-04-30 | (B) 168,886 | (B-D) 168,886 | DISTINCT has no effect |
-- 2005-05-01 - 2005-07-30 | (C) 247,189 | (C-D) 247,189 | DISTINCT has no effect |
-- sum of sub-range queries | (B) + (C) 416,075 | (B-D) + (C-D) 416,075 | In both cases, sum of 2 queries equals (A-D) |
-----------------------------------------------------------------------------------------------------------------------------------

Query (A-D) (with DISTINCT) should not return more rows than query (A) (the identical query without DISTINCT), so clearly something is wrong there.
Looking at the results of the queries over the two sub-ranges strongly suggests that it is query (A) that is returning too few rows.

Beneath the queries below I also show the EXPLAIN results for queries (A), (A-D), (B), and (B-D). Notice that the plan for query (A) differs from the other three -- it appears to have an extra "Hash" (highlighted with asterisks) that the others do not.

I'm afraid I am unable to share the data, but can provide table statistics, index descriptions, or anything else that might be useful. Any suggestions for how to proceed?

Seth

-- (A) 2005-03-01 - 2005-07-30 returns 415,983 rows
select count(*) from
(
SELECT
rrr.*
FROM files.models_direct_row_asset_data rrr
INNER JOIN files.models_direct_file fff
ON fff.idx = rrr.barra_file_idx
INNER JOIN files.temp_universe_instruments uuu
ON uuu.universe_hash = 5188205190738336870 AND
uuu.barrid = rrr.barrid
WHERE
fff.file_name_model_ver = '100' AND
fff.file_name_date BETWEEN '2005-03-01' AND '2005-07-30'
) a

-- (A-D) 2005-03-01 - 2005-07-30 DISTNICT returns 416,075 rows
select count(*) from
(
SELECT DISTINCT
rrr.*
FROM files.models_direct_row_asset_data rrr
INNER JOIN files.models_direct_file fff
ON fff.idx = rrr.barra_file_idx
INNER JOIN files.temp_universe_instruments uuu
ON uuu.universe_hash = 5188205190738336870 AND
uuu.barrid = rrr.barrid
WHERE
fff.file_name_model_ver = '100' AND
fff.file_name_date BETWEEN '2005-03-01' AND '2005-07-30'
) ad

-- (B) 2005-03-01 - 2005-04-30 returns 168,886 rows
select count(*) from
(
SELECT
rrr.*
FROM files.models_direct_row_asset_data rrr
INNER JOIN files.models_direct_file fff
ON fff.idx = rrr.barra_file_idx
INNER JOIN files.temp_universe_instruments uuu
ON uuu.universe_hash = 5188205190738336870 AND
uuu.barrid = rrr.barrid
WHERE
fff.file_name_model_ver = '100' AND
fff.file_name_date BETWEEN '2005-03-01' AND '2005-04-30'
) b

-- (B-D) 2005-03-01 - 2005-04-30 DISTINCT returns 168,886 rows
select count(*) from
(
SELECT DISTINCT
rrr.*
FROM files.models_direct_row_asset_data rrr
INNER JOIN files.models_direct_file fff
ON fff.idx = rrr.barra_file_idx
INNER JOIN files.temp_universe_instruments uuu
ON uuu.universe_hash = 5188205190738336870 AND
uuu.barrid = rrr.barrid
WHERE
fff.file_name_model_ver = '100' AND
fff.file_name_date BETWEEN '2005-03-01' AND '2005-04-30'
) bd

-- (C) 2005-05-01 - 2005-07-30 returns 247,189 rows
select count(*) from
(
SELECT
rrr.*
FROM files.models_direct_row_asset_data rrr
INNER JOIN files.models_direct_file fff
ON fff.idx = rrr.barra_file_idx
INNER JOIN files.temp_universe_instruments uuu
ON uuu.universe_hash = 5188205190738336870 AND
uuu.barrid = rrr.barrid
WHERE
fff.file_name_model_ver = '100' AND
fff.file_name_date BETWEEN '2005-05-01' AND '2005-07-30'
) c

-- (C-D) 2005-05-01 - 2005-07-30 DISTINCT returns 247,189 rows
select count(*) from
(
SELECT DISTINCT
rrr.*
FROM files.models_direct_row_asset_data rrr
INNER JOIN files.models_direct_file fff
ON fff.idx = rrr.barra_file_idx
INNER JOIN files.temp_universe_instruments uuu
ON uuu.universe_hash = 5188205190738336870 AND
uuu.barrid = rrr.barrid
WHERE
fff.file_name_model_ver = '100' AND
fff.file_name_date BETWEEN '2005-05-01' AND '2005-07-30'
) cd

EPXLAIN of queries

(A)
"Aggregate (cost=1821781.18..1821781.19 rows=1 width=0)"
" -> Hash Join (cost=1811365.12..1821096.53 rows=273861 width=0)"
" Hash Cond: ((uuu.barrid)::text = (rrr.barrid)::text)"
" -> Bitmap Heap Scan on temp_universe_instruments uuu (cost=231.25..932.60 rows=8108 width=8)"
" Recheck Cond: (universe_hash = '5188205190738336870'::bigint)"
" -> Bitmap Index Scan on pk_temp_universe_instruments (cost=0.00..229.23 rows=8108 width=0)"
" Index Cond: (universe_hash = '5188205190738336870'::bigint)"
" -> Hash (cost=1796474.21..1796474.21 rows=893492 width=8)" **********************************************************
" -> Hash Join (cost=2341.15..1796474.21 rows=893492 width=8)"
" Hash Cond: (rrr.barra_file_idx = fff.idx)"
" -> Seq Scan on models_direct_row_asset_data rrr (cost=0.00..1518763.74 rows=71049174 width=12)"
" -> Hash (cost=2329.00..2329.00 rows=972 width=4)"
" -> Bitmap Heap Scan on models_direct_file fff (cost=35.33..2329.00 rows=972 width=4)"
" Recheck Cond: ((file_name_date >= '2005-03-01'::date) AND (file_name_date <= '2005-07-30'::date))"
" Filter: ((file_name_model_ver)::text = '100'::text)"
" -> Bitmap Index Scan on ix_models_direct_file_file_name_date (cost=0.00..35.08 rows=1479 width=0)"
" Index Cond: ((file_name_date >= '2005-03-01'::date) AND (file_name_date <= '2005-07-30'::date))"

(A-D)
"Aggregate (cost=1886439.23..1886439.24 rows=1 width=0)"
" -> Unique (cost=1875484.79..1883015.97 rows=273861 width=64)"
" -> Sort (cost=1875484.79..1876169.44 rows=273861 width=64)"
" Sort Key: rrr.idx, rrr.row_number, rrr.barrid, rrr.yield_pct, rrr.total_risk_pct, rrr.spec_risk_pct, rrr.hist_beta, rrr.pred_beta, rrr.data_date, rrr.barra_file_idx"
" -> Hash Join (cost=3375.10..1840453.92 rows=273861 width=64)"
" Hash Cond: ((rrr.barrid)::text = (uuu.barrid)::text)"
" -> Hash Join (cost=2341.15..1796474.21 rows=893492 width=64)"
" Hash Cond: (rrr.barra_file_idx = fff.idx)"
" -> Seq Scan on models_direct_row_asset_data rrr (cost=0.00..1518763.74 rows=71049174 width=64)"
" -> Hash (cost=2329.00..2329.00 rows=972 width=4)"
" -> Bitmap Heap Scan on models_direct_file fff (cost=35.33..2329.00 rows=972 width=4)"
" Recheck Cond: ((file_name_date >= '2005-03-01'::date) AND (file_name_date <= '2005-07-30'::date))"
" Filter: ((file_name_model_ver)::text = '100'::text)"
" -> Bitmap Index Scan on ix_models_direct_file_file_name_date (cost=0.00..35.08 rows=1479 width=0)"
" Index Cond: ((file_name_date >= '2005-03-01'::date) AND (file_name_date <= '2005-07-30'::date))"
" -> Hash (cost=932.60..932.60 rows=8108 width=8)"
" -> Bitmap Heap Scan on temp_universe_instruments uuu (cost=231.25..932.60 rows=8108 width=8)"
" Recheck Cond: (universe_hash = '5188205190738336870'::bigint)"
" -> Bitmap Index Scan on pk_temp_universe_instruments (cost=0.00..229.23 rows=8108 width=0)"
" Index Cond: (universe_hash = '5188205190738336870'::bigint)"

(B)
"Aggregate (cost=1809368.84..1809368.85 rows=1 width=0)"
" -> Hash Join (cost=2484.83..1809086.39 rows=112981 width=0)"
" Hash Cond: ((rrr.barrid)::text = (uuu.barrid)::text)"
" -> Hash Join (cost=1450.88..1790335.13 rows=368611 width=8)"
" Hash Cond: (rrr.barra_file_idx = fff.idx)"
" -> Seq Scan on models_direct_row_asset_data rrr (cost=0.00..1518763.74 rows=71049174 width=12)"
" -> Hash (cost=1445.87..1445.87 rows=401 width=4)"
" -> Bitmap Heap Scan on models_direct_file fff (cost=14.49..1445.87 rows=401 width=4)"
" Recheck Cond: ((file_name_date >= '2005-03-01'::date) AND (file_name_date <= '2005-04-30'::date))"
" Filter: ((file_name_model_ver)::text = '100'::text)"
" -> Bitmap Index Scan on ix_models_direct_file_file_name_date (cost=0.00..14.39 rows=610 width=0)"
" Index Cond: ((file_name_date >= '2005-03-01'::date) AND (file_name_date <= '2005-04-30'::date))"
" -> Hash (cost=932.60..932.60 rows=8108 width=8)"
" -> Bitmap Heap Scan on temp_universe_instruments uuu (cost=231.25..932.60 rows=8108 width=8)"
" Recheck Cond: (universe_hash = '5188205190738336870'::bigint)"
" -> Bitmap Index Scan on pk_temp_universe_instruments (cost=0.00..229.23 rows=8108 width=0)"
" Index Cond: (universe_hash = '5188205190738336870'::bigint)"

(B-D)
"Aggregate (cost=1827336.97..1827336.98 rows=1 width=0)"
" -> Unique (cost=1822817.73..1825924.71 rows=112981 width=64)"
" -> Sort (cost=1822817.73..1823100.18 rows=112981 width=64)"
" Sort Key: rrr.idx, rrr.row_number, rrr.barrid, rrr.yield_pct, rrr.total_risk_pct, rrr.spec_risk_pct, rrr.hist_beta, rrr.pred_beta, rrr.data_date, rrr.barra_file_idx"
" -> Hash Join (cost=2484.83..1809086.39 rows=112981 width=64)"
" Hash Cond: ((rrr.barrid)::text = (uuu.barrid)::text)"
" -> Hash Join (cost=1450.88..1790335.13 rows=368611 width=64)"
" Hash Cond: (rrr.barra_file_idx = fff.idx)"
" -> Seq Scan on models_direct_row_asset_data rrr (cost=0.00..1518763.74 rows=71049174 width=64)"
" -> Hash (cost=1445.87..1445.87 rows=401 width=4)"
" -> Bitmap Heap Scan on models_direct_file fff (cost=14.49..1445.87 rows=401 width=4)"
" Recheck Cond: ((file_name_date >= '2005-03-01'::date) AND (file_name_date <= '2005-04-30'::date))"
" Filter: ((file_name_model_ver)::text = '100'::text)"
" -> Bitmap Index Scan on ix_models_direct_file_file_name_date (cost=0.00..14.39 rows=610 width=0)"
" Index Cond: ((file_name_date >= '2005-03-01'::date) AND (file_name_date <= '2005-04-30'::date))"
" -> Hash (cost=932.60..932.60 rows=8108 width=8)"
" -> Bitmap Heap Scan on temp_universe_instruments uuu (cost=231.25..932.60 rows=8108 width=8)"
" Recheck Cond: (universe_hash = '5188205190738336870'::bigint)"
" -> Bitmap Index Scan on pk_temp_universe_instruments (cost=0.00..229.23 rows=8108 width=0)"
" Index Cond: (universe_hash = '5188205190738336870'::bigint)"

--
�lvaro Herrera http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

seth-p@outlook.com writes:

Query (A-D) (with DISTINCT) should not return more rows than query (A) (the
identical query without DISTINCT), so clearly something is wrong there.

That does seem fishy, but unless you can provide a self-contained test
case, it's unlikely that we are going to be able to magically locate
the problem. I'd suggest seeing if you can reproduce the issue with
some obfuscated or randomly-generated data.

regards, tom lane

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

On Tue, Feb 2, 2016 at 3:52 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

seth-p@outlook.com writes:

Query (A-D) (with DISTINCT) should not return more rows than query (A)

(the

identical query without DISTINCT), so clearly something is wrong there.

That does seem fishy, but unless you can provide a self-contained test
case, it's unlikely that we are going to be able to magically locate
the problem. I'd suggest seeing if you can reproduce the issue with
some obfuscated or randomly-generated data.

​While Tom is correct I'd like to make a couple of points...

It apparently isn't the DISTINCT query that is increasing the count of rows
but rather than the non-DISTINCT version fails to return/count as many as
are actually present - but only when dealing with the entire range...

​Lacking a reproducible test case you really need to at least supply an
EXPLAIN ANALYZE so that actual row counts at each node can be observed.

The note about the apparent extra HASH first made me think that there must
be some kind of hash collision involved in the data - apparently one that
occurs between data points in B and C but not within B or within C...but I
fear this might be a red herring. But if it is a collision then the odds
of random data exhibiting the problem are quite slim...

David J.

Below are the EXPLAIN ANALYZE results. I will try to reproduce the problem with isolated/toy data, but that may take a while.

Query A (results believed to be incorrect)

"Aggregate (cost=1821781.18..1821781.19 rows=1 width=0) (actual time=15887.259..15887.259 rows=1 loops=1)"
" -> Hash Join (cost=1811365.12..1821096.53 rows=273861 width=0) (actual time=15562.422..15871.122 rows=415983 loops=1)"
" Hash Cond: ((uuu.barrid)::text = (rrr.barrid)::text)"
" -> Bitmap Heap Scan on temp_universe_instruments uuu (cost=231.25..932.60 rows=8108 width=8) (actual time=0.445..1.281 rows=7993 loops=1)"
" Recheck Cond: (universe_hash = '5188205190738336870'::bigint)"
" Heap Blocks: exact=44"
" -> Bitmap Index Scan on pk_temp_universe_instruments (cost=0.00..229.23 rows=8108 width=0) (actual time=0.436..0.436 rows=7993 loops=1)"
" Index Cond: (universe_hash = '5188205190738336870'::bigint)"
" -> Hash (cost=1796474.21..1796474.21 rows=893492 width=8) (actual time=15556.367..15556.367 rows=1275138 loops=1)"
" Buckets: 131072 (originally 131072) Batches: 32 (originally 16) Memory Usage: 3073kB"
" -> Hash Join (cost=2341.15..1796474.21 rows=893492 width=8) (actual time=5761.544..15363.787 rows=1275138 loops=1)"
" Hash Cond: (rrr.barra_file_idx = fff.idx)"
" -> Seq Scan on models_direct_row_asset_data rrr (cost=0.00..1518763.74 rows=71049174 width=12) (actual time=0.002..6316.855 rows=71098547 loops=1)"
" -> Hash (cost=2329.00..2329.00 rows=972 width=4) (actual time=0.613..0.613 rows=964 loops=1)"
" Buckets: 1024 Batches: 1 Memory Usage: 42kB"
" -> Bitmap Heap Scan on models_direct_file fff (cost=35.33..2329.00 rows=972 width=4) (actual time=0.092..0.516 rows=964 loops=1)"
" Recheck Cond: ((file_name_date >= '2005-03-01'::date) AND (file_name_date <= '2005-07-30'::date))"
" Filter: ((file_name_model_ver)::text = '100'::text)"
" Rows Removed by Filter: 540"
" Heap Blocks: exact=66"
" -> Bitmap Index Scan on ix_models_direct_file_file_name_date (cost=0.00..35.08 rows=1479 width=0) (actual time=0.082..0.082 rows=1504 loops=1)"
" Index Cond: ((file_name_date >= '2005-03-01'::date) AND (file_name_date <= '2005-07-30'::date))"
"Planning time: 0.866 ms"
"Execution time: 15887.534 ms"

Query A-D

"Aggregate (cost=1886439.23..1886439.24 rows=1 width=0) (actual time=15927.999..15927.999 rows=1 loops=1)"
" -> Unique (cost=1875484.79..1883015.97 rows=273861 width=64) (actual time=15745.902..15911.374 rows=416075 loops=1)"
" -> Sort (cost=1875484.79..1876169.44 rows=273861 width=64) (actual time=15745.901..15794.280 rows=416075 loops=1)"
" Sort Key: rrr.idx, rrr.row_number, rrr.barrid, rrr.yield_pct, rrr.total_risk_pct, rrr.spec_risk_pct, rrr.hist_beta, rrr.pred_beta, rrr.data_date, rrr.barra_file_idx"
" Sort Method: external sort Disk: 30080kB"
" -> Hash Join (cost=3375.10..1840453.92 rows=273861 width=64) (actual time=5718.845..15502.041 rows=416075 loops=1)"
" Hash Cond: ((rrr.barrid)::text = (uuu.barrid)::text)"
" -> Hash Join (cost=2341.15..1796474.21 rows=893492 width=64) (actual time=5716.653..15310.931 rows=1275138 loops=1)"
" Hash Cond: (rrr.barra_file_idx = fff.idx)"
" -> Seq Scan on models_direct_row_asset_data rrr (cost=0.00..1518763.74 rows=71049174 width=64) (actual time=0.002..6262.125 rows=71098547 loops=1)"
" -> Hash (cost=2329.00..2329.00 rows=972 width=4) (actual time=0.630..0.630 rows=964 loops=1)"
" Buckets: 1024 Batches: 1 Memory Usage: 42kB"
" -> Bitmap Heap Scan on models_direct_file fff (cost=35.33..2329.00 rows=972 width=4) (actual time=0.101..0.535 rows=964 loops=1)"
" Recheck Cond: ((file_name_date >= '2005-03-01'::date) AND (file_name_date <= '2005-07-30'::date))"
" Filter: ((file_name_model_ver)::text = '100'::text)"
" Rows Removed by Filter: 540"
" Heap Blocks: exact=66"
" -> Bitmap Index Scan on ix_models_direct_file_file_name_date (cost=0.00..35.08 rows=1479 width=0) (actual time=0.092..0.092 rows=1504 loops=1)"
" Index Cond: ((file_name_date >= '2005-03-01'::date) AND (file_name_date <= '2005-07-30'::date))"
" -> Hash (cost=932.60..932.60 rows=8108 width=8) (actual time=2.085..2.085 rows=7993 loops=1)"
" Buckets: 8192 Batches: 1 Memory Usage: 377kB"
" -> Bitmap Heap Scan on temp_universe_instruments uuu (cost=231.25..932.60 rows=8108 width=8) (actual time=0.463..1.255 rows=7993 loops=1)"
" Recheck Cond: (universe_hash = '5188205190738336870'::bigint)"
" Heap Blocks: exact=44"
" -> Bitmap Index Scan on pk_temp_universe_instruments (cost=0.00..229.23 rows=8108 width=0) (actual time=0.450..0.450 rows=7993 loops=1)"
" Index Cond: (universe_hash = '5188205190738336870'::bigint)"
"Planning time: 0.889 ms"
"Execution time: 15932.735 ms"

Query B

"Aggregate (cost=1809368.84..1809368.85 rows=1 width=0) (actual time=15031.329..15031.330 rows=1 loops=1)"
" -> Hash Join (cost=2484.83..1809086.39 rows=112981 width=0) (actual time=5653.925..15024.207 rows=168886 loops=1)"
" Hash Cond: ((rrr.barrid)::text = (uuu.barrid)::text)"
" -> Hash Join (cost=1450.88..1790335.13 rows=368611 width=8) (actual time=5651.724..14946.845 rows=533241 loops=1)"
" Hash Cond: (rrr.barra_file_idx = fff.idx)"
" -> Seq Scan on models_direct_row_asset_data rrr (cost=0.00..1518763.74 rows=71049174 width=12) (actual time=0.002..6188.050 rows=71098547 loops=1)"
" -> Hash (cost=1445.87..1445.87 rows=401 width=4) (actual time=0.261..0.261 rows=391 loops=1)"
" Buckets: 1024 Batches: 1 Memory Usage: 22kB"
" -> Bitmap Heap Scan on models_direct_file fff (cost=14.49..1445.87 rows=401 width=4) (actual time=0.043..0.218 rows=391 loops=1)"
" Recheck Cond: ((file_name_date >= '2005-03-01'::date) AND (file_name_date <= '2005-04-30'::date))"
" Filter: ((file_name_model_ver)::text = '100'::text)"
" Rows Removed by Filter: 219"
" Heap Blocks: exact=34"
" -> Bitmap Index Scan on ix_models_direct_file_file_name_date (cost=0.00..14.39 rows=610 width=0) (actual time=0.036..0.036 rows=610 loops=1)"
" Index Cond: ((file_name_date >= '2005-03-01'::date) AND (file_name_date <= '2005-04-30'::date))"
" -> Hash (cost=932.60..932.60 rows=8108 width=8) (actual time=2.108..2.108 rows=7993 loops=1)"
" Buckets: 8192 Batches: 1 Memory Usage: 377kB"
" -> Bitmap Heap Scan on temp_universe_instruments uuu (cost=231.25..932.60 rows=8108 width=8) (actual time=0.460..1.280 rows=7993 loops=1)"
" Recheck Cond: (universe_hash = '5188205190738336870'::bigint)"
" Heap Blocks: exact=44"
" -> Bitmap Index Scan on pk_temp_universe_instruments (cost=0.00..229.23 rows=8108 width=0) (actual time=0.452..0.452 rows=7993 loops=1)"
" Index Cond: (universe_hash = '5188205190738336870'::bigint)"
"Planning time: 0.850 ms"
"Execution time: 15031.386 ms"

Query B-D

"Aggregate (cost=1827336.97..1827336.98 rows=1 width=0) (actual time=15193.952..15193.952 rows=1 loops=1)"
" -> Unique (cost=1822817.73..1825924.71 rows=112981 width=64) (actual time=15122.057..15187.357 rows=168886 loops=1)"
" -> Sort (cost=1822817.73..1823100.18 rows=112981 width=64) (actual time=15122.056..15141.047 rows=168886 loops=1)"
" Sort Key: rrr.idx, rrr.row_number, rrr.barrid, rrr.yield_pct, rrr.total_risk_pct, rrr.spec_risk_pct, rrr.hist_beta, rrr.pred_beta, rrr.data_date, rrr.barra_file_idx"
" Sort Method: external sort Disk: 12208kB"
" -> Hash Join (cost=2484.83..1809086.39 rows=112981 width=64) (actual time=5655.552..15024.729 rows=168886 loops=1)"
" Hash Cond: ((rrr.barrid)::text = (uuu.barrid)::text)"
" -> Hash Join (cost=1450.88..1790335.13 rows=368611 width=64) (actual time=5653.397..14944.115 rows=533241 loops=1)"
" Hash Cond: (rrr.barra_file_idx = fff.idx)"
" -> Seq Scan on models_direct_row_asset_data rrr (cost=0.00..1518763.74 rows=71049174 width=64) (actual time=0.002..6210.401 rows=71098547 loops=1)"
" -> Hash (cost=1445.87..1445.87 rows=401 width=4) (actual time=0.268..0.268 rows=391 loops=1)"
" Buckets: 1024 Batches: 1 Memory Usage: 22kB"
" -> Bitmap Heap Scan on models_direct_file fff (cost=14.49..1445.87 rows=401 width=4) (actual time=0.053..0.236 rows=391 loops=1)"
" Recheck Cond: ((file_name_date >= '2005-03-01'::date) AND (file_name_date <= '2005-04-30'::date))"
" Filter: ((file_name_model_ver)::text = '100'::text)"
" Rows Removed by Filter: 219"
" Heap Blocks: exact=34"
" -> Bitmap Index Scan on ix_models_direct_file_file_name_date (cost=0.00..14.39 rows=610 width=0) (actual time=0.047..0.047 rows=610 loops=1)"
" Index Cond: ((file_name_date >= '2005-03-01'::date) AND (file_name_date <= '2005-04-30'::date))"
" -> Hash (cost=932.60..932.60 rows=8108 width=8) (actual time=2.050..2.050 rows=7993 loops=1)"
" Buckets: 8192 Batches: 1 Memory Usage: 377kB"
" -> Bitmap Heap Scan on temp_universe_instruments uuu (cost=231.25..932.60 rows=8108 width=8) (actual time=0.467..1.239 rows=7993 loops=1)"
" Recheck Cond: (universe_hash = '5188205190738336870'::bigint)"
" Heap Blocks: exact=44"
" -> Bitmap Index Scan on pk_temp_universe_instruments (cost=0.00..229.23 rows=8108 width=0) (actual time=0.457..0.457 rows=7993 loops=1)"
" Index Cond: (universe_hash = '5188205190738336870'::bigint)"
"Planning time: 0.883 ms"
"Execution time: 15197.640 ms"

Query C

"Aggregate (cost=1818525.28..1818525.29 rows=1 width=0) (actual time=15181.269..15181.269 rows=1 loops=1)"
" -> Hash Join (cost=2826.27..1818128.02 rows=158907 width=0) (actual time=5814.662..15170.804 rows=247189 loops=1)"
" Hash Cond: ((rrr.barrid)::text = (uuu.barrid)::text)"
" -> Hash Join (cost=1792.32..1792174.92 rows=518446 width=8) (actual time=5812.495..15061.248 rows=741897 loops=1)"
" Hash Cond: (rrr.barra_file_idx = fff.idx)"
" -> Seq Scan on models_direct_row_asset_data rrr (cost=0.00..1518763.74 rows=71049174 width=12) (actual time=0.002..6233.423 rows=71098547 loops=1)"
" -> Hash (cost=1785.27..1785.27 rows=564 width=4) (actual time=0.367..0.367 rows=573 loops=1)"
" Buckets: 1024 Batches: 1 Memory Usage: 29kB"
" -> Bitmap Heap Scan on models_direct_file fff (cost=21.01..1785.27 rows=564 width=4) (actual time=0.058..0.305 rows=573 loops=1)"
" Recheck Cond: ((file_name_date >= '2005-05-01'::date) AND (file_name_date <= '2005-07-30'::date))"
" Filter: ((file_name_model_ver)::text = '100'::text)"
" Rows Removed by Filter: 321"
" Heap Blocks: exact=43"
" -> Bitmap Index Scan on ix_models_direct_file_file_name_date (cost=0.00..20.87 rows=858 width=0) (actual time=0.051..0.051 rows=894 loops=1)"
" Index Cond: ((file_name_date >= '2005-05-01'::date) AND (file_name_date <= '2005-07-30'::date))"
" -> Hash (cost=932.60..932.60 rows=8108 width=8) (actual time=2.066..2.066 rows=7993 loops=1)"
" Buckets: 8192 Batches: 1 Memory Usage: 377kB"
" -> Bitmap Heap Scan on temp_universe_instruments uuu (cost=231.25..932.60 rows=8108 width=8) (actual time=0.463..1.228 rows=7993 loops=1)"
" Recheck Cond: (universe_hash = '5188205190738336870'::bigint)"
" Heap Blocks: exact=44"
" -> Bitmap Index Scan on pk_temp_universe_instruments (cost=0.00..229.23 rows=8108 width=0) (actual time=0.454..0.454 rows=7993 loops=1)"
" Index Cond: (universe_hash = '5188205190738336870'::bigint)"
"Planning time: 0.866 ms"
"Execution time: 15181.330 ms"

Query C-D

"Aggregate (cost=1844190.13..1844190.14 rows=1 width=0) (actual time=15495.232..15495.233 rows=1 loops=1)"
" -> Unique (cost=1837833.85..1842203.79 rows=158907 width=64) (actual time=15388.762..15485.467 rows=247189 loops=1)"
" -> Sort (cost=1837833.85..1838231.12 rows=158907 width=64) (actual time=15388.761..15416.951 rows=247189 loops=1)"
" Sort Key: rrr.idx, rrr.row_number, rrr.barrid, rrr.yield_pct, rrr.total_risk_pct, rrr.spec_risk_pct, rrr.hist_beta, rrr.pred_beta, rrr.data_date, rrr.barra_file_idx"
" Sort Method: external sort Disk: 17880kB"
" -> Hash Join (cost=2826.27..1818128.02 rows=158907 width=64) (actual time=5832.453..15240.599 rows=247189 loops=1)"
" Hash Cond: ((rrr.barrid)::text = (uuu.barrid)::text)"
" -> Hash Join (cost=1792.32..1792174.92 rows=518446 width=64) (actual time=5830.312..15121.828 rows=741897 loops=1)"
" Hash Cond: (rrr.barra_file_idx = fff.idx)"
" -> Seq Scan on models_direct_row_asset_data rrr (cost=0.00..1518763.74 rows=71049174 width=64) (actual time=0.002..6244.816 rows=71098547 loops=1)"
" -> Hash (cost=1785.27..1785.27 rows=564 width=4) (actual time=0.360..0.360 rows=573 loops=1)"
" Buckets: 1024 Batches: 1 Memory Usage: 29kB"
" -> Bitmap Heap Scan on models_direct_file fff (cost=21.01..1785.27 rows=564 width=4) (actual time=0.055..0.310 rows=573 loops=1)"
" Recheck Cond: ((file_name_date >= '2005-05-01'::date) AND (file_name_date <= '2005-07-30'::date))"
" Filter: ((file_name_model_ver)::text = '100'::text)"
" Rows Removed by Filter: 321"
" Heap Blocks: exact=43"
" -> Bitmap Index Scan on ix_models_direct_file_file_name_date (cost=0.00..20.87 rows=858 width=0) (actual time=0.048..0.048 rows=894 loops=1)"
" Index Cond: ((file_name_date >= '2005-05-01'::date) AND (file_name_date <= '2005-07-30'::date))"
" -> Hash (cost=932.60..932.60 rows=8108 width=8) (actual time=2.043..2.043 rows=7993 loops=1)"
" Buckets: 8192 Batches: 1 Memory Usage: 377kB"
" -> Bitmap Heap Scan on temp_universe_instruments uuu (cost=231.25..932.60 rows=8108 width=8) (actual time=0.466..1.240 rows=7993 loops=1)"
" Recheck Cond: (universe_hash = '5188205190738336870'::bigint)"
" Heap Blocks: exact=44"
" -> Bitmap Index Scan on pk_temp_universe_instruments (cost=0.00..229.23 rows=8108 width=0) (actual time=0.456..0.456 rows=7993 loops=1)"
" Index Cond: (universe_hash = '5188205190738336870'::bigint)"
"Planning time: 0.876 ms"
"Execution time: 15499.128 ms"

________________________________
From: David G. Johnston <david.g.johnston@gmail.com>
Sent: Tuesday, February 2, 2016 6:27 PM
To: Tom Lane
Cc: seth-p@outlook.com; pgsql-bugs@postgresql.org
Subject: Re: [BUGS] BUG #13908: Query returns too few rows

On Tue, Feb 2, 2016 at 3:52 PM, Tom Lane <tgl@sss.pgh.pa.us<mailto:tgl@sss.pgh.pa.us>> wrote:
seth-p@outlook.com<mailto:seth-p@outlook.com> writes:

Query (A-D) (with DISTINCT) should not return more rows than query (A) (the
identical query without DISTINCT), so clearly something is wrong there.

That does seem fishy, but unless you can provide a self-contained test
case, it's unlikely that we are going to be able to magically locate
the problem. I'd suggest seeing if you can reproduce the issue with
some obfuscated or randomly-generated data.

?While Tom is correct I'd like to make a couple of points...

It apparently isn't the DISTINCT query that is increasing the count of rows but rather than the non-DISTINCT version fails to return/count as many as are actually present - but only when dealing with the entire range...

?Lacking a reproducible test case you really need to at least supply an EXPLAIN ANALYZE so that actual row counts at each node can be observed.

The note about the apparent extra HASH first made me think that there must be some kind of hash collision involved in the data - apparently one that occurs between data points in B and C but not within B or within C...but I fear this might be a red herring. But if it is a collision then the odds of random data exhibiting the problem are quite slim...

David J.

On Tue, Feb 2, 2016 at 7:05 PM, Seth P <seth-p@outlook.com> wrote:

Below are the EXPLAIN ANALYZE results. I will try to reproduce the problem
with isolated/toy data, but that may take a while.

Nothing obvious...what type of column is "barrid" and, if it is indeed
textual, can you provide some example values?

David J.

"barrid" is "character varying(8) NOT NULL", and some examples are 'CANCEJ1' and 'USA06Z1'.

In case it helps, the following are the table definitions and all the constraints and indices I have on the three tables:

files.models_direct_file ("fff")

CREATE TABLE files.models_direct_file
(
idx serial NOT NULL,
file_class character varying(32) NOT NULL,
file_name character varying(64) NOT NULL,
file_name_data character varying(32) NOT NULL,
file_name_date date,
header_columns character varying(32)[],
file_created timestamp without time zone,
file_imported_to_db timestamp without time zone,
num_rows integer,
file_name_model character varying(8) NOT NULL,
file_name_model_horizon character varying(1) NOT NULL,
file_name_exchange character varying(8) NOT NULL,
file_name_etf character varying(12) NOT NULL,
file_name_model_forecast_horizon character varying(1) NOT NULL,
file_name_model_speed character varying(1) NOT NULL,
file_name_model_ver character varying(3) NOT NULL,
header_vendor character varying(16),
header_model_ver character varying(3),
header_release_date date,
header_release_datetime timestamp without time zone,
header_last_modified_date date,
header_bim_ver character varying(4),
header_bimef_ver character varying(4),
CONSTRAINT pk_models_direct_file PRIMARY KEY (idx)
)
WITH (
OIDS=FALSE
);

CREATE INDEX ix_models_direct_file_file_name_date
ON files.models_direct_file
USING btree
(file_name_date);

CREATE UNIQUE INDEX ix_models_direct_file_unique
ON files.models_direct_file
USING btree
(file_name COLLATE pg_catalog."default");

files.models_direct_row_asset_data ("rrr")

CREATE TABLE files.models_direct_row_asset_data
(
idx serial NOT NULL,
row_number integer NOT NULL,
barrid character varying(8) NOT NULL,
yield_pct double precision,
total_risk_pct double precision,
spec_risk_pct double precision,
hist_beta double precision,
pred_beta double precision,
data_date date NOT NULL,
barra_file_idx integer NOT NULL,
CONSTRAINT pk_models_direct_row_asset_data PRIMARY KEY (idx),
CONSTRAINT fk_models_direct_row_asset_data_barra_file_idx_models_direct_fi FOREIGN KEY (barra_file_idx)
REFERENCES files.models_direct_file (idx) MATCH SIMPLE
ON UPDATE CASCADE ON DELETE CASCADE DEFERRABLE INITIALLY IMMEDIATE
)
WITH (
OIDS=FALSE
);

CREATE INDEX ix_models_direct_row_asset_data_barrid
ON files.models_direct_row_asset_data
USING btree
(barrid COLLATE pg_catalog."default");

CREATE INDEX ix_models_direct_row_asset_data_data_date
ON files.models_direct_row_asset_data
USING btree
(data_date);

CREATE UNIQUE INDEX ix_models_direct_row_asset_data_unique
ON files.models_direct_row_asset_data
USING btree
(barra_file_idx, row_number);

temp_universe_instruments ("uuu")

CREATE TABLE files.temp_universe_instruments
(
universe_hash bigserial NOT NULL,
barrid character varying(8) NOT NULL,
CONSTRAINT pk_temp_universe_instruments PRIMARY KEY (universe_hash, barrid)
)
WITH (
OIDS=FALSE
);

no indices

________________________________
From: David G. Johnston <david.g.johnston@gmail.com>
Sent: Tuesday, February 2, 2016 10:04 PM
To: Seth P
Cc: Tom Lane; pgsql-bugs@postgresql.org
Subject: Re: [BUGS] BUG #13908: Query returns too few rows

On Tue, Feb 2, 2016 at 7:05 PM, Seth P <seth-p@outlook.com<mailto:seth-p@outlook.com>> wrote:

Below are the EXPLAIN ANALYZE results. I will try to reproduce the problem with isolated/toy data, but that may take a while.

Nothing obvious...what type of column is "barrid" and, if it is indeed textual, can you provide some example values?

David J.

On Tue, Feb 2, 2016 at 9:41 PM, Seth P <seth-p@outlook.com> wrote:

"barrid" is "character varying(8) NOT NULL", and some examples are
'CANCEJ1' and 'USA06Z1'.

Consider...

​CREATE TABLE "rrr_temp" AS SELECT ​idx, barrid FROM "rrr" AND ...; --see
note below
CREATE TABLE "uuu_temp" AS SELECT barrid FROM "uuu" WHERE universe_hash =
#; -- should get 7,993 record

modify the WHERE clause for "rrr_temp" so you copy in the same records into
rrr_temp as matched in the full query: # 1,275,138 from the explain analyze
for A (and A-D too)

Now run simple join sub-queries inside your count(*)

If it repeats you should be able to supply the temporary table data as
unless barrid values are somehow super-secret. You do not have to send the
data to the public list either - you can send it privately to someone (not
me, Tom should be good but confirm before sending).

Hope that helps.

David J.

Adding back the list so that everyone can see the latest finding. Adding
in the original bug block too...
​

The following bug has been logged on the website:

Bug reference: 13908
Logged by: Seth
Email address: seth-p@outlook.com
PostgreSQL version: 9.5.0
Operating system: Windows 10
Description:

*​Next request, Seth*: please restore your dump into a clean database and
see what results you get. Also, please run:
SELECT version(); and provide the results.​

​My findings
​- there is​
a smaller count for
​the ​
DISTINCT than without.​

​
I successfully restored your pg_dump file​, vacuum analyzed it, then ran
the two counting queries. Here are my results.

The DISTINCT plan has an actual count of 415,874 while the non-DISTINCT
plan resulted in 415,967; *thus DISTINCT removed 93 duplicates.*

Looking back at your most recent email your numbers are 415,983 and
416,009; an increase of 26 by adding DISTINCT...and not matching either of
these numbers.

*version*
PostgreSQL 9.5.0 on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu
4.8.2-19ubuntu1) 4.8.2, 64-bit

​Installed into the default postgres database which has an encoding of
en_US.UTF-8

(NB: had to use pg_database as I couldn't located a psql meta-command to
list databases...am I missing something here?)
​
The follow are the results of my EXPLAIN ANALYZE confirmed by running the
actual count queries.

QUERY PLAN
Aggregate (cost=1464939.22..1464939.23 rows=1 width=0) (actual
time=151609.418..151609.419 rows=1 loops=1)
* -> Hash Join (cost=1454885.92..1464269.54 rows=267870 width=0) (actual
time=150567.030..151188.740 rows=415967 loops=1)*
Hash Cond: ((uuu.bababa)::text = (rrr.bababa)::text)
-> Index Only Scan using pk_uuu on uuu (cost=0.42..270.01
rows=8091 width=8) (actual time=0.019..9.337 rows=7993 loops=1)
Index Cond: (universe_hash = '5188205190738336870'::bigint)
Heap Fetches: 0
-> Hash (cost=1440572.59..1440572.59 rows=872393 width=8) (actual
time=150566.397..150566.397 rows=1275138 loops=1)
Buckets: 131072 (originally 131072) Batches: 32 (originally
16) Memory Usage: 3073kB
-> Hash Join (cost=819.47..1440572.59 rows=872393 width=8)
(actual time=11865.529..149038.533 rows=1275138 loops=1)
Hash Cond: (rrr.fff_idx = fff.idx)
-> Seq Scan on rrr (cost=0.00..1164409.32
rows=71098632 width=12) (actual time=0.006..73136.366 rows=71098547 loops=1)
-> Hash (cost=807.58..807.58 rows=951 width=4)
(actual time=3.458..3.458 rows=964 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 42kB
-> Bitmap Heap Scan on fff (cost=30.98..807.58
rows=951 width=4) (actual time=0.133..1.843 rows=964 loops=1)
Recheck Cond: ((file_name_date >=
'2005-03-01'::date) AND (file_name_date <= '2005-07-30'::date))
Filter: ((file_name_model_ver)::text =
'100'::text)
Rows Removed by Filter: 540
Heap Blocks: exact=30
-> Bitmap Index Scan on
ix_fff_file_name_date (cost=0.00..30.74 rows=1445 width=0) (actual
time=0.117..0.117 rows=1504 loops=1)
Index Cond: ((file_name_date >=
'2005-03-01'::date) AND (file_name_date <= '2005-07-30'::date))
Planning time: 1.727 ms
Execution time: 151609.494 ms

QUERY PLAN
Aggregate (cost=1504689.02..1504689.03 rows=1 width=0) (actual
time=155253.758..155253.759 rows=1 loops=1)
* -> Unique (cost=1497322.60..1501340.65 rows=267870 width=24) (actual
time=153375.583..154829.461 rows=415874 loops=1)*
-> Sort (cost=1497322.60..1497992.27 rows=267870 width=24)
(actual time=153375.578..153919.245 rows=415874 loops=1)
Sort Key: rrr.idx, rrr.row_number, rrr.bababa, rrr.data_date,
rrr.fff_idx
Sort Method: external merge Disk: 13784kB
-> Hash Join (cost=1456589.92..1467677.54 rows=267870
width=24) (actual time=151982.289..152665.099 rows=415874 loops=1)
Hash Cond: ((uuu.bababa)::text = (rrr.bababa)::text)
-> Index Only Scan using pk_uuu on uuu
(cost=0.42..270.01 rows=8091 width=8) (actual time=0.012..9.359 rows=7993
loops=1)
Index Cond: (universe_hash =
'5188205190738336870'::bigint)
Heap Fetches: 0
-> Hash (cost=1440572.59..1440572.59 rows=872393
width=24) (actual time=151981.919..151981.919 rows=1275138 loops=1)
Buckets: 65536 (originally 65536) Batches: 32
(originally 16) Memory Usage: 3585kB
-> Hash Join (cost=819.47..1440572.59
rows=872393 width=24) (actual time=12037.549..150408.756 rows=1275138
loops=1)
Hash Cond: (rrr.fff_idx = fff.idx)
-> Seq Scan on rrr (cost=0.00..1164409.32
rows=71098632 width=24) (actual time=0.004..73673.708 rows=71098547 loops=1)
-> Hash (cost=807.58..807.58 rows=951
width=4) (actual time=2.360..2.360 rows=964 loops=1)
Buckets: 1024 Batches: 1 Memory
Usage: 42kB
-> Bitmap Heap Scan on fff
(cost=30.98..807.58 rows=951 width=4) (actual time=0.123..1.293 rows=964
loops=1)
Recheck Cond: ((file_name_date

= '2005-03-01'::date) AND (file_name_date <= '2005-07-30'::date))

Filter:
((file_name_model_ver)::text = '100'::text)
Rows Removed by Filter: 540
Heap Blocks: exact=30
-> Bitmap Index Scan on
ix_fff_file_name_date (cost=0.00..30.74 rows=1445 width=0) (actual
time=0.111..0.111 rows=1504 loops=1)
Index Cond:
((file_name_date >= '2005-03-01'::date) AND (file_name_date <=
'2005-07-30'::date))
Planning time: 0.668 ms
Execution time: 155255.933 ms

Tom, we really need you to chime in here.

On Thu, Feb 4, 2016 at 2:58 PM, David G. Johnston <
david.g.johnston@gmail.com> wrote:

Adding back the list so that everyone can see the latest finding. Adding
in the original bug block too...
​

The following bug has been logged on the website:

Bug reference: 13908
Logged by: Seth
Email address: seth-p@outlook.com
PostgreSQL version: 9.5.0
Operating system: Windows 10
Description:

* -> Unique (cost=1497322.60..1501340.65 rows=267870 width=24) (actual
time=153375.583..154829.461 rows=415874 loops=1)*

​Without running any DML I just got this result on the DISTINCT query...​

*​ -> Unique (cost=1519634.64..1520973.99 rows=200 width=48) (actual
time=161695.425..163174.422 rows=416075 loops=1)*
​
There is nothing in the SQL​ itself that would invoke an order dependency...

The query, the explain analyze on the first pass and the explain analyze on
the second pass.

*The second-level Hash Join combines/sees, in both cases, 7,993 and
1,275,138 records but depending on the LEFT/RIGHT order of the sub-nodes
appears to provide a different result.*

EXPLAIN ANALYZE
select count(*) from
(
SELECT DISTINCT
rrr
FROM public.rrr
INNER JOIN public.fff
ON fff.idx = rrr.fff_idx
INNER JOIN public.uuu
ON uuu.universe_hash = 5188205190738336870 AND
uuu.bababa = rrr.bababa
WHERE
fff.file_name_model_ver = '100' AND
fff.file_name_date BETWEEN '2005-03-01' AND '2005-07-30'
) ad

QUERY PLAN
Aggregate (cost=1504689.02..1504689.03 rows=1 width=0) (actual
time=155253.758..155253.759 rows=1 loops=1)
-> Unique (cost=1497322.60..1501340.65 rows=267870 width=24) *(actual
time=153375.583..154829.461 rows=415874 loops=1)*
-> Sort (cost=1497322.60..1497992.27 rows=267870 width=24)
(actual time=153375.578..153919.245 rows=415874 loops=1)
Sort Key: rrr.idx, rrr.row_number, rrr.bababa, rrr.data_date,
rrr.fff_idx
Sort Method: external merge Disk: 13784kB
-> Hash Join (cost=1456589.92..1467677.54 rows=267870
width=24) (actual time=151982.289..152665.099 rows=415874 loops=1)
Hash Cond: ((uuu.bababa)::text = (rrr.bababa)::text)
-> Index Only Scan using pk_uuu on uuu
(cost=0.42..270.01 rows=8091 width=8) (actual time=0.012..9.359 rows=*7993*
loops=1)
Index Cond: (universe_hash =
'5188205190738336870'::bigint)
Heap Fetches: 0
-> Hash (cost=1440572.59..1440572.59 rows=872393
width=24) (actual time=151981.919..151981.919 rows=*1275138* loops=1)
Buckets: 65536 (originally 65536) Batches: 32
(originally 16) Memory Usage: 3585kB
-> Hash Join (cost=819.47..1440572.59
rows=872393 width=24) (actual time=12037.549..150408.756 rows=1275138
loops=1)
Hash Cond: (rrr.fff_idx = fff.idx)
-> Seq Scan on rrr (cost=0.00..1164409.32
rows=71098632 width=24) (actual time=0.004..73673.708 rows=71098547 loops=1)
-> Hash (cost=807.58..807.58 rows=951
width=4) (actual time=2.360..2.360 rows=964 loops=1)
Buckets: 1024 Batches: 1 Memory
Usage: 42kB
-> Bitmap Heap Scan on fff
(cost=30.98..807.58 rows=951 width=4) (actual time=0.123..1.293 rows=964
loops=1)
Recheck Cond: ((file_name_date

= '2005-03-01'::date) AND (file_name_date <= '2005-07-30'::date))

Filter:
((file_name_model_ver)::text = '100'::text)
Rows Removed by Filter: 540
Heap Blocks: exact=30
-> Bitmap Index Scan on
ix_fff_file_name_date (cost=0.00..30.74 rows=1445 width=0) (actual
time=0.111..0.111 rows=1504 loops=1)
Index Cond:
((file_name_date >= '2005-03-01'::date) AND (file_name_date <=
'2005-07-30'::date))
Planning time: 0.668 ms
Execution time: 155255.933 ms

QUERY PLAN
Aggregate (cost=1520976.49..1520976.50 rows=1 width=0) (actual
time=163603.573..163603.574 rows=1 loops=1)
-> Unique (cost=1519634.64..1520973.99 rows=200 width=48) *(actual
time=161695.425..163174.422 rows=416075 loops=1)*
-> Sort (cost=1519634.64..1520304.32 rows=267870 width=48)
(actual time=161695.393..162157.673 rows=416075 loops=1)
Sort Key: rrr.*
Sort Method: external sort Disk: 22376kB
-> Hash Join (cost=1190.62..1487242.09 rows=267870
width=48) (actual time=12556.229..158035.711 rows=416075 loops=1)
Hash Cond: ((rrr.bababa)::text = (uuu.bababa)::text)
-> Hash Join (cost=819.47..1440572.59 rows=872393
width=56) (actual time=12538.212..156077.489 rows=*1275138 *loops=1)
Hash Cond: (rrr.fff_idx = fff.idx)
-> Seq Scan on rrr (cost=0.00..1164409.32
rows=71098632 width=60) (actual time=0.008..82185.329 rows=71098547 loops=1)
-> Hash (cost=807.58..807.58 rows=951 width=4)
(actual time=2.351..2.351 rows=964 loops=1)
Buckets: 1024 Batches: 1 Memory Usage:
42kB
-> Bitmap Heap Scan on fff
(cost=30.98..807.58 rows=951 width=4) (actual time=0.097..1.307 rows=964
loops=1)
Recheck Cond: ((file_name_date >=
'2005-03-01'::date) AND (file_name_date <= '2005-07-30'::date))
Filter: ((file_name_model_ver)::text
= '100'::text)
Rows Removed by Filter: 540
Heap Blocks: exact=30
-> Bitmap Index Scan on
ix_fff_file_name_date (cost=0.00..30.74 rows=1445 width=0) (actual
time=0.086..0.086 rows=1504 loops=1)
Index Cond: ((file_name_date >=
'2005-03-01'::date) AND (file_name_date <= '2005-07-30'::date))
-> Hash (cost=270.01..270.01 rows=8091 width=8)
(actual time=17.233..17.233 rows=7993 loops=1)
Buckets: 8192 Batches: 1 Memory Usage: 377kB
-> Index Only Scan using pk_uuu on uuu
(cost=0.42..270.01 rows=8091 width=8) (actual time=0.012..8.525 rows=*7993
*loops=1)
Index Cond: (universe_hash =
'5188205190738336870'::bigint)
Heap Fetches: 0
Planning time: 0.642 ms
Execution time: 163606.571 ms

On Thu, Feb 4, 2016 at 2:56 PM, Seth P <seth-p@outlook.com> wrote:

Meanwhile, your results are curious not just because they differ from
mine, but because you observe the DISTINCT removing *any* duplicates.
There shouldn't be any, since rrr.idx is a unique serial (idx integer NOT
NULL DEFAULT nextval('rrr_idx_seq'::regclass)). In particular, the
following query returns no rows:

SELECT rrr.idx FROM public.rrr GROUP BY rrr.idx HAVING count(*)>1

Put another way, in your database, can you find the duplicates being
removed by DISTINCT

B
​ut the query is written as a series of INNER JOINs against "rrr" and so
its output is not constrained by UNIQUE(rrr.idx). So it very well may
return multiple rows for a given rrr.idx but when you restrict the output
to "rrr.*" and add DISTINCT the result is fewer records since now you only
have one of each rrr.idx.

​
​
​I made one possibly meaningful change when I reported my discrepancy
earlier. The query with the ​416,075 DISTINCT row count uses "SELECT
DISTINCT rrr" while the one returning 415,874 uses "SELECT DISTINCT rrr.*".

​That said, running the following returns zero records:

​SELECT
rrr.idx, count(*)
FROM public.rrr
INNER JOIN public.fff
ON fff.idx = rrr.fff_idx
INNER JOIN public.uuu
ON uuu.universe_hash = 5188205190738336870 AND
uuu.bababa = rrr.bababa
WHERE
fff.file_name_model_ver = '100' AND
fff.file_name_date BETWEEN '2005-03-01' AND '2005-07-30'
GROUP BY rrr.idx
HAVING count(*) > 1

​So indeed the query does not result in multiple rrr.idx values being
output for the DISTINCT to remove.

​David J.​

"David G. Johnston" <david.g.johnston@gmail.com> writes:

*The second-level Hash Join combines/sees, in both cases, 7,993 and
1,275,138 records but depending on the LEFT/RIGHT order of the sub-nodes
appears to provide a different result.*

Hmm, that's pretty fishy; and given all the hacking that's gone on lately
on hash join, 9.5 introducing a bug there wouldn't be all that astonishing.
But I decline to try to find it without a self-contained test case.

regards, tom lane

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

On Thu, Feb 4, 2016 at 3:13 PM, David G. Johnston <
david.g.johnston@gmail.com> wrote:

Tom, we really need you to chime in here.

On Thu, Feb 4, 2016 at 2:58 PM, David G. Johnston <
david.g.johnston@gmail.com> wrote:

Adding back the list so that everyone can see the latest finding. Adding
in the original bug block too...
​

The following bug has been logged on the website:

Bug reference: 13908
Logged by: Seth
Email address: seth-p@outlook.com
PostgreSQL version: 9.5.0
Operating system: Windows 10
Description:

* -> Unique (cost=1497322.60..1501340.65 rows=267870 width=24) (actual
time=153375.583..154829.461 rows=415874 loops=1)*

​Without running any DML I just got this result on the DISTINCT query...​

*​ -> Unique (cost=1519634.64..1520973.99 rows=200 width=48) (actual
time=161695.425..163174.422 rows=416075 loops=1)*
​

​According to 9.3 this 416,075 count is the correct one - and I got the
same count with and without distinct executed multiple times each.

​My next thought is to see which 300 or so rows that are being left out in
9.5 appear in 9.3....​

​David J.​

On Thu, Feb 4, 2016 at 4:28 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

"David G. Johnston" <david.g.johnston@gmail.com> writes:

*The second-level Hash Join combines/sees, in both cases, 7,993 and
1,275,138 records but depending on the LEFT/RIGHT order of the sub-nodes
appears to provide a different result.*

Hmm, that's pretty fishy; and given all the hacking that's gone on lately
on hash join, 9.5 introducing a bug there wouldn't be all that astonishing.
But I decline to try to find it without a self-contained test case.

​So, one of the tables involved has 70M-ish rows of which only maybe 2M-ish
of them are necessary to fulfill the query in terms of getting the right
answer. Realizing this I deleted the other 68M records and then
immediately (same transaction) run the counting query and find that I still
get an incorrect result. I ran a count instead of an explain analyze so
I'm not sure exactly what it did behind the scenes. Regardless, I got the
under-counting behavior. I then commit the transaction, run vacuum
analyze, and the re-run the counting query and that completes I now get the
correct count.

Do you expect that some portion of the 68M records that were deleted would
be required to diagnose the problem or can knobs be twiddled in some way to
get similar behavior exhibited without them actually being present. The
fact that the records were deleted, but not vacuumed, and a wrong result
was returned makes me think it should be possible but I don't know enough
to say for sure or to make informed decisions as to which knobs to turn (if
indeed such knobs are exposed since I do not have source-editing or
debugging capabilities).

David J
​
​

On Thu, Feb 4, 2016 at 8:57 PM, David G. Johnston <
david.g.johnston@gmail.com> wrote:

On Thu, Feb 4, 2016 at 4:28 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

"David G. Johnston" <david.g.johnston@gmail.com> writes:

*The second-level Hash Join combines/sees, in both cases, 7,993 and
1,275,138 records but depending on the LEFT/RIGHT order of the sub-nodes
appears to provide a different result.*

Hmm, that's pretty fishy; and given all the hacking that's gone on lately
on hash join, 9.5 introducing a bug there wouldn't be all that
astonishing.
But I decline to try to find it without a self-contained test case.

​So, one of the tables involved has 70M-ish rows of which only maybe
2M-ish of them are necessary to fulfill the query in terms of getting the
right answer. Realizing this I deleted the other 68M records and then
immediately (same transaction) run the counting query and find that I still
get an incorrect result. I ran a count instead of an explain analyze so
I'm not sure exactly what it did behind the scenes. Regardless, I got the
under-counting behavior. I then commit the transaction, run vacuum
analyze, and the re-run the counting query and that completes I now get the
correct count.

Do you expect that some portion of the 68M records that were deleted would
be required to diagnose the problem or can knobs be twiddled in some way to
get similar behavior exhibited without them actually being present. The
fact that the records were deleted, but not vacuumed, and a wrong result
was returned makes me think it should be possible but I don't know enough
to say for sure or to make informed decisions as to which knobs to turn (if
indeed such knobs are exposed since I do not have source-editing or
debugging capabilities).

​Some more observations...

On this node's detail (the rows seems to appear consistently regardless of
node ordering in the plan...)
Hash (cost=1440572.59..1440572.59 rows=872393 width=24) (actual
time=151981.919..151981.919 rows=*1275138* loops=1)
Bad Plan: ​

​ ​
Buckets: 131072 (originally 131072) Batches: 32 (originally 16) Memory
Usage: 3073kB
​Bad Plan: ​ Buckets: 65536 (originally 65536) Batches: 32 (originally
16) Memory Usage: 3585kB
Good Plan: Buckets: 1024 Batches: 1 Memory Usage: 42kB
Good Plan: Buckets: 8192 Batches: 1 Memory Usage: 439kB (see below)
9.3 Plan: Buckets: 4096 Batches: 64 Memory Usage: 889kB

9.5 Made Up Good Plan (see below): Buckets: 131072 (originally 1024)
Batches: 16 (originally 1) Memory Usage: 3227kB

*The difference on this last one is that the original bucket count is
considerably smaller than the seemingly important 2^16-1 boundary even
though the final count is greater.*

I was able to force a Hash Join between the 1,275,138 node and the 7,993
node using CTEs
BEGIN;
SET LOCAL enable_mergejoin = off;
EXPLAIN ANALYZE
WITH first_join AS (
SELECT *
FROM rrr JOIN fff ON fff.idx = rrr.fff_idx
WHERE fff.file_name_model_ver = '100' AND
fff.file_name_date BETWEEN '2005-03-01' AND '2005-07-30'
),
second_join AS (
SELECT * FROM uuu WHERE universe_hash = 5188205190738336870
),
combined AS (
SELECT * FROM first_join JOIN second_join USING (bababa)
)
SELECT count(*) FROM combined;

The result was the following explain analyze and a good count.

QUERY PLAN
Aggregate (cost=320276.69..320276.70 rows=1 width=0) (actual
time=23126.200..23126.201 rows=1 loops=1)
CTE first_join
-> Hash Join (cost=820.88..228772.40 rows=38783 width=68) (actual
time=8573.804..15931.271 rows=1275138 loops=1)
Hash Cond: (rrr.fff_idx = fff.idx)
-> Seq Scan on rrr (cost=0.00..216302.86 rows=3002886 width=24)
(actual time=7499.001..10979.666 rows=3007454 loops=1)
-> Hash (cost=808.37..808.37 rows=1001 width=44) (actual
time=2.616..2.616 rows=964 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 87kB
-> Bitmap Heap Scan on fff (cost=35.75..808.37 rows=1001
width=44) (actual time=0.122..1.438 rows=964 loops=1)
Recheck Cond: ((file_name_date >= '2005-03-01'::date)
AND (file_name_date <= '2005-07-30'::date))
Filter: ((file_name_model_ver)::text = '100'::text)
Rows Removed by Filter: 540
Heap Blocks: exact=30
-> Bitmap Index Scan on ix_fff_file_name_date
(cost=0.00..35.50 rows=1521 width=0) (actual time=0.100..0.100 rows=1504
loops=1)
Index Cond: ((file_name_date >=
'2005-03-01'::date) AND (file_name_date <= '2005-07-30'::date))
CTE second_join
-> Index Only Scan using pk_uuu on uuu (cost=0.42..269.84 rows=8081
width=16) (actual time=0.019..9.372 rows=7993 loops=1)
Index Cond: (universe_hash = '5188205190738336870'::bigint)
Heap Fetches: 0
CTE combined
-> Hash Join (cost=262.63..55976.35 rows=1567027 width=228) (actual
time=8612.493..21535.488 rows=416075 loops=1)
Hash Cond: ((first_join.bababa)::text =
(second_join.bababa)::text)
-> CTE Scan on first_join (cost=0.00..775.66 rows=38783
width=220) (actual time=8573.810..19343.262 rows=1275138 loops=1)
-> Hash (cost=161.62..161.62 rows=8081 width=42) (actual
time=37.346..37.346 rows=7993 loops=1)
* Buckets: 8192 Batches: 1 Memory Usage: 439kB*
-> CTE Scan on second_join (cost=0.00..161.62 rows=8081
width=42) (actual time=0.023..27.642 rows=7993 loops=1)
-> CTE Scan on combined (cost=0.00..31340.54 rows=1567027 width=0)
(actual time=8612.498..22664.354 rows=416075 loops=1)
Planning time: 0.137 ms
Execution time: 23145.303 ms

And below is the 9.3 non-Distinct plan

QUERY PLAN
Aggregate (cost=1467123.37..1467123.38 rows=1 width=0) (actual
time=165954.407..165954.409 rows=1 loops=1)
-> Hash Join (cost=1456877.26..1466434.87 rows=275399 width=0) (actual
time=164885.552..165504.698 rows=416075 loops=1)
Hash Cond: ((uuu.bababa)::text = (rrr.bababa)::text)
-> Index Only Scan using pk_uuu on uuu (cost=0.42..260.48
rows=7775 width=8) (actual time=0.011..9.630 rows=7993 loops=1)
Index Cond: (universe_hash = 5188205190738336870::bigint)
Heap Fetches: 0
-> Hash (cost=1441329.64..1441329.64 rows=947616 width=8) (actual
time=164884.922..164884.922 rows=1275138 loops=1)
*Buckets: 4096 Batches: 64 Memory Usage: 889kB*
-> Hash Join (cost=822.75..1441329.64 rows=947616 width=8)
(actual time=60770.116..163253.376 rows=1275138 loops=1)
Hash Cond: (rrr.fff_idx = fff.idx)
-> Seq Scan on rrr (cost=0.00..1164410.44
rows=71098744 width=12) (actual time=0.036..79440.276 rows=71098547 loops=1)
-> Hash (cost=809.84..809.84 rows=1033 width=4)
(actual time=2.577..2.577 rows=964 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 34kB
-> Bitmap Heap Scan on fff (cost=36.29..809.84
rows=1033 width=4) (actual time=0.110..1.418 rows=964 loops=1)
Recheck Cond: ((file_name_date >=
'2005-03-01'::date) AND (file_name_date <= '2005-07-30'::date))
Filter: ((file_name_model_ver)::text =
'100'::text)
Rows Removed by Filter: 540
-> Bitmap Index Scan on
ix_fff_file_name_date (cost=0.00..36.03 rows=1574 width=0) (actual
time=0.098..0.098 rows=1504 loops=1)
Index Cond: ((file_name_date >=
'2005-03-01'::date) AND (file_name_date <= '2005-07-30'::date))
Total runtime: 165954.463 ms

Though it doesn't seem simply a function bug bucket count since:

EXPLAIN ANALYZE
WITH first_join AS (
SELECT * FROM generate_series(1, 1000000) gs (i)
),
second_join AS (
SELECT * FROM generate_series(1, 1000000) gs (i)
),
combined AS (
SELECT * FROM first_join JOIN second_join USING (i)
)
SELECT count(*) FROM combined;

QUERY PLAN
Aggregate (cost=362.50..362.51 rows=1 width=0) (actual
time=13842.652..13842.653 rows=1 loops=1)
CTE first_join
-> Function Scan on generate_series gs (cost=0.00..10.00 rows=1000
width=4) (actual time=88.464..1186.923 rows=1000000 loops=1)
CTE second_join
-> Function Scan on generate_series gs_1 (cost=0.00..10.00 rows=1000
width=4) (actual time=88.287..1187.215 rows=1000000 loops=1)
CTE combined
-> Hash Join (cost=32.50..230.00 rows=5000 width=4) (actual
time=4668.961..10530.299 *rows=1000000* loops=1)
Hash Cond: (first_join.i = second_join.i)
-> CTE Scan on first_join (cost=0.00..20.00 rows=1000 width=4)
(actual time=88.468..3333.798 rows=1000000 loops=1)
-> Hash (cost=20.00..20.00 rows=1000 width=4) (actual
time=4580.247..4580.247 rows=1000000 loops=1)
* Buckets: 131072 (originally 1024) Batches: 16 (originally
1) Memory Usage: 3227kB*
-> CTE Scan on second_join (cost=0.00..20.00 rows=1000
width=4) (actual time=88.294..3320.363 rows=1000000 loops=1)
-> CTE Scan on combined (cost=0.00..100.00 rows=5000 width=0) (actual
time=4668.966..12787.652 rows=1000000 loops=1)
Planning time: 0.071 ms
Execution time: 13853.714 ms

Though maybe because the original was only 1024 while the Bad plans above
had original sizes greater than 2^16-1...

David J.

On Thu, Feb 4, 2016 at 9:47 PM, David G. Johnston <
david.g.johnston@gmail.com> wrote:

On this node's detail (the rows seems to appear consistently regardless of
node ordering in the plan...)
Hash (cost=1440572.59..1440572.59 rows=872393 width=24) (actual
time=151981.919..151981.919 rows=*1275138* loops=1)

Bad Plan: ​

​ ​
Buckets: 131072 (originally 131072) Batches: 32 (originally 16) Memory
Usage: 3073kB

Final result: ​415,967 / ​416,075 (108 missing)

​Bad Plan: ​ Buckets: 65536 (originally 65536) Batches: 32 (originally
16) Memory Usage: 3585kB

​Final result: 415,874 / 416,075 (201 missing)​

​David J.​

On Thu, Feb 4, 2016 at 10:17 PM, David G. Johnston <
david.g.johnston@gmail.com> wrote:

On Thu, Feb 4, 2016 at 9:47 PM, David G. Johnston <
david.g.johnston@gmail.com> wrote:

On this node's detail (the rows seems to appear consistently regardless
of node ordering in the plan...)
Hash (cost=1440572.59..1440572.59 rows=872393 width=24) (actual
time=151981.919..151981.919 rows=*1275138* loops=1)

Bad Plan: ​

​ ​
Buckets: 131072 (originally 131072) Batches: 32 (originally 16) Memory
Usage: 3073kB

Final result: ​415,967 / ​416,075 (108 missing)

​So just over 3 output records per bucket and 32 batches ​gives 96+

​Bad Plan: ​ Buckets: 65536 (originally 65536) Batches: 32 (originally
16) Memory Usage: 3585kB

​Final result: 415,874 / 416,075 (201 missing)​

​Just over 6 output records per bucket and 32 batches yields 192+

Didn't notice any obvious numeric equalities using ​
1,275,138

David J.

"David G. Johnston" <david.g.johnston@gmail.com> writes:

Didn't notice any obvious numeric equalities using ​
1,275,138

I've committed a patch for this. Thanks for all the legwork!

regards, tom lane

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

From: Tom Lane <tgl@sss.pgh.pa.us>

I've committed a patch for this. Thanks for all the legwork!

Indeed, I no longer see this problem in 9.5.1. Thank you for the quick diagnosis and fix.

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs