Re: BUG #7598: Loss of view performance after dump/restore of the view definition

From: Vaclav Juza <vaclav(dot)juza(at)xitee(dot)com>
To: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
Cc: pgsql-bugs(at)postgresql(dot)org
Subject: Re: BUG #7598: Loss of view performance after dump/restore of the view definition
Date: 2012-10-16 13:49:32
Message-ID: 507D65EC.4090908@xitee.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-bugs

And if it helps,
see below results of my explain(analyze, buffers) where it is worse on
9.2.1 than on 9.1.4 (both on the same hardware):

Original view:
pg 9.1.4:
Nested Loop (cost=237.46..289.36 rows=1 width=254) (actual time=3998.609..5870.697 rows=1848 loops=1)
Buffers: shared hit=1044261 read=5384
-> Nested Loop (cost=237.46..281.07 rows=1 width=330) (actual time=3998.501..5844.433 rows=1848 loops=1)
Buffers: shared hit=1040565 read=5384
-> Nested Loop (cost=237.46..272.77 rows=1 width=672) (actual time=3998.357..5791.577 rows=1848 loops=1)
Buffers: shared hit=1034973 read=5384
-> Nested Loop (cost=237.46..254.75 rows=1 width=558) (actual time=3997.604..4086.442 rows=308 loops=1)
Buffers: shared hit=671036 read=5381
-> HashAggregate (cost=237.46..237.47 rows=1 width=342) (actual time=3995.176..3996.270 rows=506 loops=1)
Buffers: shared hit=659911 read=5138
-> Nested Loop (cost=4.28..237.45 rows=1 width=342) (actual time=2.679..3985.891 rows=3036 loops=1)
Buffers: shared hit=659911 read=5138
-> Nested Loop (cost=4.28..229.15 rows=1 width=304) (actual time=2.603..3896.570 rows=3036 loops=1)
Buffers: shared hit=650736 read=5138
-> Nested Loop (cost=4.28..211.13 rows=1 width=190) (actual time=1.114..680.538 rows=2511 loops=1)
Buffers: shared hit=51214 read=2265
-> Bitmap Heap Scan on testtable3 ug (cost=4.28..12.75 rows=1 width=76) (actual time=0.069..0.111 rows=5 loops=1)
Recheck Cond: ((ida)::text = 'a4'::text)
Filter: (status = 'A'::bpchar)
Buffers: shared hit=3
-> Bitmap Index Scan on pk_testtable3 (cost=0.00..4.28 rows=4 width=0) (actual time=0.034..0.034 rows=10 loops=1)
Index Cond: ((ida)::text = 'a4'::text)
Buffers: shared hit=2
-> Index Scan using pk_testtable1 on testtable1 tt1 (cost=0.00..198.37 rows=1 width=222) (actual time=29.150..134.763 rows=502
loops=5)
Index Cond: (((ida)::text = 'a4'::text) AND ((idd)::text = (ug.idd)::text) AND ((parname)::text = 'PARNAME1'::text))
Filter: ((val = 0::numeric) AND (lvl = (SubPlan 6)))
Buffers: shared hit=51211 read=2265
SubPlan 6
-> Result (cost=8.62..8.63 rows=1 width=0) (actual time=0.051..0.052 rows=1 loops=7500)
Buffers: shared hit=29825 read=175
InitPlan 5 (returns $17)
-> Limit (cost=0.00..8.62 rows=1 width=32) (actual time=0.044..0.045 rows=1 loops=7500)
Buffers: shared hit=29825 read=175
-> Index Scan Backward using pk_testtable1 on testtable1 tt1a (cost=0.00..8.62 rows=1 width=32) (actual
time=0.040..0.040 rows=1 loops=7500)
Index Cond: (((tt1.ida)::text = (ida)::text) AND ((tt1.idb)::text = (idb)::text) AND
((tt1.idc)::text = (idc)::text) AND ((tt1.idd)::text = (idd)::text) AND ((tt1.parname)::text = (parname)::text) AND (lvl IS NOT NULL) AND (lvl <= 400::numeric))
Buffers: shared hit=29825 read=175
-> Index Scan using pk_testtable2 on testtable2 tt2 (cost=0.00..18.00 rows=1 width=146) (actual time=0.218..1.272 rows=1 loops=2511)
Index Cond: (((ida)::text = 'a4'::text) AND ((idb)::text = (tt1.idb)::text) AND ((idc)::text = (tt1.idc)::text))
Filter: (lvl = (SubPlan 4))
Buffers: shared hit=599522 read=2873
SubPlan 4
-> Aggregate (cost=9.00..9.01 rows=1 width=32) (actual time=0.162..0.163 rows=1 loops=18216)
Buffers: shared hit=575373 read=1023
-> Index Scan using pk_testtable2 on testtable2 tt2a (cost=0.00..8.99 rows=1 width=32) (actual time=0.040..0.108
rows=28 loops=18216)
Index Cond: (((tt2.ida)::text = (ida)::text) AND ((tt2.idb)::text = (idb)::text) AND ((tt2.idc)::text =
(idc)::text) AND (lvl <= 400::numeric))
Buffers: shared hit=575373 read=1023
-> Index Scan using pk_testtable4 on testtable4 tt4 (cost=0.00..8.29 rows=1 width=114) (actual time=0.021..0.023 rows=1 loops=3036)
Index Cond: (((ida)::text = 'a4'::text) AND ((idb)::text = (tt2.idb)::text) AND ((idc)::text = (tt2.idc)::text))
Buffers: shared hit=9175
-> Index Scan using pk_testtable1 on testtable1 tt1 (cost=0.00..17.26 rows=1 width=254) (actual time=0.086..0.173 rows=1 loops=506)
Index Cond: (((ida)::text = 'a4'::text) AND ((idb)::text = (tt4.idb)::text) AND ((idc)::text = (tt4.idc)::text) AND ((idd)::text = (ug.idd)::text))
Filter: (((idd)::text <> 'dddd8'::text) AND (upper((idc)::text) ~~ 'CCC5%'::text) AND (lvl = (SubPlan 3)))
Buffers: shared hit=11125 read=243
SubPlan 3
-> Result (cost=8.62..8.63 rows=1 width=0) (actual time=0.048..0.049 rows=1 loops=924)
Buffers: shared hit=3681 read=15
InitPlan 2 (returns $8)
-> Limit (cost=0.00..8.62 rows=1 width=32) (actual time=0.042..0.044 rows=1 loops=924)
Buffers: shared hit=3681 read=15
-> Index Scan Backward using pk_testtable1 on testtable1 tt1a (cost=0.00..8.62 rows=1 width=32) (actual time=0.039..0.039 rows=1
loops=924)
Index Cond: (((tt1.ida)::text = (ida)::text) AND ((tt1.idb)::text = (idb)::text) AND ((tt1.idc)::text = (idc)::text) AND
((tt1.idd)::text = (idd)::text) AND ((tt1.parname)::text = (parname)::text) AND (lvl IS NOT NULL) AND (lvl <= 400::numeric))
Buffers: shared hit=3681 read=15
-> Index Scan using pk_testtable2 on testtable2 tt2 (cost=0.00..18.00 rows=1 width=146) (actual time=0.767..5.517 rows=6 loops=308)
Index Cond: (((ida)::text = 'a4'::text) AND ((idb)::text = (tt1.idb)::text) AND ((idc)::text = (tt1.idc)::text))
Filter: (lvl = (SubPlan 1))
Buffers: shared hit=363937 read=3
SubPlan 1
-> Aggregate (cost=9.00..9.01 rows=1 width=32) (actual time=0.146..0.147 rows=1 loops=11088)
Buffers: shared hit=351792
-> Index Scan using pk_testtable2 on testtable2 tt2a (cost=0.00..8.99 rows=1 width=32) (actual time=0.039..0.100 rows=28 loops=11088)
Index Cond: (((tt2.ida)::text = (ida)::text) AND ((tt2.idb)::text = (idb)::text) AND ((tt2.idc)::text = (idc)::text) AND (lvl <=
400::numeric))
Buffers: shared hit=351792
-> Index Scan using pk_testtable4 on testtable4 tt4 (cost=0.00..8.29 rows=1 width=114) (actual time=0.021..0.023 rows=1 loops=1848)
Index Cond: (((ida)::text = 'a4'::text) AND ((idb)::text = (tt2.idb)::text) AND ((idc)::text = (tt2.idc)::text))
Buffers: shared hit=5592
-> Index Scan using pk_testtable3 on testtable3 tt3 (cost=0.00..8.28 rows=1 width=76) (actual time=0.007..0.009 rows=1 loops=1848)
Index Cond: (((ida)::text = 'a4'::text) AND ((idd)::text = (tt1.idd)::text))
Filter: (status = 'A'::bpchar)
Buffers: shared hit=3696
Total runtime: 5874.032 ms

9.2.1:
Nested Loop (cost=256.64..327.24 rows=1 width=254) (actual time=4299.081..6490.252 rows=1848 loops=1)
Buffers: shared hit=1056517 read=6024 written=184
-> Nested Loop (cost=256.64..296.30 rows=1 width=596) (actual time=4298.154..4587.980 rows=308 loops=1)
Join Filter: ((tt3.idd)::text = (tt1.idd)::text)
Rows Removed by Join Filter: 616
Buffers: shared hit=692583 read=6018 written=184
-> Nested Loop (cost=256.64..272.87 rows=1 width=532) (actual time=4287.180..4319.431 rows=506 loops=1)
Buffers: shared hit=662451 read=5139
-> Nested Loop (cost=256.64..264.94 rows=1 width=418) (actual time=4287.098..4299.564 rows=506 loops=1)
Buffers: shared hit=660922 read=5139
-> HashAggregate (cost=256.64..256.65 rows=1 width=342) (actual time=4286.884..4288.415 rows=506 loops=1)
Buffers: shared hit=659910 read=5139
-> Nested Loop (cost=4.28..256.63 rows=1 width=342) (actual time=2.429..4273.182 rows=3036 loops=1)
Buffers: shared hit=659910 read=5139
-> Nested Loop (cost=4.28..248.23 rows=1 width=304) (actual time=2.363..4171.124 rows=3036 loops=1)
Buffers: shared hit=650735 read=5139
-> Nested Loop (cost=4.28..217.28 rows=1 width=190) (actual time=0.781..738.720 rows=2511 loops=1)
Buffers: shared hit=51213 read=2266
-> Bitmap Heap Scan on testtable3 ug (cost=4.28..12.75 rows=1 width=76) (actual time=0.064..0.122 rows=5 loops=1)
Recheck Cond: ((ida)::text = 'a4'::text)
Filter: (status = 'A'::bpchar)
Rows Removed by Filter: 5
Buffers: shared hit=3
-> Bitmap Index Scan on pk_testtable3 (cost=0.00..4.28 rows=4 width=0) (actual time=0.035..0.035 rows=10 loops=1)
Index Cond: ((ida)::text = 'a4'::text)
Buffers: shared hit=2
-> Index Scan using pk_testtable1 on testtable1 tt1 (cost=0.00..204.52 rows=1 width=222) (actual time=32.053..145.921 rows=502
loops=5)
Index Cond: (((ida)::text = 'a4'::text) AND ((idd)::text = (ug.idd)::text) AND ((parname)::text = 'PARNAME1'::text))
Filter: ((val = 0::numeric) AND (lvl = (SubPlan 6)))
Rows Removed by Filter: 2498
Buffers: shared hit=51210 read=2266
SubPlan 6
-> Result (cost=11.70..11.71 rows=1 width=0) (actual time=0.053..0.055 rows=1 loops=7500)
Buffers: shared hit=29825 read=175
InitPlan 5 (returns $17)
-> Limit (cost=0.00..11.70 rows=1 width=32) (actual time=0.046..0.048 rows=1 loops=7500)
Buffers: shared hit=29825 read=175
-> Index Only Scan Backward using pk_testtable1 on testtable1 tt1a (cost=0.00..11.70 rows=1 width=32)
(actual time=0.042..0.042 rows=1 loops=7500)
Index Cond: ((ida = (tt1.ida)::text) AND (idb = (tt1.idb)::text) AND (idc = (tt1.idc)::text) AND
(idd = (tt1.idd)::text) AND (parname = (tt1.parname)::text) AND (lvl IS NOT NULL) AND (lvl <= 400::numeric))
Heap Fetches: 7500
Buffers: shared hit=29825 read=175
-> Index Only Scan using pk_testtable2 on testtable2 tt2 (cost=0.00..30.93 rows=1 width=146) (actual time=0.236..1.359 rows=1
loops=2511)
Index Cond: ((ida = 'a4'::text) AND (idb = (tt1.idb)::text) AND (idc = (tt1.idc)::text))
Filter: (lvl = (SubPlan 4))
Rows Removed by Filter: 6
Heap Fetches: 18216
Buffers: shared hit=599522 read=2873
SubPlan 4
-> Aggregate (cost=15.46..15.47 rows=1 width=32) (actual time=0.172..0.173 rows=1 loops=18216)
Buffers: shared hit=575373 read=1023
-> Index Only Scan using pk_testtable2 on testtable2 tt2a (cost=0.00..15.46 rows=1 width=32) (actual time=0.041..0.120
rows=28 loops=18216)
Index Cond: ((ida = (tt2.ida)::text) AND (idb = (tt2.idb)::text) AND (idc = (tt2.idc)::text) AND (lvl <=
400::numeric))
Heap Fetches: 514512
Buffers: shared hit=575373 read=1023
-> Index Only Scan using pk_testtable4 on testtable4 tt4 (cost=0.00..8.39 rows=1 width=114) (actual time=0.024..0.026 rows=1 loops=3036)
Index Cond: ((ida = 'a4'::text) AND (idb = (tt2.idb)::text) AND (idc = (tt2.idc)::text))
Heap Fetches: 3036
Buffers: shared hit=9175
-> Index Scan using pk_testtable3 on testtable3 tt3 (cost=0.00..8.28 rows=1 width=76) (actual time=0.012..0.015 rows=1 loops=506)
Index Cond: (((ida)::text = 'a4'::text) AND ((idd)::text = (ug.idd)::text))
Filter: (status = 'A'::bpchar)
Buffers: shared hit=1012
-> Index Only Scan using pk_testtable4 on testtable4 tt4 (cost=0.00..7.92 rows=1 width=114) (actual time=0.029..0.031 rows=1 loops=506)
Index Cond: ((ida = 'a4'::text) AND (idb = (tt4.idb)::text) AND (idc = (tt4.idc)::text))
Heap Fetches: 506
Buffers: shared hit=1529
-> Index Scan using pk_testtable1 on testtable1 tt1 (cost=0.00..23.42 rows=1 width=254) (actual time=0.171..0.520 rows=2 loops=506)
Index Cond: (((ida)::text = 'a4'::text) AND ((idb)::text = (tt4.idb)::text) AND ((idc)::text = (tt4.idc)::text))
Filter: (((idd)::text <> 'dddd8'::text) AND (upper((idc)::text) ~~ 'CCC5%'::text) AND (lvl = (SubPlan 3)))
Rows Removed by Filter: 34
Buffers: shared hit=30132 read=879 written=184
SubPlan 3
-> Result (cost=11.70..11.71 rows=1 width=0) (actual time=0.055..0.056 rows=1 loops=2772)
Buffers: shared hit=11045 read=43 written=16
InitPlan 2 (returns $8)
-> Limit (cost=0.00..11.70 rows=1 width=32) (actual time=0.048..0.050 rows=1 loops=2772)
Buffers: shared hit=11045 read=43 written=16
-> Index Only Scan Backward using pk_testtable1 on testtable1 tt1a (cost=0.00..11.70 rows=1 width=32) (actual time=0.044..0.044 rows=1
loops=2772)
Index Cond: ((ida = (tt1.ida)::text) AND (idb = (tt1.idb)::text) AND (idc = (tt1.idc)::text) AND (idd = (tt1.idd)::text) AND (parname =
(tt1.parname)::text) AND (lvl IS NOT NULL) AND (lvl <= 400::numeric))
Heap Fetches: 2772
Buffers: shared hit=11045 read=43 written=16
-> Index Only Scan using pk_testtable2 on testtable2 tt2 (cost=0.00..30.93 rows=1 width=146) (actual time=0.866..6.154 rows=6 loops=308)
Index Cond: ((ida = 'a4'::text) AND (idb = (tt4.idb)::text) AND (idc = (tt4.idc)::text))
Filter: (lvl = (SubPlan 1))
Rows Removed by Filter: 30
Heap Fetches: 11088
Buffers: shared hit=363934 read=6
SubPlan 1
-> Aggregate (cost=15.46..15.47 rows=1 width=32) (actual time=0.162..0.163 rows=1 loops=11088)
Buffers: shared hit=351792
-> Index Only Scan using pk_testtable2 on testtable2 tt2a (cost=0.00..15.46 rows=1 width=32) (actual time=0.042..0.114 rows=28 loops=11088)
Index Cond: ((ida = (tt2.ida)::text) AND (idb = (tt2.idb)::text) AND (idc = (tt2.idc)::text) AND (lvl <= 400::numeric))
Heap Fetches: 313632
Buffers: shared hit=351792
Total runtime: 6493.514 ms

View with explicit casts:
pg 9.1.4:
Nested Loop (cost=23621.06..28055.12 rows=1 width=35) (actual time=7032.914..9011.217 rows=1848 loops=1)
Buffers: shared hit=1179403
-> Nested Loop (cost=23621.06..28046.84 rows=1 width=41) (actual time=7032.880..8982.230 rows=1848 loops=1)
Buffers: shared hit=1175707
-> Nested Loop (cost=23621.06..28038.53 rows=1 width=64) (actual time=7032.821..8926.450 rows=1848 loops=1)
Buffers: shared hit=1170115
-> Nested Loop (cost=23615.64..23738.09 rows=1 width=50) (actual time=7031.803..7142.837 rows=308 loops=1)
Buffers: shared hit=806175
-> HashAggregate (cost=23610.87..23610.88 rows=1 width=18) (actual time=7030.004..7031.396 rows=506 loops=1)
Buffers: shared hit=794807
-> Nested Loop (cost=18.93..23610.86 rows=1 width=18) (actual time=6.765..7018.452 rows=3036 loops=1)
Buffers: shared hit=794807
-> Nested Loop (cost=18.93..19309.46 rows=1 width=70) (actual time=6.033..3944.550 rows=506 loops=1)
Buffers: shared hit=198476
-> Hash Join (cost=18.93..1350.80 rows=1250 width=90) (actual time=0.175..712.333 rows=312500 loops=1)
Hash Cond: ((tt4.ida)::text = (ug.ida)::text)
Buffers: shared hit=461
-> Seq Scan on testtable4 tt4 (cost=0.00..1085.00 rows=62500 width=14) (actual time=0.033..89.502 rows=62500 loops=1)
Buffers: shared hit=460
-> Hash (cost=18.88..18.88 rows=4 width=76) (actual time=0.110..0.110 rows=25 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 2kB
Buffers: shared hit=1
-> Seq Scan on testtable3 ug (cost=0.00..18.88 rows=4 width=76) (actual time=0.016..0.061 rows=25 loops=1)
Filter: (status = 'A'::bpchar)
Buffers: shared hit=1
-> Index Scan using pk_testtable1 on testtable1 tt1 (cost=0.00..14.35 rows=1 width=31) (actual time=0.007..0.007 rows=0 loops=312500)
Index Cond: (((ida)::text = 'a4'::text) AND ((ida)::text = (tt4.ida)::text) AND ((idb)::text = (tt4.idb)::text) AND ((idc)::text
= (tt4.idc)::text) AND ((idd)::text = (ug.idd)::text) AND ((parname)::text = 'PARNAME1'::text))
Filter: ((val = 0::numeric) AND (lvl = (SubPlan 6)))
Buffers: shared hit=198015
SubPlan 6
-> Result (cost=6.28..6.29 rows=1 width=0) (actual time=0.054..0.055 rows=1 loops=1500)
Buffers: shared hit=6000
InitPlan 5 (returns $17)
-> Limit (cost=0.00..6.28 rows=1 width=4) (actual time=0.046..0.048 rows=1 loops=1500)
Buffers: shared hit=6000
-> Index Scan Backward using pk_testtable1 on testtable1 tt1a (cost=0.00..12.57 rows=2 width=4) (actual
time=0.042..0.042 rows=1 loops=1500)
Index Cond: (((tt1.ida)::text = (ida)::text) AND ((tt1.idb)::text = (idb)::text) AND ((tt1.idc)::text =
(idc)::text) AND ((tt1.idd)::text = (idd)::text) AND ((tt1.parname)::text = (parname)::text) AND (lvl IS NOT NULL) AND (lvl <= 400::numeric))
Buffers: shared hit=6000
-> Index Scan using pk_testtable2 on testtable2 tt2 (cost=0.00..4301.39 rows=1 width=18) (actual time=0.844..6.051 rows=6 loops=506)
Index Cond: (((ida)::text = (tt4.ida)::text) AND ((idb)::text = (tt4.idb)::text) AND ((idc)::text = (tt4.idc)::text))
Filter: (lvl = (SubPlan 4))
Buffers: shared hit=596331
SubPlan 4
-> Aggregate (cost=115.40..115.41 rows=1 width=4) (actual time=0.159..0.161 rows=1 loops=18216)
Buffers: shared hit=576396
-> Index Scan using pk_testtable2 on testtable2 tt2a (cost=0.00..115.33 rows=28 width=4) (actual time=0.043..0.109 rows=28
loops=18216)
Index Cond: (((tt2.ida)::text = (ida)::text) AND ((tt2.idb)::text = (idb)::text) AND ((tt2.idc)::text = (idc)::text) AND
(lvl <= 400::numeric))
Buffers: shared hit=576396
-> Bitmap Heap Scan on testtable1 tt1 (cost=4.77..127.13 rows=4 width=35) (actual time=0.111..0.211 rows=1 loops=506)
Recheck Cond: (((ida)::text = 'a4'::text) AND ((idb)::text = (tt1.idb)::text) AND ((idc)::text = (tt1.idc)::text) AND ((idd)::text = (tt1.idd)::text))
Filter: (((idd)::text <> 'dddd8'::text) AND (upper((idc)::text) ~~ 'CCC5%'::text) AND (lvl = (SubPlan 3)))
Buffers: shared hit=11368
-> Bitmap Index Scan on pk_testtable1 (cost=0.00..4.77 rows=12 width=0) (actual time=0.049..0.049 rows=12 loops=506)
Index Cond: (((ida)::text = 'a4'::text) AND ((idb)::text = (tt1.idb)::text) AND ((idc)::text = (tt1.idc)::text) AND ((idd)::text =
(tt1.idd)::text))
Buffers: shared hit=1600
SubPlan 3
-> Result (cost=6.28..6.29 rows=1 width=0) (actual time=0.053..0.054 rows=1 loops=924)
Buffers: shared hit=3696
InitPlan 2 (returns $8)
-> Limit (cost=0.00..6.28 rows=1 width=4) (actual time=0.047..0.048 rows=1 loops=924)
Buffers: shared hit=3696
-> Index Scan Backward using pk_testtable1 on testtable1 tt1a (cost=0.00..12.57 rows=2 width=4) (actual time=0.042..0.042 rows=1
loops=924)
Index Cond: (((tt1.ida)::text = (ida)::text) AND ((tt1.idb)::text = (idb)::text) AND ((tt1.idc)::text = (idc)::text) AND
((tt1.idd)::text = (idd)::text) AND ((tt1.parname)::text = (parname)::text) AND (lvl IS NOT NULL) AND (lvl <= 400::numeric))
Buffers: shared hit=3696
-> Bitmap Heap Scan on testtable2 tt2 (cost=5.42..4299.91 rows=36 width=18) (actual time=0.524..5.765 rows=6 loops=308)
Recheck Cond: (((ida)::text = 'a4'::text) AND ((idb)::text = (tt1.idb)::text) AND ((idc)::text = (tt1.idc)::text))
Filter: (lvl = (SubPlan 1))
Buffers: shared hit=363940
-> Bitmap Index Scan on pk_testtable2 (cost=0.00..5.42 rows=36 width=0) (actual time=0.050..0.050 rows=36 loops=308)
Index Cond: (((ida)::text = 'a4'::text) AND ((idb)::text = (tt1.idb)::text) AND ((idc)::text = (tt1.idc)::text))
Buffers: shared hit=1060
SubPlan 1
-> Aggregate (cost=115.40..115.41 rows=1 width=4) (actual time=0.151..0.152 rows=1 loops=11088)
Buffers: shared hit=351792
-> Index Scan using pk_testtable2 on testtable2 tt2a (cost=0.00..115.33 rows=28 width=4) (actual time=0.040..0.103 rows=28 loops=11088)
Index Cond: (((tt2.ida)::text = (ida)::text) AND ((tt2.idb)::text = (idb)::text) AND ((tt2.idc)::text = (idc)::text) AND (lvl <=
400::numeric))
Buffers: shared hit=351792
-> Index Scan using pk_testtable4 on testtable4 tt4 (cost=0.00..8.29 rows=1 width=14) (actual time=0.022..0.024 rows=1 loops=1848)
Index Cond: (((ida)::text = 'a4'::text) AND ((idb)::text = (tt2.idb)::text) AND ((idc)::text = (tt2.idc)::text))
Buffers: shared hit=5592
-> Index Scan using pk_testtable3 on testtable3 tt3 (cost=0.00..8.28 rows=1 width=76) (actual time=0.008..0.010 rows=1 loops=1848)
Index Cond: (((ida)::text = 'a4'::text) AND ((idd)::text = (tt1.idd)::text))
Filter: (status = 'A'::bpchar)
Buffers: shared hit=3696
Total runtime: 9014.607 ms

Pg 9.2.1:
Nested Loop (cost=316789.12..321569.63 rows=1 width=35) (actual time=7167.881..19837.510 rows=1848 loops=1)
Buffers: shared hit=3701042 read=773
-> Nested Loop (cost=316789.12..321567.91 rows=1 width=58) (actual time=7166.177..19779.950 rows=1848 loops=1)
Buffers: shared hit=3695450 read=773
-> Nested Loop (cost=316789.12..321453.32 rows=1 width=108) (actual time=7094.176..19278.978 rows=3036 loops=1)
Join Filter: ((tt1.idd)::text = (tt3.idd)::text)
Rows Removed by Join Filter: 12144
Buffers: shared hit=3627242 read=773
-> Index Scan using pk_testtable3 on testtable3 tt3 (cost=0.00..20.33 rows=1 width=76) (actual time=0.070..0.113 rows=5 loops=1)
Index Cond: ((ida)::text = 'a4'::text)
Filter: (status = 'A'::bpchar)
Rows Removed by Filter: 5
Buffers: shared hit=3
-> Nested Loop (cost=316789.12..321432.97 rows=1 width=32) (actual time=808.496..3849.543 rows=3036 loops=5)
Buffers: shared hit=3627239 read=773
-> HashAggregate (cost=316789.12..316789.13 rows=1 width=18) (actual time=807.586..808.861 rows=506 loops=5)
Buffers: shared hit=645584 read=773
-> Nested Loop (cost=1734.49..316789.11 rows=1 width=18) (actual time=157.418..4029.344 rows=3036 loops=1)
Buffers: shared hit=645584 read=773
-> Nested Loop (cost=1734.49..312398.36 rows=1 width=70) (actual time=156.262..863.669 rows=506 loops=1)
Buffers: shared hit=49388 read=637
-> Nested Loop (cost=1734.49..312391.02 rows=1 width=56) (actual time=149.813..794.397 rows=2511 loops=1)
Buffers: shared hit=43841 read=637
-> Index Scan using pk_testtable3 on testtable3 ug (cost=0.00..60.68 rows=4 width=76) (actual time=0.015..0.121 rows=25 loops=1)
Filter: (status = 'A'::bpchar)
Rows Removed by Filter: 25
Buffers: shared hit=2
-> Bitmap Heap Scan on testtable1 tt1 (cost=1734.49..78082.51 rows=8 width=31) (actual time=13.123..31.474 rows=100 loops=25)
Recheck Cond: (((ida)::text = (ug.ida)::text) AND ((ida)::text = 'a4'::text) AND ((parname)::text = 'PARNAME1'::text))
Filter: ((val = 0::numeric) AND ((ug.idd)::text = (idd)::text) AND (lvl = (SubPlan 6)))
Rows Removed by Filter: 8900
Buffers: shared hit=43839 read=637
-> Bitmap Index Scan on pk_testtable1 (cost=0.00..1734.49 rows=9120 width=0) (actual time=9.209..9.209 rows=9000 loops=25)
Index Cond: (((ida)::text = (ug.ida)::text) AND ((ida)::text = 'a4'::text) AND ((parname)::text = 'PARNAME1'::text))
Buffers: shared hit=8475 read=1
SubPlan 6
-> Result (cost=7.82..7.83 rows=1 width=0) (actual time=0.053..0.054 rows=1 loops=7500)
Buffers: shared hit=30000
InitPlan 5 (returns $17)
-> Limit (cost=0.00..7.82 rows=1 width=4) (actual time=0.046..0.048 rows=1 loops=7500)
Buffers: shared hit=30000
-> Index Only Scan Backward using pk_testtable1 on testtable1 tt1a (cost=0.00..15.65 rows=2 width=4)
(actual time=0.042..0.042 rows=1 loops=7500)
Index Cond: ((ida = (tt1.ida)::text) AND (idb = (tt1.idb)::text) AND (idc = (tt1.idc)::text) AND
(idd = (tt1.idd)::text) AND (parname = (tt1.parname)::text) AND (lvl IS NOT NULL) AND (lvl <= 400::numeric))
Heap Fetches: 7500
Buffers: shared hit=30000
-> Index Only Scan using pk_testtable4 on testtable4 tt4 (cost=0.00..7.34 rows=1 width=14) (actual time=0.023..0.023 rows=0 loops=2511)
Index Cond: ((ida = (tt1.ida)::text) AND (idb = (tt1.idb)::text) AND (idc = (tt1.idc)::text))
Heap Fetches: 506
Buffers: shared hit=5547
-> Index Only Scan using pk_testtable2 on testtable2 tt2 (cost=0.00..4390.73 rows=1 width=18) (actual time=0.891..6.234 rows=6 loops=506)
Index Cond: ((ida = (tt4.ida)::text) AND (idb = (tt4.idb)::text) AND (idc = (tt4.idc)::text))
Filter: (lvl = (SubPlan 4))
Rows Removed by Filter: 30
Heap Fetches: 18216
Buffers: shared hit=596196 read=136
SubPlan 4
-> Aggregate (cost=121.65..121.66 rows=1 width=4) (actual time=0.164..0.165 rows=1 loops=18216)
Buffers: shared hit=576395 read=1
-> Index Only Scan using pk_testtable2 on testtable2 tt2a (cost=0.00..121.58 rows=28 width=4) (actual time=0.041..0.114
rows=28 loops=18216)
Index Cond: ((ida = (tt2.ida)::text) AND (idb = (tt2.idb)::text) AND (idc = (tt2.idc)::text) AND (lvl <= 400::numeric))
Heap Fetches: 514512
Buffers: shared hit=576395 read=1
-> Index Only Scan using pk_testtable2 on testtable2 tt2 (cost=0.00..4643.83 rows=1 width=18) (actual time=0.854..5.988 rows=6 loops=2530)
Index Cond: ((ida = 'a4'::text) AND (idb = (tt1.idb)::text) AND (idc = (tt1.idc)::text))
Filter: (lvl = (SubPlan 1))
Rows Removed by Filter: 30
Heap Fetches: 91080
Buffers: shared hit=2981655
SubPlan 1
-> Aggregate (cost=121.65..121.66 rows=1 width=4) (actual time=0.158..0.159 rows=1 loops=91080)
Buffers: shared hit=2881980
-> Index Only Scan using pk_testtable2 on testtable2 tt2a (cost=0.00..121.58 rows=28 width=4) (actual time=0.040..0.111 rows=28 loops=91080)
Index Cond: ((ida = (tt2.ida)::text) AND (idb = (tt2.idb)::text) AND (idc = (tt2.idc)::text) AND (lvl <= 400::numeric))
Heap Fetches: 2572560
Buffers: shared hit=2881980
-> Index Scan using pk_testtable1 on testtable1 tt1 (cost=0.00..114.58 rows=1 width=35) (actual time=0.074..0.160 rows=1 loops=3036)
Index Cond: (((ida)::text = 'a4'::text) AND ((idb)::text = (tt2.idb)::text) AND ((idc)::text = (tt2.idc)::text) AND ((idd)::text = (tt3.idd)::text))
Filter: (((idd)::text <> 'dddd8'::text) AND (upper((idc)::text) ~~ 'CCC5%'::text) AND (lvl = (SubPlan 3)))
Rows Removed by Filter: 11
Buffers: shared hit=68208
SubPlan 3
-> Result (cost=7.82..7.83 rows=1 width=0) (actual time=0.049..0.050 rows=1 loops=5544)
Buffers: shared hit=22176
InitPlan 2 (returns $8)
-> Limit (cost=0.00..7.82 rows=1 width=4) (actual time=0.043..0.044 rows=1 loops=5544)
Buffers: shared hit=22176
-> Index Only Scan Backward using pk_testtable1 on testtable1 tt1a (cost=0.00..15.65 rows=2 width=4) (actual time=0.039..0.039 rows=1
loops=5544)
Index Cond: ((ida = (tt1.ida)::text) AND (idb = (tt1.idb)::text) AND (idc = (tt1.idc)::text) AND (idd = (tt1.idd)::text) AND (parname =
(tt1.parname)::text) AND (lvl IS NOT NULL) AND (lvl <= 400::numeric))
Heap Fetches: 5544
Buffers: shared hit=22176
-> Index Only Scan using pk_testtable4 on testtable4 tt4 (cost=0.00..1.71 rows=1 width=14) (actual time=0.022..0.024 rows=1 loops=1848)
Index Cond: ((ida = 'a4'::text) AND (idb = (tt2.idb)::text) AND (idc = (tt2.idc)::text))
Heap Fetches: 1848
Buffers: shared hit=5592
Total runtime: 19840.747 ms

In response to

Browse pgsql-bugs by date

  From Date Subject
Next Message Hedén Daniel 2012-10-16 13:55:21 Re: BUG #7602: Select with many joins against the same table is very slow compared to 9.2.0.
Previous Message Heikki Linnakangas 2012-10-16 12:31:08 Re: BUG #7534: walreceiver takes long time to detect n/w breakdown