Thread: very slow queries when max_parallel_workers_per_gather is higher than zero

On 04/16/2018 11:34 AM, Pavel Stehule wrote:
> Hi,
> 
> my customer does performance checks of PostgreSQL 9.5 and 10. Almost all
> queries on 10 are faster, but there are few queries (40 from 1000) where
> PostgreSQL 9.5 is significantly faster than. Unfortunately - pretty fast
> queries (about 20ms) are too slow now (5 sec).
> 
> attached execution plans
> 
> It looks like some cost issue, slow queries prefers Seq scan against
> bitmap heap scan
> 
> Hash Cond: (f_ticketupdate_aad5jtwal0ayaax.dt_event_id =
> dwh_dm_aabv5kk9rxac4lz_aaonw7nchsan2n1_aad8xhr0m_aaewg8j61ia.id
> <http://dwh_dm_aabv5kk9rxac4lz_aaonw7nchsan2n1_aad8xhr0m_aaewg8j61ia.id>)
>    ->  Parallel Seq Scan on f_ticketupdate_aad5jtwal0ayaax 
> (cost=0.00..1185867.47 rows=24054847 width=8) (actual
> time=0.020..3741.409 rows=19243863 loops=3)
>    ->  Hash  (cost=27.35..27.35 rows=7 width=4) (actual
> time=0.089..0.089 rows=7 loops=3)
>         Buckets: 1024  Batches: 1  Memory Usage: 9kB
> 
> 

What happens when you disable sequential scans on pg10?

regards

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

> Query Performs nicely, but no parallel workers are used:
> GroupAggregate  (cost=2611148.87..2611152.89 rows=31 width=22) (actual
> time=0.084..0.084 rows=0 loops=1)
>    Group Key:
> f_zendesktickets_aaeljtllr5at3el.cstm_custom_38746665_primary_column
>    ->  Sort  (cost=2611148.87..2611149.11 rows=99 width=28) (actual
> time=0.082..0.082 rows=0 loops=1)
>          Sort Key:
> f_zendesktickets_aaeljtllr5at3el.cstm_custom_38746665_primary_column
>          Sort Method: quicksort  Memory: 25kB
>          ->  Nested Loop  (cost=1639.25..2611145.59 rows=99 width=28)
> (actual time=0.076..0.076 rows=0 loops=1)
>                Join Filter:
> (((f_ticketattributeshistory_aajzjp98uraszb6.attrnewvalue_id = ANY
> ('{4757,4758,4759}'::integer[])) AND (4754 =
> f_ticketattributeshistory_aajzjp98uraszb6.attroldvalue_id) AND (4790 =
> f_ticketattributeshistory_aajzjp98uraszb6.ticketfield_id)) OR
> (f_zendesktickets_aaeljtllr5at3el.dt_createda
> t_id = f_ticketupdate_aad5jtwal0ayaax.dt_event_id))
>                ->  Nested Loop  (cost=1638.81..1809540.39 rows=350270
> width=20) (actual time=0.075..0.075 rows=0 loops=1)
>                      ->  Nested Loop  (cost=1638.24..1508474.08
> rows=69140 width=8) (actual time=0.075..0.075 rows=0 loops=1)
>                            ->  Bitmap Heap Scan on
> dwh_dm_aabv5kk9rxac4lz_aaonw7nchsan2n1_aad8xhr0m_aaewg8j61iagl1z
> dwh_dm_aabv5kk9rxac4lz_aaonw7nchsan2n1_aad8xhr0m_aaewg8j61ia 
> (cost=4.34..27.35 rows=7 width=4) (actual time=0.026..0.038 rows=7 loops=1)
>                                  Recheck Cond: (6171 = id_euweek)
>                                  Heap Blocks: exact=7
>                                  ->  Bitmap Index Scan on
> dwh_dm_aabv5kk9rxac4lz_aaonw7nchsan2n1_aad8xhr0m_a_id_euweek_idx 
> (cost=0.00..4.33 rows=7 width=0) (actual time=0.019..0.019 rows=7 loops=1)
>                                        Index Cond: (6171 = id_euweek)
>                            ->  Bitmap Heap Scan on
> f_ticketupdate_aad5jtwal0ayaax  (cost=1633.90..214617.67 rows=87472
> width=8) (actual time=0.004..0.004 rows=0 loops=7)
>                                  Recheck Cond: (dt_event_id =
> dwh_dm_aabv5kk9rxac4lz_aaonw7nchsan2n1_aad8xhr0m_aaewg8j61ia.id
> <http://dwh_dm_aabv5kk9rxac4lz_aaonw7nchsan2n1_aad8xhr0m_aaewg8j61ia.id>)
>                                  ->  Bitmap Index Scan on
> f_ticketupdate_aad5jtwal0ayaax_dt_event_id_idx  (cost=0.00..1612.03
> rows=87472 width=0) (actual time=0.003..0.003 rows=0 loops=7)
>                                        Index Cond: (dt_event_id =
> dwh_dm_aabv5kk9rxac4lz_aaonw7nchsan2n1_aad8xhr0m_aaewg8j61ia.id
> <http://dwh_dm_aabv5kk9rxac4lz_aaonw7nchsan2n1_aad8xhr0m_aaewg8j61ia.id>)
>                      ->  Index Scan using
> f_ticketattributeshistory_aajzjp98uraszb6_ticketupdate_id_idx on
> f_ticketattributeshistory_aajzjp98uraszb6  (cost=0.57..4.12 rows=23
> width=20) (never executed)
>                            Index Cond: (ticketupdate_id =
> f_ticketupdate_aad5jtwal0ayaax.id
> <http://f_ticketupdate_aad5jtwal0ayaax.id>)
>                ->  Index Scan using
> f_zendesktickets_aaeljtllr5at3el_pkey on
> f_zendesktickets_aaeljtllr5at3el  (cost=0.43..2.27 rows=1 width=12)
> (never executed)
>                      Index Cond: (id =
> f_ticketattributeshistory_aajzjp98uraszb6.zendesktickets_id)
>                      Filter: ((4765 <> status_id) AND (group_id = 17429))
>  Planning time: 8.516 ms
>  Execution time: 1.895 ms
> 
> the speed is back
> 

Yeah, but the cost is higher (2611152 vs. 1949508). So clearly, the
database believes it's going to be cheaper. I suspect a part of the
issue might be that the join is misestimated - it's expected to produce
~29k rows, but produces 0.

Can you check if this query has the same issue? It's just the
problematic join, and it should be simpler to investigate:

SELECT count(*)
  FROM f_ticketupdate_aad5jtwal0ayaax AS f
  INNER JOIN
  dwh_dm_aabv5kk9rxac4lz_aaonw7nchsan2n1_aad8xhr0m_aaewg8j61iagl1z AS d
  ON (f.dt_event_id = d.id)


regards

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

Apologies, the reduced query was missing a where condition on id_week:

SELECT count(*)
FROM f_ticketupdate_aad5jtwal0ayaax AS f
INNER JOIN
  dwh_dm_aabv5kk9rxac4lz_aaonw7nchsan2n1_aad8xhr0m_aaewg8j61iagl1z AS d
  ON (f.dt_event_id = d.id)
WHERE ( 6171 = d."id_euweek" )


regards

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

Thanks. So we now have a trivial query demonstrating the issue. IMHO
this is not really a costing issue, but due to a misestimate.

Essentially, the problem is that the two sides of the join mismatch,
causing this:

    ->  Bitmap Heap Scan on dwh_dm ... d  (... rows=7 width=4) (...)

    ->  Bitmap Heap Scan on f_ticketupdate_aad5jtwal0ayaax f
          (cost=1633.90..214617.67 rows=87472 width=4)
          (actual time=0.003..0.003 rows=0 loops=7)
        Recheck Cond: (dt_event_id = d.id)

        ->  Bitmap Index Scan on f_ticketupdate_aad5jtwal0ayaa ...
              (cost=0.00..1612.03 rows=87472 width=0)
              (actual time=0.003..0.003 rows=0 loops=7)
            Index Cond: (dt_event_id = d.id)

I.e. the database believes the bitmap index scan will match 87k rows.
But in fact it matches 0, which makes the bitmap heap scan entirely
unnecessary (thus costing nothing, because it's skipped).

Of course, the parallel plan is structured slightly differently, and
does not allow this skipping because it places the f_ table on the outer
side of the join (and scans it using sequential scan).

Now, try changing the parameters (particularly id_euweek) so that the
bitmap index scan actually matches something. I'm pretty sure that will
make the non-parallel case much more expensive.

Increasing the parallel_setup_cost makes the parallel plan a bit more
expensive, enough to switch to the non-parallel plan. But that's mostly
a fluke and not particularly principled way to fix this - if the cost
difference gets a bit larger (or if you increase the number of parallel
workers) it's probably going to use the parallel plan again.

Obviously, PostgreSQL 9.5 doesn't have parallel queries, so it does not
have a chance of making this mistake.

regards
-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services