Strange behavior once statistics are there

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Hi,

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):

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=10749 loops=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=80 loops=1)
                           Buffers: shared hit=21842546
                           ->  Nested Loop  (cost=28.76..678087.75 rows=4 width=16) (actual time=198.414..13418.767 rows=80 loops=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=80 loops=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.69 rows=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=8 loops=54472)
                                             Buffers: shared hit=22
                                             ->  Nested Loop  (cost=9.14..14.21 rows=1 width=8) (actual time=0.534..0.564 rows=8 loops=1)
                                                   Buffers: shared hit=22
                                                   ->  Seq Scan on zid_zieldefinition zieldefini5_  (cost=0.00..1.05 rows=1 width=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.15 rows=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.499 rows=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=64293 loops=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=892 width=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) (actual time=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.001 rows=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.001 rows=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=1 loops=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 something like 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=80 loops=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.340 rows=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=54472 loops=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=54472 loops=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=54472 width=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=64293 loops=1)
                                Buffers: shared hit=1970
                                ->  Seq Scan on stuv_stufe_vorgabe stufevorga8_  (cost=0.00..1.12 rows=4 width=8) (actual time=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=19829 width=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) (actual time=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=1867 width=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) (actual time=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.364 rows=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





[Postgresql General]     [Postgresql PHP]     [PHP Users]     [PHP Home]     [PHP on Windows]     [Kernel Newbies]     [PHP Classes]     [PHP Books]     [PHP Databases]     [Yosemite]

  Powered by Linux