Thread: BUG #7598: Loss of view performance after dump/restore of the view definition
BUG #7598: Loss of view performance after dump/restore of the view definition
From
vaclav.juza@xitee.com
Date:
The following bug has been logged on the website: Bug reference: 7598 Logged by: Vaclav Juza Email address: vaclav.juza@xitee.com PostgreSQL version: 9.2.1 Operating system: Linux 2.6.18-128.el5 x86_64 (RHEL 5.3) Description: = Hi, when a view (with the below properites) is dump and restored (no matter if using pg_dump, copied from pg_admin or using pg_views) it's performance is worse than before. The view was using tables with columns of type "character varying(xx)" and the dump inserts "::text" casts into the join conditions on these columns. In the real case we faced this problem, the performance loss was much higher on PostgreSQL 9.2.1 (3 seconds vs. 3 minutes) than on 9.1.4 (1.3 seconds vs. 7 seconds) and both variants were slower on 9.2.1 than on 9.1.4. In the test case below the behaviour is similar on both Postgres version. The testcase was created in a way that it has similar constructs as the real-word case. The testcase is initialized with the following (on our hardware it runs cca 1 minute): =3D=3D=3D=3D=3D=3D=3D=3D TEST SETUP =3D=3D=3D=3D=3D=3D=3D set search_path=3Dpublic, pg_catalog; create table testtable ( ida character varying (10), idb character varying (10), idc character varying (10), lvl numeric, val numeric ); alter table testtable add constraint pk_testtable primary key (ida, idb, idc, lvl); create table testtable2 ( ida character varying (10), idb character varying (10), idc character varying (10), idd character varying (10), lvl numeric, val numeric ); alter table testtable2 add constraint pk_testtable2 primary key (ida, idb, idc, idd, lvl); insert into testtable select 'a' || a.a, 'bb' || b.b, 'ccc' || c.c, (37*a.a + 53*b.b + 71*c.c + 101*lvl.lvl) % 512, ( 31*a.a + 17*b.b + 7*c.c + 11*lvl.lvl ) % 16 from generate_series(1, 5) a, generate_series(1, 50) b, generate_series(1, 500) c, generate_series(1, 9) lvl; insert into testtable2 select 'a' || a.a, 'bb' || b.b, 'ccc' || 5*c.c, 'dddd' || d.d, (37*a.a + 53*b.b + 71*5*c.c + 101*3*lvl.lvl) % 512, (31*a.a + 17*b.b + 7*5*c.c + 11*3*lvl.lvl) % 3 from generate_series(1, 5) a, generate_series(1, 50) b, generate_series(1, 100) c, generate_series(1, 10) d, generate_series(1, 3) lvl; create or replace view testview as select t1.ida, t1.idb, t1.idc, t1.lvl, t1.val from testtable t1 join testtable2 t6 on t6.ida=3Dt1.ida and t6.idb=3Dt1.idb and t6.idc=3Dt1.idc and t6.idd=3D'dddd1' and t6.lvl=3D ( SELECT max(t7.lvl) from testtable2 t7 where t7.ida=3Dt6.ida and t7.idb=3Dt6.idb and t7.idc=3Dt6.idc and t7.idd=3Dt6.idd and t7.lvl<300 ) where t1.lvl=3D ( SELECT max(t2.lvl) from testtable t2 where t2.ida=3Dt1.ida and t2.idb=3Dt1.idb and t2.idc=3Dt1.idc and t2.lv= l<300 ) and (t1.ida, t1.idb, t1.idc) in ( select t3.ida, t3.idb, t3.idc from testtable2 t3 join testtable t5 on t5.ida=3Dt3.ida and t5.idb=3Dt3.idb and t5.idc=3Dt3.idc where t3.lvl=3D ( SELECT min(t4.lvl) from testtable2 t4 where t4.ida=3Dt3.ida and t4.idb=3Dt3.idb and t4.idc=3Dt3.idc and t4.idd=3Dt3.idd and t4.lvl<300 ) and t3.idd=3D'dddd8' and t3.val=3D0 ) ; =3D=3D=3D=3D END TEST SETUP =3D=3D=3D=3D=3D=3D=3D The following query: select * from testview where ida=3D'a4'; has the following performance on our hardware: -- pg 9.2.1: time~=3D1.2s, cost=3D119222.86..123174.62 -- pg 9.1.4: time~=3D1.1s, cost=3D105848.75..112083.82 After recreating the view from dump or simplier from pg_views: DO language plpgsql $$ declare begin execute ''::text || ( select 'CREATE OR REPLACE VIEW ' || viewname || ' AS ' ||definition from pg_views where schemaname=3D'public' and viewname=3D'testview' ); end; $$ the same query select * from testview where ida=3D'a4'; on the same hardware has the following performance: -- pg 9.2.1: time~=3D2.5s, cost=3D578843.62..587364.78 -- pg 9.1.4: time~=3D2.5s, cost=3D513879.12..521655.37 Expected: The performance and execution plan of the query should be the same when the view is dumped and restored. Regards, Vaclav Juza
Re: BUG #7598: Loss of view performance after dump/restore of the view definition
From
Tom Lane
Date:
vaclav.juza@xitee.com writes: > when a view (with the below properites) is dump and restored (no matter if > using pg_dump, copied from pg_admin or using pg_views) it's performance is > worse than before. The view was using tables with columns of type "character > varying(xx)" and the dump inserts "::text" casts into the join conditions on > these columns. This is not the dump code's fault: those casts are legitimate, and indeed present in the original view anyway. However, the planner was having a problem with thinking that implicit and explicit casts weren't equivalent. I've committed a fix into 9.2. I'm hesitant to change the behavior further back than that, even though arguably this has been broken since 8.3. > In the real case we faced this problem, the performance loss was much higher > on PostgreSQL 9.2.1 (3 seconds vs. 3 minutes) than on 9.1.4 (1.3 seconds vs. > 7 seconds) and both variants were slower on 9.2.1 than on 9.1.4. In the test > case below the behaviour is similar on both Postgres version. It's difficult to tell whether there's any real issue here beyond that. I sometimes get a noticeably slower plan out of HEAD, but sometimes I don't, if I regenerate the random table contents. It looks to me like the slower plans occur when it changes the join ordering, but that's contingent on rowcount estimates that are equally awful in both versions; the lvl = (SELECT max/min(lvl) ...) conditions are not estimated well by any existing Postgres release. So I'm not inclined to ascribe a lot of significance to the planner's choices here. regards, tom lane
Re: BUG #7598: Loss of view performance after dump/restore of the view definition
From
Vaclav Juza
Date:
On 12/10/2012 23:24, Tom Lane wrote: > vaclav.juza@xitee.com writes: > >> In the real case we faced this problem, the performance loss was much higher >> on PostgreSQL 9.2.1 (3 seconds vs. 3 minutes) than on 9.1.4 (1.3 seconds vs. >> 7 seconds) and both variants were slower on 9.2.1 than on 9.1.4. In the test >> case below the behaviour is similar on both Postgres version. > > It's difficult to tell whether there's any real issue here beyond that. > I sometimes get a noticeably slower plan out of HEAD, but sometimes I > don't, if I regenerate the random table contents. It looks to me like > the slower plans occur when it changes the join ordering, but that's > contingent on rowcount estimates that are equally awful in both versions; > the lvl = (SELECT max/min(lvl) ...) conditions are not estimated well by > any existing Postgres release. So I'm not inclined to ascribe a lot of > significance to the planner's choices here. > > regards, tom lane > Hi, I have modified the test case (it is more similar to the real-word query), so that now it is slower on 9.2.1 than on 9.1.4 (the version with the explicit cast): Setup took cca 230s on my hw: ====== BEGIN TEST SETUP ================= set search_path=public, pg_catalog; create table testtable1 ( ida character varying (10), idb character varying (10), idc character varying (10), idd character varying (10), lvl numeric, parname character varying (10), val numeric ); alter table testtable1 add constraint pk_testtable1 primary key (ida, idb, idc, idd, parname, lvl); create table testtable2 ( ida character varying (10), idb character varying (10), idc character varying (10), lvl numeric, parname character varying (10), val numeric ); alter table testtable2 add constraint pk_testtable2 primary key (ida, idb, idc, parname, lvl); create table testtable3 ( ida character varying (10), idd character varying (10), status character(1) ); alter table testtable3 add constraint pk_testtable3 primary key (ida, idd); create table testtable4 ( ida character varying (10), idb character varying (10), idc character varying (10), detail character varying (100) ); alter table testtable4 add constraint pk_testtable4 primary key (ida, idb, idc); insert into testtable1 select 'a' || a.a, 'bb' || b.b, 'ccc' || c.c, 'dddd' || d.d, (37*a.a + 53*b.b + 71*5*c.c + 101*3*lvl.lvl) % 512, 'PARNAME' || p.p, (31*a.a + 17*b.b + 7*5*c.c + 11*3*lvl.lvl) % 2 from generate_series(1, 5) a, generate_series(1, 50) b, generate_series(1, 100) c, generate_series(1, 3) d, generate_series(1, 3) lvl, generate_series(1, 4) p; insert into testtable2 select 'a' || a.a, 'bb' || b.b, 'ccc' || 5*c.c, (37*a.a + 53*b.b + 71*2*c.c + 101*lvl.lvl) % 512, 'PARNAME' || p.p, (31*a.a + 17*b.b + 7*2*c.c + 11*lvl.lvl) % 8 from generate_series(1, 5) a, generate_series(1, 50) b, generate_series(1, 250) c, generate_series(1, 6) lvl, generate_series(1, 6) p; insert into testtable3 select 'a' || a.a, 'dddd' || d.d, chr(ascii('A') + (31*a.a + 17*d.d) % 2) from generate_series(1, 5) a, generate_series(1, 10) d; insert into testtable4 select 'a' || a.a, 'bb' || b.b, 'ccc' || 5*c.c, 'some_comment' || a.a || b.b from generate_series(1, 5) a, generate_series(1, 50) b, generate_series(1, 250) c; create or replace view testview as select ida, idb, idc, idd, lvl, parname, val from ( SELECT tt1.ida, tt1.idb, tt1.idc, tt1.idd, tt1.lvl, tt1.parname, tt1.val FROM testtable1 tt1 JOIN ( SELECT tt2.ida, tt2.idb, tt2.idc, tt2.lvl, tt2.parname FROM testtable2 tt2 JOIN testtable4 tt4 ON tt4.ida = tt2.ida AND tt4.idb = tt2.idb AND tt4.idc = tt2.idc WHERE tt2.lvl = ( SELECT max(tt2a.lvl) AS max FROM testtable2 tt2a WHERE tt2.ida = tt2a.ida AND tt2.idb = tt2a.idb AND tt2.idc = tt2a.idc AND tt2a.lvl <= 400 ) ) ip ON ip.ida = tt1.ida AND ip.idb = tt1.idb AND ip.idc = tt1.idc JOIN testtable3 tt3 ON tt3.ida = tt1.ida AND tt3.idd = tt1.idd AND tt3.status = 'A' WHERE tt1.lvl = ( ( SELECT max(tt1a.lvl) AS max FROM testtable1 tt1a WHERE tt1.ida = tt1a.ida AND tt1.idb = tt1a.idb AND tt1.idc = tt1a.idc AND tt1.idd = tt1a.idd AND tt1.parname = tt1a.parname AND tt1a.lvl <= 400 ) ) ) a where (ida, idb, idc, idd) in ( select ida, idb, idc, idd from ( SELECT tt1.ida, tt1.idb, tt1.idc, tt1.idd, tt1.lvl, tt1.parname, tt1.val FROM testtable1 tt1 JOIN ( SELECT tt2.ida, tt2.idb, tt2.idc, tt2.lvl, tt2.parname FROM testtable2 tt2 JOIN testtable4 tt4 ON tt4.ida = tt2.ida AND tt4.idb = tt2.idb AND tt4.idc = tt2.idc WHERE tt2.lvl = ( SELECT max(tt2a.lvl) AS max FROM testtable2 tt2a WHERE tt2.ida = tt2a.ida AND tt2.idb = tt2a.idb AND tt2.idc = tt2a.idc AND tt2a.lvl <= 400 ) ) ip ON ip.ida = tt1.ida AND ip.idb = tt1.idb AND ip.idc = tt1.idc JOIN testtable3 ug ON ug.ida = tt1.ida AND ug.idd = tt1.idd AND ug.status = 'A' WHERE tt1.lvl = ( ( SELECT max(tt1a.lvl) AS max FROM testtable1 tt1a WHERE tt1.ida = tt1a.ida AND tt1.idb = tt1a.idb AND tt1.idc = tt1a.idc AND tt1.idd = tt1a.idd AND tt1.parname = tt1a.parname AND tt1a.lvl <= 400 ) ) ) a where parname='PARNAME1' and val=0 ) and idd <> 'dddd8' and UPPER(idc) LIKE UPPER('CCC5%') and ida='a4'; -- pg 9.1.4: time ~= 231s -- pg 9.2.1: time ~= 215s ======= END TEST SETUP ================== select * from testview; -- pg 9.1.4 time~=2.6s cost=115295.20..119729.68 -- pg 9.2.1 time~=2.6s cost=137353.53..141869.38 DO language plpgsql $$ declare begin execute '' || ( select 'CREATE OR REPLACE VIEW ' || viewname || ' AS ' ||definition from pg_views where schemaname='public' and viewname='testview' ); end; $$ select * from testview; -- pg 9.1.4 time~=3.8s cost=23619.47..28053.95 -- pg 9.2.1 time~=8.8s cost=309502.48..314173.61 Regards, Vaclav Juza
Re: BUG #7598: Loss of view performance after dump/restore of the view definition
From
Tom Lane
Date:
Vaclav Juza <vaclav.juza@xitee.com> writes: > I have modified the test case (it is more similar to the real-word > query), so that now it is slower on 9.2.1 than on 9.1.4 (the version > with the explicit cast): FWIW, testing this on HEAD (with the patch I committed last week), I get a plan that's about 10% faster than 9.1; or if I disable index-only scans for a more level playing field, it's just about equivalent to 9.1. regards, tom lane
Re: BUG #7598: Loss of view performance after dump/restore of the view definition
From
Vaclav Juza
Date:
I was doing the test on the released 9.2.1 (without the patch). The times of the query with the original view were floating around those values, so it's maybe just a luck that it was slightly slower on 9.2.1. The big difference was after the view was restored with the explicit cast. The purpose of this updated test case was mainly that you can check which change between 9.1.4 and 9.2.1 could have caused this performance regression and if this change can have some negative impact (on different queries) even after applying the patch. Thanks for the patch anyway. Regards, Vaclav Juza On 15/10/2012 17:44, Tom Lane wrote: > Vaclav Juza <vaclav.juza@xitee.com> writes: >> I have modified the test case (it is more similar to the real-word >> query), so that now it is slower on 9.2.1 than on 9.1.4 (the version >> with the explicit cast): > > FWIW, testing this on HEAD (with the patch I committed last week), > I get a plan that's about 10% faster than 9.1; or if I disable > index-only scans for a more level playing field, it's just about > equivalent to 9.1. > > regards, tom lane >
Re: BUG #7598: Loss of view performance after dump/restore of the view definition
From
Vaclav Juza
Date:
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=3036loops=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=2511loops=1) Buffers: shared hit=51214 read=2265 -> Bitmap Heap Scan on testtable3 ug (cost=4.28..12.75 rows=1 width=76) (actualtime=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=1width=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.052rows=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.045rows=1 loops=7500) Buffers: shared hit=29825 read=175 -> Index Scan Backward using pk_testtable1 on testtable1tt1a (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 (lvlIS 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.163rows=1 loops=18216) Buffers: shared hit=575373 read=1023 -> Index Scan using pk_testtable2 on testtable2 tt2a (cost=0.00..8.99rows=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.173rows=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 = (SubPlan3))) 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.62rows=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.517rows=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) (actualtime=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.023rows=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=1loops=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=3036loops=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=2511loops=1) Buffers: shared hit=51213 read=2266 -> Bitmap Heap Scan on testtable3 ug (cost=4.28..12.75 rows=1 width=76) (actualtime=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=1width=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.055rows=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.048rows=1 loops=7500) Buffers: shared hit=29825 read=175 -> Index Only Scan Backward using pk_testtable1 on testtable1tt1a (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=1width=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.173rows=1 loops=18216) Buffers: shared hit=575373 read=1023 -> Index Only Scan using pk_testtable2 on testtable2 tt2a (cost=0.00..15.46rows=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.015rows=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.031rows=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.520rows=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=1width=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.154rows=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.114rows=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=506loops=1) Buffers: shared hit=794807 -> Nested Loop (cost=18.93..23610.86 rows=1 width=18) (actual time=6.765..7018.452 rows=3036loops=1) Buffers: shared hit=794807 -> Nested Loop (cost=18.93..19309.46 rows=1 width=70) (actual time=6.033..3944.550 rows=506loops=1) Buffers: shared hit=198476 -> Hash Join (cost=18.93..1350.80 rows=1250 width=90) (actual time=0.175..712.333rows=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) (actualtime=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=25loops=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) (actualtime=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=1loops=1500) Buffers: shared hit=6000 InitPlan 5 (returns $17) -> Limit (cost=0.00..6.28 rows=1 width=4) (actual time=0.046..0.048rows=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=1loops=18216) Buffers: shared hit=576396 -> Index Scan using pk_testtable2 on testtable2 tt2a (cost=0.00..115.33 rows=28width=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.211rows=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 = (SubPlan3))) Buffers: shared hit=11368 -> Bitmap Index Scan on pk_testtable1 (cost=0.00..4.77 rows=12 width=0) (actual time=0.049..0.049rows=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.57rows=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=6loops=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=36loops=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) (actualtime=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.024rows=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=1loops=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.113rows=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=506loops=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=3036loops=1) Buffers: shared hit=645584 read=773 -> Nested Loop (cost=1734.49..312398.36 rows=1 width=70) (actual time=156.262..863.669rows=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.397rows=2511 loops=1) Buffers: shared hit=43841 read=637 -> Index Scan using pk_testtable3 on testtable3 ug (cost=0.00..60.68 rows=4width=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.054rows=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.048rows=1 loops=7500) Buffers: shared hit=30000 -> Index Only Scan Backward using pk_testtable1 on testtable1tt1a (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=1width=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=1loops=18216) Buffers: shared hit=576395 read=1 -> Index Only Scan using pk_testtable2 on testtable2 tt2a (cost=0.00..121.58rows=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) (actualtime=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=28width=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.160rows=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=2width=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.024rows=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