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

The following bug has been logged on the website:

Bug reference: 7598
Logged by: Vaclav Juza
Email address: vaclav(dot)juza(at)xitee(dot)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):
======== TEST SETUP =======
set search_path=public, 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=t1.ida and t6.idb=t1.idb and t6.idc=t1.idc and
t6.idd='dddd1'
and t6.lvl=
(
SELECT max(t7.lvl)
from testtable2 t7
where t7.ida=t6.ida and t7.idb=t6.idb and t7.idc=t6.idc
and t7.idd=t6.idd and t7.lvl<300
)
where t1.lvl=
(
SELECT max(t2.lvl)
from testtable t2
where t2.ida=t1.ida and t2.idb=t1.idb and t2.idc=t1.idc and t2.lvl<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=t3.ida and t5.idb=t3.idb and t5.idc=t3.idc
where t3.lvl=
(
SELECT min(t4.lvl)
from testtable2 t4
where t4.ida=t3.ida and t4.idb=t3.idb and t4.idc=t3.idc and
t4.idd=t3.idd
and t4.lvl<300
)
and t3.idd='dddd8' and t3.val=0
)
;

==== END TEST SETUP =======

The following query:
select * from testview where ida='a4';
has the following performance on our hardware:
-- pg 9.2.1: time~=1.2s, cost=119222.86..123174.62
-- pg 9.1.4: time~=1.1s, cost=105848.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='public' and viewname='testview'
);
end;
$$

the same query
select * from testview where ida='a4';
on the same hardware has the following performance:
-- pg 9.2.1: time~=2.5s, cost=578843.62..587364.78
-- pg 9.1.4: time~=2.5s, cost=513879.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

vaclav(dot)juza(at)xitee(dot)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

On 12/10/2012 23:24, Tom Lane wrote:
> vaclav(dot)juza(at)xitee(dot)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

Vaclav Juza <vaclav(dot)juza(at)xitee(dot)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

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(dot)juza(at)xitee(dot)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
>

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