Subject: Regression from 9.4-9.6

From: Jim Nasby <[email-masked]>
Date: Sun, 8 Oct 2017 14:25:54 -0500

I've got a query that's regressed from 9.4 to 9.6. I suspect it has 
something to do with the work done around bad plans from single-row 
estimates. There's a SeqScan happening even though the join is to the PK 
of bd_ident. Full plans are at [1,2,3], but here's the relevant bits...

9.4:
>    ->  Nested Loop Left Join  (cost=1.00..50816.55 rows=1 width=27) (actual time=979.406..3213.286 rows=508 loops=1)
>          ->  Index Scan using bdata_filed_departuretime on bdata_forks  (cost=0.57..50807.51 rows=1 width=36) (actual time=979.381..3207.777 rows=508 loops=1)
>                Index Cond: ((filed_departuretime >= '2017-07-20 05:00:00'::timestamp without time zone) AND (filed_departuretime <= '2017-07-30 04:59:59'::timestamp without time zone))
...
>          ->  Index Scan using bd_ident_pkey on bd_ident i  (cost=0.43..4.45 rows=1 width=11) (actual time=0.006..0.006 rows=1 loops=508)
>                Index Cond: (bdata_forks.ident_id = id)
>          SubPlan 1
>            ->  Index Scan using bd_airport_pkey on bd_airport  (cost=0.56..4.58 rows=1 width=20) (actual time=0.003..0.003 rows=1 loops=508)
>                  Index Cond: (id = bdata_forks.destination_id)

9.6:
>    ->  Nested Loop Left Join  (cost=0.57..14994960.40 rows=1 width=71) (actual time=931.479..327972.891 rows=508 loops=1)
>          Join Filter: (bdata_forks.ident_id = i.id)
>          Rows Removed by Join Filter: 1713127892
>          ->  Index Scan using bdata_filed_departuretime on bdata_forks  (cost=0.57..14894236.06 rows=1 width=36) (actual time=892.664..3025.653 rows=508 loops=1)
...
>          ->  Seq Scan on bd_ident i  (cost=0.00..58566.00 rows=3372300 width=11) (actual time=0.002..280.966 rows=3372300 loops=508)
                ^^^^^^^^
>          SubPlan 1
>            ->  Index Scan using bd_airport_pkey on bd_airport  (cost=0.56..4.58 rows=1 width=20) (actual time=0.009..0.009 rows=1 loops=508)
>                  Index Cond: (id = bdata_forks.destination_id)

Altering the predicates somewhat (removing one of the timestamp 
conditions) results in the input to the outer part of the nested loop 
estimating at 326 rows instead of 1, which generates a good plan:

>    ->  Nested Loop Left Join  (cost=1.00..14535906.91 rows=326 width=71) (actual time=23.670..4558.273 rows=3543 loops=1)
>          ->  Index Scan using bdata_filed_departuretime on bdata_forks  (cost=0.57..14532973.05 rows=326 width=36) (actual time=23.647..4522.428 rows=3543 loops=1)
 
                           ^^^^^^^^
...
>          ->  Index Scan using bd_ident_pkey on bd_ident i  (cost=0.43..4.40 rows=1 width=11) (actual time=0.005..0.006 rows=1 loops=3543)
>                Index Cond: (bdata_forks.ident_id = id)
>          SubPlan 1
>            ->  Index Scan using bd_airport_pkey on bd_airport  (cost=0.56..4.58 rows=1 width=20) (actual time=0.003..0.003 rows=1 loops=3543)
>                  Index Cond: (id = bdata_forks.destination_id)

1: https://explain.depesz.com/s/2A90
2: https://explain.depesz.com/s/jKdr
3: https://explain.depesz.com/s/nFh
-- 
Jim C. Nasby, Data Architect                       [email-masked]
512.569.9461 (cell)                         http://jim.nasby.net

-- 
Sent via pgsql-performance mailing list ([email-masked])
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance

---

From: Tom Lane <[email-masked]>
Date: Sun, 08 Oct 2017 15:34:51 -0400

Jim Nasby <[email-masked]> writes:
> estimates.

Why has this indexscan's cost estimate changed so much?

>> ->  Index Scan using bdata_filed_departuretime on bdata_forks  (cost=0.57..14894236.06 rows=1 width=36) (actual time=892.664..3025.653 rows=508 loops=1)

I think the reason it's discarding the preferable plan is that, with this
huge increment in the estimated cost getting added to both alternatives,
the two nestloop plans have fuzzily the same total cost, and it's picking
the one you don't want on the basis of some secondary criterion.

			regards, tom lane

---

From: Jim Nasby <[email-masked]>
Date: Sun, 8 Oct 2017 15:02:42 -0500

> the one you don't want on the basis of some secondary criterion.

Great question... the only thing that sticks out is the coalesce(). Let 
me see if an analyze with a higher stats target changes anything. FWIW, 
the 9.6 database is copied from the 9.4 one once a week and then 
pg_upgraded. I'm pretty sure an ANALYZE is part of that process.

9.4:
>                Filter: (((view_www IS NULL) OR (view_www IS TRUE)) AND (sch_block_out IS NOT NULL) AND (diverted IS NOT TRUE) AND (true_cancel IS NOT TRUE) AND (sch_block_out >= '2017-07-23 05:00:00'::timestamp without time zone) AND (sch_block_out <= '2017-07-24 04:59:59'::timestamp without time zone) AND (COALESCE(actualarrivaltime, cancellation) >= actualdeparturetime) AND ((act_block_out - sch_block_out) >= '00:15:00'::interval) AND (((SubPlan 2))::text = 'KORD'::text))
>                Rows Removed by Filter: 2696593
>                SubPlan 2
>                  ->  Index Scan using bd_airport_pkey on bd_airport bd_airport_1  (cost=0.56..4.58 rows=1 width=20) (actual time=0.003..0.003 rows=1 loops=21652)
>                        Index Cond: (id = bdata_forks.origin_id)

9.6:
>                Filter: (((view_www IS NULL) OR (view_www IS TRUE)) AND (sch_block_out IS NOT NULL) AND (diverted IS NOT TRUE) AND (true_cancel IS NOT TRUE) AND (sch_block_out >= '2017-07-23 05:00:00'::timestamp without time zone) AND (sch_block_out <= '2017-07-24 04:59:59'::timestamp without time zone) AND (COALESCE(actualarrivaltime, cancellation) >= actualdeparturetime) AND ((act_block_out - sch_block_out) >= '00:15:00'::interval) AND (((SubPlan 2))::text = 'KORD'::text))
>                Rows Removed by Filter: 2696592
>                SubPlan 2
>                  ->  Index Scan using bd_airport_pkey on bd_airport bd_airport_1  (cost=0.56..4.58 rows=1 width=20) (actual time=0.004..0.004 rows=1 loops=21652)
>                        Index Cond: (id = bdata_forks.origin_id)

---

From: Jim Nasby <[email-masked]>
Date: Sun, 8 Oct 2017 15:33:07 -0500

On 10/8/17 3:02 PM, Jim Nasby wrote:
>>
>>>> -> Index Scan using bdata_filed_departuretime on bdata_forks 
>>>> (cost=0.57..50807.51 rows=1 width=36) (actual time=979.381..3207.777 
>>>> rows=508 loops=1)
>>
>>>> -> Index Scan using bdata_filed_departuretime on bdata_forks 
>>>> (cost=0.57..14894236.06 rows=1 width=36) (actual 
>>>> time=892.664..3025.653 rows=508 loops=1)
>>

Turns out that analyze is the 'problem'. On the 9.4 database, pg_stats 
shows that the newest date in filed_departuretime is 3/18/2017, while 
the 9.6 database is up-to-date. If I change the query to use 2/9/2018 
instead of 7/20/2017 I get the same results.

So, the larger cost estimate is theoretically more correct. If I set 
random_page_cost = 1 I end up with a good plan.
-- 
Jim C. Nasby, Data Architect                       [email-masked]
512.569.9461 (cell)                         http://jim.nasby.net

---

From: Tom Lane <[email-masked]>
Date: Sun, 08 Oct 2017 16:37:59 -0400

> pg_upgraded. I'm pretty sure an ANALYZE is part of that process.

Hm, now that I see the SubPlan in there, I wonder whether 9.6 is
accounting more conservatively for the cost of the subplan.  It
probably is assuming that the subplan gets run for each row fetched
from the index, although the loops and rows-removed counts show
that the previous filter conditions reject 99% of the fetched rows.

But that code looks the same in 9.4, so I don't understand why
the 9.4 estimate isn't equally large ...

			regards, tom lane

---

From: Jim Nasby <[email-masked]>
Date: Sun, 8 Oct 2017 16:07:04 -0500

> the 9.4 estimate isn't equally large ...

Besides the analyze issue, the other part of this is

[email-masked]/20106> select 
pg_size_pretty(pg_relation_size('bdata_forks'));
  pg_size_pretty
----------------
  106 GB
(1 row)

[email-masked]/20106> select relpages::bigint*8192/reltuples from 
pg_class where relname='bdata_forks';
      ?column?
------------------
  185.559397863791
(1 row)

With an effective_cache_size of 200GB that's not really helping things. 
But it's also another example of the planner's reluctance towards index 
scans.
-- 
Jim C. Nasby, Data Architect                       [email-masked]
512.569.9461 (cell)                         http://jim.nasby.net