Re: BUG #13908: Query returns too few rows

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(dot)g(dot)johnston(at)gmail(dot)com>
Sent: Tuesday, February 2, 2016 6:27 PM
To: Tom Lane
Cc: seth-p(at)outlook(dot)com; pgsql-bugs(at)postgresql(dot)org
Subject: Re: [BUGS] BUG #13908: Query returns too few rows

On Tue, Feb 2, 2016 at 3:52 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us<mailto:tgl(at)sss(dot)pgh(dot)pa(dot)us>> wrote:
seth-p(at)outlook(dot)com<mailto:seth-p(at)outlook(dot)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.