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
