Strange behavior once statistics are there
| От | Daniel Westermann (DWE) |
|---|---|
| Тема | Strange behavior once statistics are there |
| Дата | |
| Msg-id | GV0P278MB0483E7016B635E4AE6B18811D24D9@GV0P278MB0483.CHEP278.PROD.OUTLOOK.COM обсуждение исходный текст |
| Ответы |
Re: Strange behavior once statistics are there
|
| Список | pgsql-performance |
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
В списке pgsql-performance по дате отправления:
Предыдущее
От: Rollo Konig-BrockДата:
Сообщение: Why is there a tenfold difference between Postgres's alleged query execution time and packet transmission time?