Thread: Strange behavior once statistics are there

Strange behavior once statistics are there

From
"Daniel Westermann (DWE)"
Date:
Hi,

I currently have a strange behavior once statistics are collected. This is the statement (I don't know the application,
thestatement is as it is): 

explain (analyze, buffers) select distinct standardzi4_.code       as col_0_0_,
                person1_.personalnummer as col_1_0_,
                person1_.funktion       as col_2_0_,
                person1_.vorgesetzter   as col_3_0_,
                person1_.ga_nr          as col_5_0_,
                person1_.gueltig_ab     as col_6_0_
from pia_01.pesz_person_standardziel personstan0_
         left outer join pia_01.pes_person_zielvergabe personziel3_ on personstan0_.pes_id = personziel3_.id
         left outer join pia_01.stz_standardziel standardzi4_ on personstan0_.stz_id = standardzi4_.id
         cross join pia_01.per_person person1_
         cross join pia_01.pess_person_stufe personstan2_
         cross join pia_01.zid_zieldefinition zieldefini5_
         cross join pia_01.stuv_stufe_vorgabe stufevorga8_
where personziel3_.zid_id = zieldefini5_.id
  and personstan2_.stuv_id = stufevorga8_.id
  and zieldefini5_.jahr=2021
  and (person1_.id in
       (select persons6_.per_id from pia_01.pesr_zielvergabe_person persons6_ where personziel3_.id =
persons6_.pes_id))
  and (personstan0_.pess_id is null)
  and (personstan2_.id in
       (select stufen7_.id from pia_01.pess_person_stufe stufen7_ where personstan0_.id = stufen7_.pesz_id))
  and stufevorga8_.default_prozent_sollwert = 100
  and personziel3_.finale_vis_status = 'ANGENOMMEN';

Without any statistics the query runs quite fine (this is after a fresh import of a dump, no statistics yet):


                                                                                            QUERY PLAN
                                                                          

--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Unique  (cost=1549875.41..1550295.03 rows=23978 width=32) (actual time=14990.816..14990.842 rows=80 loops=1)
   Buffers: shared hit=24422449
   ->  Sort  (cost=1549875.41..1549935.36 rows=23978 width=32) (actual time=14990.815..14990.824 rows=80 loops=1)
         Sort Key: person1_.personalnummer, standardzi4_.code, person1_.funktion, person1_.vorgesetzter,
person1_.ga_nr,person1_.gueltig_ab 
         Sort Method: quicksort  Memory: 31kB
         Buffers: shared hit=24422449
         ->  Nested Loop  (cost=28.90..1548131.08 rows=23978 width=32) (actual time=13496.302..14990.767 rows=80
loops=1)
               Join Filter: (SubPlan 1)
               Rows Removed by Join Filter: 859840
               Buffers: shared hit=24422449
               ->  Seq Scan on per_person person1_  (cost=0.00..250.49 rows=10749 width=38) (actual time=0.025..1.119
rows=10749loops=1) 
                     Buffers: shared hit=143
               ->  Materialize  (cost=28.90..678088.61 rows=4 width=10) (actual time=0.019..1.252 rows=80 loops=10749)
                     Buffers: shared hit=21842546
                     ->  Nested Loop Left Join  (cost=28.90..678088.59 rows=4 width=10) (actual time=198.423..13419.226
rows=80loops=1) 
                           Buffers: shared hit=21842546
                           ->  Nested Loop  (cost=28.76..678087.75 rows=4 width=16) (actual time=198.414..13418.767
rows=80loops=1) 
                                 Join Filter: (SubPlan 2)
                                 Rows Removed by Join Filter: 5143360
                                 Buffers: shared hit=21842386
                                 ->  Nested Loop  (cost=9.43..5319.71 rows=1 width=24) (actual time=69.778..90.956
rows=80loops=1) 
                                       Join Filter: (personziel3_.id = personstan0_.pes_id)
                                       Rows Removed by Join Filter: 435696
                                       Buffers: shared hit=18053
                                       ->  Index Scan using dwe30 on pesz_person_standardziel personstan0_
(cost=0.29..5300.69rows=321 width=24) (actual time=0.037..25.543 rows=54472 loops=1) 
                                             Filter: (pess_id IS NULL)
                                             Rows Removed by Filter: 9821
                                             Buffers: shared hit=18031
                                       ->  Materialize  (cost=9.14..14.22 rows=1 width=8) (actual time=0.000..0.000
rows=8loops=54472) 
                                             Buffers: shared hit=22
                                             ->  Nested Loop  (cost=9.14..14.21 rows=1 width=8) (actual
time=0.534..0.564rows=8 loops=1) 
                                                   Buffers: shared hit=22
                                                   ->  Seq Scan on zid_zieldefinition zieldefini5_  (cost=0.00..1.05
rows=1width=8) (actual time=0.012..0.014 rows=1 loops=1) 
                                                         Filter: (jahr = 2021)
                                                         Rows Removed by Filter: 3
                                                         Buffers: shared hit=1
                                                   ->  Bitmap Heap Scan on pes_person_zielvergabe personziel3_
(cost=9.14..13.15rows=1 width=16) (actual time=0.514..0.537 rows=8 loops=1) 
                                                         Recheck Cond: ((zid_id = zieldefini5_.id) AND
((finale_vis_status)::text= 'ANGENOMMEN'::text)) 
                                                         Heap Blocks: exact=7
                                                         Buffers: shared hit=21
                                                         ->  BitmapAnd  (cost=9.14..9.14 rows=1 width=0) (actual
time=0.498..0.499rows=0 loops=1) 
                                                               Buffers: shared hit=14
                                                               ->  Bitmap Index Scan on dwe33  (cost=0.00..4.44 rows=21
width=0)(actual time=0.137..0.137 rows=1109 loops=1) 
                                                                     Index Cond: (zid_id = zieldefini5_.id)
                                                                     Buffers: shared hit=5
                                                               ->  Bitmap Index Scan on dwe35  (cost=0.00..4.44 rows=21
width=0)(actual time=0.345..0.345 rows=1867 loops=1) 
                                                                     Index Cond: ((finale_vis_status)::text =
'ANGENOMMEN'::text)
                                                                     Buffers: shared hit=9
                                 ->  Nested Loop  (cost=19.33..1493.56 rows=892 width=8) (actual time=0.928..14.326
rows=64293loops=80) 
                                       Buffers: shared hit=157600
                                       ->  Seq Scan on stuv_stufe_vorgabe stufevorga8_  (cost=0.00..1.12 rows=1
width=8)(actual time=0.001..0.007 rows=4 loops=80) 
                                             Filter: (default_prozent_sollwert = 100)
                                             Rows Removed by Filter: 6
                                             Buffers: shared hit=80
                                       ->  Bitmap Heap Scan on pess_person_stufe personstan2_  (cost=19.33..1483.51
rows=892width=16) (actual time=0.465..2.179 rows=16073 loops=320) 
                                             Recheck Cond: (stuv_id = stufevorga8_.id)
                                             Heap Blocks: exact=142560
                                             Buffers: shared hit=157520
                                             ->  Bitmap Index Scan on dwe32  (cost=0.00..19.11 rows=892 width=0)
(actualtime=0.427..0.427 rows=16073 loops=320) 
                                                   Index Cond: (stuv_id = stufevorga8_.id)
                                                   Buffers: shared hit=14960
                                 SubPlan 2
                                   ->  Bitmap Heap Scan on pess_person_stufe stufen7_  (cost=19.33..1483.51 rows=892
width=8)(actual time=0.001..0.002 rows=3 loops=5143440) 
                                         Recheck Cond: (personstan0_.id = pesz_id)
                                         Heap Blocks: exact=6236413
                                         Buffers: shared hit=21666733
                                         ->  Bitmap Index Scan on dwe41  (cost=0.00..19.11 rows=892 width=0) (actual
time=0.001..0.001rows=3 loops=5143440) 
                                               Index Cond: (pesz_id = personstan0_.id)
                                               Buffers: shared hit=15430320
                           ->  Index Scan using dwe26 on stz_standardziel standardzi4_  (cost=0.14..0.21 rows=1
width=10)(actual time=0.003..0.003 rows=1 loops=80) 
                                 Index Cond: (id = personstan0_.stz_id)
                                 Buffers: shared hit=160
               SubPlan 1
                 ->  Bitmap Heap Scan on pesr_zielvergabe_person persons6_  (cost=4.50..35.86 rows=28 width=8) (actual
time=0.001..0.001rows=1 loops=859920) 
                       Recheck Cond: (personziel3_.id = pes_id)
                       Heap Blocks: exact=859920
                       Buffers: shared hit=2579760
                       ->  Bitmap Index Scan on dwe40  (cost=0.00..4.49 rows=28 width=0) (actual time=0.001..0.001
rows=1loops=859920) 
                             Index Cond: (pes_id = personziel3_.id)
                             Buffers: shared hit=1719840
 Planning Time: 3.796 ms
 Execution Time: 14991.063 ms


As soon as statistics are there (default configuration of 100) it takes ages to complete and the plan changes to
somethinglike this: 

Sort  (cost=39436681358.77..39436681466.76 rows=43197 width=19) (actual time=6650173.775..6650173.787 rows=80 loops=1)
  Sort Key: person1_.personalnummer
  Sort Method: quicksort  Memory: 31kB
  Buffers: shared hit=14615335936 read=549, temp read=24 written=196
  I/O Timings: read=11.777
  ->  HashAggregate  (cost=39436677600.92..39436678032.89 rows=43197 width=19) (actual time=6650173.529..6650173.760
rows=80loops=1) 
        Group Key: person1_.personalnummer, standardzi4_.code, person1_.funktion, person1_.vorgesetzter,
person1_.ga_nr,person1_.gueltig_ab 
        Buffers: shared hit=14615335936 read=549, temp read=24 written=196
        I/O Timings: read=11.777
        ->  Hash Join  (cost=7114329.95..21693291098.12 rows=1182892433520 width=19) (actual
time=4836630.324..6650173.340rows=80 loops=1) 
              Hash Cond: (personstan0_.pes_id = personziel3_.id)
              Buffers: shared hit=14615335936 read=549, temp read=24 written=196
              I/O Timings: read=11.777
              ->  Nested Loop  (cost=0.85..6566973644.72 rows=1944203730 width=10) (actual time=2.004..6649787.421
rows=54472loops=1) 
                    Join Filter: (SubPlan 2)
                    Rows Removed by Join Filter: 3502113824
                    Buffers: shared hit=14615065561 read=549
                    I/O Timings: read=11.777
                    ->  Nested Loop Left Join  (cost=0.43..10803.16 rows=54472 width=18) (actual time=0.027..429.204
rows=54472loops=1) 
                          Buffers: shared hit=112968 read=142
                          I/O Timings: read=3.081
                          ->  Index Scan using dbi21 on pesz_person_standardziel personstan0_  (cost=0.29..2092.80
rows=54472width=24) (actual time=0.017..132.607 rows=54472 loops=1) 
                                Filter: (pess_id IS NULL)
                                Rows Removed by Filter: 9821
                                Buffers: shared hit=4024 read=142
                                I/O Timings: read=3.081
                          ->  Index Scan using dbi22 on stz_standardziel standardzi4_  (cost=0.14..0.16 rows=1
width=10)(actual time=0.003..0.003 rows=1 loops=54472) 
                                Index Cond: (id = personstan0_.stz_id)
                                Buffers: shared hit=108944
                    ->  Materialize  (cost=0.42..3691.48 rows=71384 width=8) (actual time=0.000..3.681 rows=64293
loops=54472)
                          Buffers: shared hit=1970
                          ->  Nested Loop  (cost=0.42..3334.56 rows=71384 width=8) (actual time=0.027..19.700
rows=64293loops=1) 
                                Buffers: shared hit=1970
                                ->  Seq Scan on stuv_stufe_vorgabe stufevorga8_  (cost=0.00..1.12 rows=4 width=8)
(actualtime=0.007..0.014 rows=4 loops=1) 
                                      Filter: (default_prozent_sollwert = 100)
                                      Rows Removed by Filter: 6
                                      Buffers: shared hit=1
                                ->  Index Scan using dbi24 on pess_person_stufe personstan2_  (cost=0.42..635.07
rows=19829width=16) (actual time=0.009..3.139 rows=16073 loops=4) 
                                      Index Cond: (stuv_id = stufevorga8_.id)
                                      Buffers: shared hit=1969
                    SubPlan 2
                      ->  Index Scan using dbi31 on pess_person_stufe stufen7_  (cost=0.42..2.92 rows=3 width=8)
(actualtime=0.001..0.001 rows=3 loops=3502168296) 
                            Index Cond: (pesz_id = personstan0_.id)
                            Buffers: shared hit=14614950623 read=407
                            I/O Timings: read=8.696
              ->  Hash  (cost=7065823.25..7065823.25 rows=2508548 width=25) (actual time=134.212..134.215 rows=9
loops=1)
                    Buckets: 65536  Batches: 64  Memory Usage: 556kB
                    Buffers: shared hit=270375
                    ->  Nested Loop  (cost=0.28..7065823.25 rows=2508548 width=25) (actual time=26.297..133.908 rows=9
loops=1)
                          Join Filter: (SubPlan 1)
                          Rows Removed by Join Filter: 85983
                          Buffers: shared hit=270375
                          ->  Nested Loop  (cost=0.28..201.31 rows=467 width=8) (actual time=1.708..1.911 rows=8
loops=1)
                                Join Filter: (personziel3_.zid_id = zieldefini5_.id)
                                Rows Removed by Join Filter: 1859
                                Buffers: shared hit=1508
                                ->  Index Scan using dbi35 on pes_person_zielvergabe personziel3_  (cost=0.28..172.26
rows=1867width=16) (actual time=0.014..1.047 rows=1867 loops=1) 
                                      Filter: ((finale_vis_status)::text = 'ANGENOMMEN'::text)
                                      Rows Removed by Filter: 2256
                                      Buffers: shared hit=1507
                                ->  Materialize  (cost=0.00..1.05 rows=1 width=8) (actual time=0.000..0.000 rows=1
loops=1867)
                                      Buffers: shared hit=1
                                      ->  Seq Scan on zid_zieldefinition zieldefini5_  (cost=0.00..1.05 rows=1 width=8)
(actualtime=0.007..0.007 rows=1 loops=1) 
                                            Filter: (jahr = 2021)
                                            Rows Removed by Filter: 3
                                            Buffers: shared hit=1
                          ->  Materialize  (cost=0.00..304.24 rows=10749 width=25) (actual time=0.002..1.463 rows=10749
loops=8)
                                Buffers: shared hit=143
                                ->  Seq Scan on per_person person1_  (cost=0.00..250.49 rows=10749 width=25) (actual
time=0.008..3.364rows=10749 loops=1) 
                                      Buffers: shared hit=143
                          SubPlan 1
                            ->  Index Scan using dbi36 on pesr_zielvergabe_person persons6_  (cost=0.28..2.50 rows=1
width=8)(actual time=0.001..0.001 rows=1 loops=85992) 
                                  Index Cond: (pes_id = personziel3_.id)
                                  Buffers: shared hit=268724
Planning Time: 1.680 ms
Execution Time: 6650174.623 ms

Have a look a the row estimates starting in the HasAggregate node. The behavior is the same for 9.6.20, 12.5 and
14devel.Is this a known issue? 

Regards
Daniel


Re: Strange behavior once statistics are there

From
Tom Lane
Date:
"Daniel Westermann (DWE)" <daniel.westermann@dbi-services.com> writes:
> I currently have a strange behavior once statistics are collected. This is the statement (I don't know the
application,the statement is as it is): 

I think your problem is with the subplan conditions, ie

>   and (person1_.id in
>        (select persons6_.per_id from pia_01.pesr_zielvergabe_person persons6_ where personziel3_.id =
persons6_.pes_id))
> ...
>   and (personstan2_.id in
>        (select stufen7_.id from pia_01.pess_person_stufe stufen7_ where personstan0_.id = stufen7_.pesz_id))

These essentially create weird join conditions (between person1_ and
personziel3_ in the first case or personstan2_ and personstan0_ in
the second case) that the planner has no idea how to estimate.
It just throws up its hands and uses a default selectivity of 0.5,
which is nowhere near reality in this case.

You accidentally got an acceptable (not great) plan anyway without
statistics, but not so much with statistics.  Worse yet, the subplans
have to be implemented essentially as nestloop joins.

I'd suggest trying to flatten these to be regular joins, ie
try to bring up persons6_ and stufen7_ into the main JOIN nest.
It looks like persons6_.pes_id might be unique, meaning that you
don't really need the IN behavior in the first case so flattening
it should be straightforward.  The other one is visibly not unique,
but since you're using "select distinct" at the top level anyway,
getting duplicate rows might not be a problem (unless there are
a lot of duplicates?)

            regards, tom lane



Re: Strange behavior once statistics are there

From
"Daniel Westermann (DWE)"
Date:
From: Tom Lane <tgl@sss.pgh.pa.us>
Sent: Thursday, April 15, 2021 17:00
To: Daniel Westermann (DWE) <daniel.westermann@dbi-services.com>
Cc: pgsql-performance@lists.postgresql.org <pgsql-performance@lists.postgresql.org>
Subject: Re: Strange behavior once statistics are there
 
>I'd suggest trying to flatten these to be regular joins, ie
>try to bring up persons6_ and stufen7_ into the main JOIN nest.
>It looks like persons6_.pes_id might be unique, meaning that you
>don't really need the IN behavior in the first case so flattening
>it should be straightforward.  The other one is visibly not unique,
>but since you're using "select distinct" at the top level anyway,
>getting duplicate rows might not be a problem (unless there are
>a lot of duplicates?)

Thank you, Tom