Re: 7.3.2 vs 7.1.2

Hello.
I'm just going to upgrade from 7.1.2 to 7.3.2 and found that some
of my queries performing on 7.3.2 much slower than on 7.1.2.
For example, pretty complex query that takes 3-4 seconds on 7.1.2
now takes about 1 minute on 7.3.2.
EXPLAIN shows the pretty same total query cost (49000 on 7.1.2 vs
56000 vs 7.3.2, but 7.1.2 didn't calculate some subqueries).
What I did: make the dump from 7.1.2, load dump into 7.3.2,
tune postgresql.conf parameters like in 7.1.2, vacuum analyze.
Why is it take so long ?
P.S. Of course, I can show the query.
--
Eugene Fokin
SOLVO Ltd. Company

On Tue, 2003-05-20 at 08:28, Eugene Fokin wrote:
> Hello.
> I'm just going to upgrade from 7.1.2 to 7.3.2 and found that some
> of my queries performing on 7.3.2 much slower than on 7.1.2.

This generally indicates misconfiguration of some kind or required
tweaking.

> P.S. Of course, I can show the query.

Please show EXPLAIN ANALYZE output along with the query.
--
Rod Taylor <rbt(at)rbt(dot)ca>

PGP Key: http://www.rbt.ca/rbtpub.asc

* Eugene Fokin <elf(at)solvo(dot)ru> [20.05.2003 15:52]:
> Why is it take so long ?
> P.S. Of course, I can show the query.

Please, attach both: query and explain analyze results.
Results of:

=> select version();

are welcomed too.

--

Victor Yegorov

On Tue, May 20, 2003 at 04:09:13PM +0300, Victor Yegorov wrote:

> Please, attach both: query and explain analyze results.
> Results of:
>
> => select version();
>
> are welcomed too.

Ok.
btw, it works on 7.2.1 fine to me too (as 7.1.2).

\d loadview:

View "public.loadview"
Column | Type | Modifiers
-------------------+--------------------------+-----------
id | integer |
parent_load_id | integer |
name | character varying(10) |
code_id | integer |
rcn_id | integer |
loc_id | integer |
real_loc_id | integer |
dest_id | integer |
order_id | integer |
last_comment | character varying |
label | character varying(20) |
type | character varying(1) |
qty | integer |
qty_type | character varying(1) |
units | integer |
assigned | integer |
visible | boolean |
status | character varying(1) |
sort | integer |
dest_status | character varying(1) |
date_pour | date |
akciz_name | text |
is_ub | boolean |
is_toll | boolean |
has_receiving | boolean |
has_ub | boolean |
has_custom | boolean |
has_akciz | boolean |
owner_id | integer |
receive_type | character varying(1) |
region_units | integer |
msk_units | integer |
town_units | integer |
date_last_counted | timestamp with time zone |
counted_by | character varying(32) |
date_last_access | timestamp with time zone |
accessed_by | character varying(32) |
created | timestamp with time zone |
created_by | character varying(32) |
sku_name | character varying |
real_loc | integer |
loc_type | character varying |
View definition: SELECT l.id, l.parent_load_id, l.name, l.code_id, l.rcn_id, l.loc_id, l.real_loc_id, l.dest_id, CASE WHEN (EXISTS (SELECT orders.id FROM orders WHERE (orders.id = l.order_id))) THEN l.order_id ELSE 0 END AS order_id, (SELECT lc."comment" FROM load_comments lc WHERE (lc.id = l.last_comment_id)) AS last_comment, l.label, l."type", l.qty, l.qty_type, l.units, l.assigned, l.visible, l.status, l.sort, l.dest_status, r.date_pour, ad.name AS akciz_name, l.is_ub, l.is_toll, l.has_receiving, l.has_ub, l.has_custom, l.has_akciz, l.owner_id, l.receive_type, l.region_units, l.msk_units, l.town_units, l.date_last_counted, l.counted_by, l.date_last_access, l.accessed_by, l.created, l.created_by, (SELECT s.name FROM sku s, code_info c WHERE ((s.id = c.sku_id) AND (c.id = l.code_id))) AS sku_name, l.real_loc_id AS real_loc, (SELECT loc."type" FROM "location" loc WHERE (loc.id = l.real_loc_id)) AS loc_type FROM (((loads l JOIN (SELECT rcn_details.id, rcn_details.date_pour FROM rcn_details) r ON ((r.id = l.rcn_id))) LEFT JOIN (SELECT min(akciz.id) AS id, akciz.rcn_id FROM akciz GROUP BY akciz.rcn_id) ah ON ((ah.rcn_id = l.rcn_id))) LEFT JOIN (SELECT max((akciz_details.name)::text) AS name, akciz_details.akciz_id FROM akciz_details GROUP BY akciz_details.akciz_id) ad ON ((ad.akciz_id = ah.id)));

7.2.1:
select version ():
"PostgreSQL 7.2.1 on i686-pc-linux-gnu, compiled by GCC 2.96"

explain analyze select count(*) from loadview:

NOTICE: QUERY PLAN:

Aggregate (cost=49464.29..49464.29 rows=1 width=20) (actual time=4823.05..4823.05 rows=1 loops=1)
-> Merge Join (cost=36149.36..47306.99 rows=862919 width=20) (actual time=4081.67..4699.48 rows=147281 loops=1)
-> Sort (cost=35013.94..35013.94 rows=147281 width=16) (actual time=3851.65..3919.07 rows=147281 loops=1)
-> Merge Join (cost=1098.11..22371.18 rows=147281 width=16) (actual time=196.80..3001.89 rows=147281 loops=1)
-> Merge Join (cost=0.00..19885.60 rows=147281 width=8) (actual time=0.08..2059.89 rows=147281 loops=1)
-> Index Scan using load_rcn_id_idx on loads l (cost=0.00..17026.36 rows=147281 width=4) (actual time=0.04..786.13 rows=147281 loops=1)
-> Index Scan using rcn_detail_idx on rcn_details (cost=0.00..618.30 rows=12692 width=4) (actual time=0.03..510.13 rows=151332 loops=1)
-> Sort (cost=1098.11..1098.11 rows=1161 width=8) (actual time=196.68..273.26 rows=140535 loops=1)
-> Subquery Scan ah (cost=980.95..1039.00 rows=1161 width=8) (actual time=73.79..167.89 rows=11497 loops=1)
-> Aggregate (cost=980.95..1039.00 rows=1161 width=8) (actual time=73.78..145.90 rows=11497 loops=1)
-> Group (cost=980.95..1009.98 rows=11610 width=8) (actual time=73.76..115.53 rows=11610 loops=1)
-> Sort (cost=980.95..980.95 rows=11610 width=8) (actual time=73.75..78.99 rows=11610 loops=1)
-> Seq Scan on akciz (cost=0.00..197.10 rows=11610 width=8) (actual time=0.01..26.24 rows=11610 loops=1)
-> Sort (cost=1135.43..1135.43 rows=1172 width=15) (actual time=229.97..308.41 rows=140648 loops=1)
-> Subquery Scan ad (cost=1017.11..1075.70 rows=1172 width=15) (actual time=94.52..200.64 rows=11610 loops=1)
-> Aggregate (cost=1017.11..1075.70 rows=1172 width=15) (actual time=94.51..179.57 rows=11610 loops=1)
-> Group (cost=1017.11..1046.40 rows=11718 width=15) (actual time=94.49..135.00 rows=11718 loops=1)
-> Sort (cost=1017.11..1017.11 rows=11718 width=15) (actual time=94.47..101.80 rows=11718 loops=1)
-> Seq Scan on akciz_details (cost=0.00..225.18 rows=11718 width=15) (actual time=0.03..30.11 rows=11718 loops=1)
Total runtime: 4878.56 msec

7.3.2:
select version():
"PostgreSQL 7.3.2 on i386-redhat-linux-gnu, compiled by GCC i386-redhat-linux-gcc (GCC) 3.2.2 20030213 (Red Hat Linux 8.0 3.2.2-1)"

Also, I've tried 7.3.2 version binaries from PostgreSQL site for RH73.
And I've got the same result.

explain analyze select count(*) from loadview:

QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=57642.48..57642.48 rows=1 width=233) (actual time=43799.03..43799.03 rows=1 loops=1)
-> Subquery Scan loadview (cost=43956.42..55485.18 rows=862919 width=233) (actual time=28013.35..43638.75 rows=147281 loops=1)
-> Merge Join (cost=43956.42..55485.18 rows=862919 width=233) (actual time=28013.35..43409.03 rows=147281 loops=1)
Merge Cond: ("outer".id = "inner".akciz_id)
-> Sort (cost=42797.70..43165.90 rows=147281 width=197) (actual time=27785.80..28126.86 rows=147281 loops=1)
Sort Key: ah.id
-> Merge Join (cost=1115.13..22038.07 rows=147281 width=197) (actual time=133.98..14205.66 rows=147281 loops=1)
Merge Cond: ("outer".rcn_id = "inner".rcn_id)
-> Merge Join (cost=0.00..19524.78 rows=147281 width=189) (actual time=0.14..9419.68 rows=147281 loops=1)
Merge Cond: ("outer".rcn_id = "inner".id)
-> Index Scan using load_rcn_id_idx on loads l (cost=0.00..16659.18 rows=147281 width=181) (actual time=0.07..4486.76 rows=147281 loops=1)
-> Index Scan using rcn_detail_idx on rcn_details (cost=0.00..624.96 rows=12692 width=8) (actual time=0.02..587.84 rows=151332 loops=1)
-> Sort (cost=1115.13..1118.03 rows=1161 width=8) (actual time=133.74..214.17 rows=140535 loops=1)
Sort Key: ah.rcn_id
-> Subquery Scan ah (cost=968.95..1056.03 rows=1161 width=8) (actual time=46.03..115.21 rows=11497 loops=1)
-> Aggregate (cost=968.95..1056.03 rows=1161 width=8) (actual time=46.02..100.01 rows=11497 loops=1)
-> Group (cost=968.95..1027.00 rows=11610 width=8) (actual time=46.00..76.80 rows=11610 loops=1)
-> Sort (cost=968.95..997.98 rows=11610 width=8) (actual time=45.99..50.45 rows=11610 loops=1)
Sort Key: rcn_id
-> Seq Scan on akciz (cost=0.00..185.10 rows=11610 width=8) (actual time=0.01..19.09 rows=11610 loops=1)
-> Sort (cost=1158.72..1161.65 rows=1172 width=15) (actual time=227.16..332.79 rows=140648 loops=1)
Sort Key: ad.akciz_id
-> Subquery Scan ad (cost=1011.11..1098.99 rows=1172 width=15) (actual time=80.77..188.32 rows=11610 loops=1)
-> Aggregate (cost=1011.11..1098.99 rows=1172 width=15) (actual time=80.76..158.60 rows=11610 loops=1)
-> Group (cost=1011.11..1069.70 rows=11718 width=15) (actual time=80.73..124.73 rows=11718 loops=1)
-> Sort (cost=1011.11..1040.40 rows=11718 width=15) (actual time=80.71..88.88 rows=11718 loops=1)
Sort Key: akciz_id
-> Seq Scan on akciz_details (cost=0.00..219.18 rows=11718 width=15) (actual time=0.03..28.57 rows=11718 loops=1)
SubPlan
-> Index Scan using orders_id_idx on orders (cost=0.00..5.92 rows=1 width=4) (actual time=0.01..0.01 rows=1 loops=147281)
Index Cond: (id = $0)
-> Index Scan using load_comments_id_idx on load_comments lc (cost=0.00..5.90 rows=1 width=10) (actual time=0.01..0.01 rows=0 loops=147281)
Index Cond: (id = $1)
-> Nested Loop (cost=0.00..11.08 rows=1 width=59) (actual time=0.02..0.03 rows=1 loops=147281)
-> Index Scan using code_id_idx on code_info c (cost=0.00..5.07 rows=1 width=4) (actual time=0.01..0.01 rows=1 loops=147281)
Index Cond: (id = $2)
-> Index Scan using sku_id_idx on sku s (cost=0.00..6.00 rows=1 width=55) (actual time=0.01..0.01 rows=1 loops=147281)
Index Cond: (s.id = "outer".sku_id)
-> Index Scan using loc_g_id_idx on "location" loc (cost=0.00..5.98 rows=1 width=5) (actual time=0.01..0.01 rows=1 loops=147281)
Index Cond: (id = $3)
Total runtime: 43825.44 msec
(41 rows)

--
Eugene Fokin
SOLVO Ltd. Company

* Eugene Fokin <elf(at)solvo(dot)ru> [20.05.2003 16:33]:
> 7.2.1:
> -> Merge Join (cost=0.00..19885.60 rows=147281 width=8) (actual time=0.08..2059.89 rows=147281 loops=1)
> -> Index Scan using load_rcn_id_idx on loads l (cost=0.00..17026.36 rows=147281 width=4) (actual time=0.04..786.13 rows=147281 loops=1)
> -> Index Scan using rcn_detail_idx on rcn_details (cost=0.00..618.30 rows=12692 width=4) (actual time=0.03..510.13 rows=151332 loops=1)

snip

> 7.3.2:
> -> Merge Join (cost=0.00..19524.78 rows=147281 width=189) (actual time=0.14..9419.68 rows=147281 loops=1)
> Merge Cond: ("outer".rcn_id = "inner".id)
> -> Index Scan using load_rcn_id_idx on loads l (cost=0.00..16659.18 rows=147281 width=181) (actual time=0.07..4486.76 rows=147281 loops=1)
> -> Index Scan using rcn_detail_idx on rcn_details (cost=0.00..624.96 rows=12692 width=8) (actual time=0.02..587.84 rows=151332 loops=1)

As you can see, in 7.2.1 index scan on loads (load_rcn_id_idx) takes 0.04..786.13,
but in 7.3.2 - 0.07..4486.76.

Also, note the difference in the:

7.2.1 "... rows=147281 width=4) ..."
7.3.2 "... rows=147281 width=181) ..."

My guesses:

1. Check your index.
2. Do vacuum analyze again.
3. This part:
(loads l JOIN (SELECT rcn_details.id, rcn_details.date_pour FROM rcn_details) r ON ((r.id = l.rcn_id)))

Why do you use subselect here? It seems to me, that you can simply join
whole table, can't you?

May be somebody else will point to some other details.
Good luck!

--

Victor Yegorov

On Tue, May 20, 2003 at 05:07:13PM +0300, Victor Yegorov wrote:
>
> As you can see, in 7.2.1 index scan on loads (load_rcn_id_idx) takes 0.04..786.13,
> but in 7.3.2 - 0.07..4486.76.
>
> Also, note the difference in the:
>
> 7.2.1 "... rows=147281 width=4) ..."
> 7.3.2 "... rows=147281 width=181) ..."
>
> My guesses:
>
> 1. Check your index.
> 2. Do vacuum analyze again.
> 3. This part:
> (loads l JOIN (SELECT rcn_details.id, rcn_details.date_pour FROM rcn_details) r ON ((r.id = l.rcn_id)))
>

I've tried to simplify it, nothing happens -- the same effect !
The question is -- why it scans my indexes so long ?
I've created "clean" experiment: the same machine, the same dump.
And perform the same procedure for each DB (btw, now it's 7.2.4 vs 7.3.1 :-)):

1. Install DB.
2. Init DB.
3. Fix postgresql.conf
4. Load dump.
5. vacuum analyze.
6. query !

Difference is the same like 5 seconds vs 50 seconds...

--
Eugene Fokin
SOLVO Ltd. Company

* Eugene Fokin <elf(at)solvo(dot)ru> [20.05.2003 18:38]:
> > (loads l JOIN (SELECT rcn_details.id, rcn_details.date_pour FROM rcn_details) r ON ((r.id = l.rcn_id)))
> >

Try changing the join above to:

loads l JOIN rcn_details r ON r.id = l.rcn_id

Also, give the full description of fields, involved in your
load_rcn_id_idx and rcn_detail_idx indicies.

--

Victor Yegorov

Eugene,

> 7.2.1 "... rows=147281 width=4) ..."
> 7.3.2 "... rows=147281 width=181) ..."

Unless we have a serious bug here, Victor changed the definition of his index,
or of his table, between versions. Or mabye type casting during upgade
changed it?

Please post the definition of "loads" and " load_rcn_id_idx" in each system,
Victor. Intentionally or not, you changed it between systems.

--
Josh Berkus
Aglio Database Solutions
San Francisco

Eugene, Victor,

Sorry! I got the two of you mixed up ... who was asking, who was answering.
Please transpose your two names in my last post!

--
Josh Berkus
Aglio Database Solutions
San Francisco

Eugene,

Another question ... given that 7.3.2's estimates are very similar to 7.2.1's
estimates, but the real execution time is much slower, is it possible that
the 7.3.2 copy of the database is being loaded on a much slower disk?

--
Josh Berkus
Aglio Database Solutions
San Francisco

Victor Yegorov <viktors(dot)jegorovs(at)nordlb(dot)lv> writes:
> As you can see, in 7.2.1 index scan on loads (load_rcn_id_idx) takes
> 0.04..786.13, but in 7.3.2 - 0.07..4486.76.

That seems very odd, doesn't it? Is it reproducible? I'm wondering if
the 7.2 table was clustered on the index while the 7.3 wasn't.

Most of the cost differential, however, is coming from the fact that 7.3
doesn't flatten the view and thus fails to realize that it doesn't need
to evaluate any of the view's targetlist expressions. Note the lack of
any "SubPlans" in the 7.2 plan, whereas they're accounting for a good
deal of time in the 7.3 plan.

The reason that the view isn't flattened is that pulling up targetlists
containing sub-selects turned out to break some obscure cases involving
join alias variables, and by the time we discovered this (after 7.3
release) there was no practical way to fix it except to disable the
optimization. It's fixed properly in CVS tip (7.4 branch) but 7.3.* is
just going to be slow on such cases; the fix is much too complex to risk
back-porting.

I'm not sure whether selecting the count from this view is really all
that important to Eugene, but if it is he could make an alternate view
that has the same FROM clause and nothing interesting in its select
list, and then count that.

regards, tom lane

Josh Berkus <josh(at)agliodbs(dot)com> writes:
> Another question ... given that 7.3.2's estimates are very similar to 7.2.1's
> estimates, but the real execution time is much slower, is it possible that
> the 7.3.2 copy of the database is being loaded on a much slower disk?

Nah, the big reason for the discrepancy is that 7.3 is unable to prune
away evaluation of all those sub-selects in the view's target list, per
my previous response.

Up till just recently (post-7.3) the planner didn't bother to charge any
evaluation cost for targetlist expressions, and so the estimated costs
don't reflect the difference.

(The reasoning behind that behavior was that the planner couldn't affect
the evaluation costs of targetlist expressions by choosing a different
plan, since the number of rows they'll be computed for will be the same
in every correct plan. But now that we allow arbitrarily complex stuff
in sub-selects, that reasoning doesn't hold water anymore --- it's
important to propagate a good estimate of the cost up to the enclosing
plan. So as of 7.4 we expend the cycles to add in tlist execution time
estimates.)

I am still interested in the apparent difference in the time taken for
that bottom indexscan, though. The width difference that you noticed is
because the unflattened view needs to fetch many more columns of the
table than the flattened query needs. But the same number of rows get
fetched, and approximately the same number of disk blocks ought to get
read, so it's hard to see why there'd be such a large difference.

regards, tom lane

On Tue, May 20, 2003 at 06:58:01PM +0300, Victor Yegorov wrote:
>
> Try changing the join above to:
>
> loads l JOIN rcn_details r ON r.id = l.rcn_id
>

Nothing, I mean - the same result.

>
> Also, give the full description of fields, involved in your
> load_rcn_id_idx and rcn_detail_idx indicies.
>

\d load_rcn_id_idx:

Index "public.load_rcn_id_idx"
Column | Type
--------+---------
rcn_id | integer
btree, for table "public.loads"

\d loads:

...
rcn_id | integer | not null default 0
...

\d rcn_detail_idx:

Index "public.rcn_detail_idx"
Column | Type
--------+---------
id | integer
unique, btree, for table "public.rcn_details"

\d rcn_details:

...
id | integer | default nextval('rcn_details_id'::text)
...

\d rcn_details_id

Sequence "public.rcn_details_id"
Column | Type
---------------+---------
sequence_name | name
last_value | bigint
increment_by | bigint
max_value | bigint
min_value | bigint
cache_value | bigint
log_cnt | bigint
is_cycled | boolean
is_called | boolean

--
Eugene Fokin
SOLVO Ltd. Company

On Tue, May 20, 2003 at 09:30:20AM -0700, Josh Berkus wrote:
>
> > 7.2.1 "... rows=147281 width=4) ..."
> > 7.3.2 "... rows=147281 width=181) ..."
>
> Unless we have a serious bug here, Victor changed the definition of his index,
> or of his table, between versions. Or mabye type casting during upgade
> changed it?
>
> Please post the definition of "loads" and " load_rcn_id_idx" in each system,
> Victor. Intentionally or not, you changed it between systems.

Nothing changed ! Believe me :-)
Same dump file, same platform, even the same machine.
I've post already necessary definitions.

--
Eugene Fokin
SOLVO Ltd. Company

On Tue, May 20, 2003 at 12:40:21PM -0400, Tom Lane wrote:
>
> [...skipped...]
>
> I'm not sure whether selecting the count from this view is really all
> that important to Eugene, but if it is he could make an alternate view
> that has the same FROM clause and nothing interesting in its select
> list, and then count that.
>

This is the one sample from the working system for which I'm trying
to upgrade the database.

And you're right. I've removed all subqueries from select list and I've
got original 5 seconds ! After that I tried to add one subquery back (the
simpliest one) and got the same 40-50 seconds again !

--
Eugene Fokin
SOLVO Ltd. Company