From: Aleksandr Vinokurov <aleksandr.vin@gmail.com>
To: pgsql-sql@postgresql.org
Subject: 8.0.1 to 8.0.13 upgrade added 15% lack of time of query execution
Date: Tue, 04 Sep 2007 14:37:36 +0400
Message-ID: <46DD3570.5090801@gmail.com> (raw)
Hello all,
I beg your pardon if I do not know some thing, but I was disappointed
after taken an upgrade from 8.0.1 to 8.0.13, now the query, that I had
optimized so far to run for 92 sec on 8.0.1, takes 106 seconds on 8.0.13.
The plan seems to stay unmodified, except statistics used for its
construction, but one nested loop's actual time was largely increased:
[For 8.0.13]
Nested Loop Left Join (cost=113409.50..137207.88 rows=12214 width=146)
(actual time=37839.806..104026.224 rows=26139 loops=1)
[For 8.0.1]
Nested Loop Left Join (cost=116564.46..119674.74 rows=1597 width=146)
(actual time=32120.292..90484.361 rows=26139 loops=1)
What I have done upgrading:
1. As rel.notes says I don't need dump/restore to perform my upgrade,
even initdb is not needed for me, as I don't want to add security
enhancements for now.
2. Compiled 8.0.13 from sources and have installed to a separate
location (/usr/local/pgsql instead of old /usr/bin, /usr/lib,..)
3. chown-ed all stuff to postgres in /usr/local/pgsql
4. run postmaster with the old data directory specified.
5. reindexed database.
Both plans with queries echoed are attached to this email.
Will appreciate any help in navigating me to the right way.
With best regards,
Aleksandr.
Attachments:8.0.13.txt (text/plain, 11.8K) download
Timing is on.
explain analyze
select log_rec_id,
log_date,
log_uid,
log_name,
array_accum(trim(trailing ' ' from gh_name)) as groups
from (
select distinct on (log_rec_id, start_rec_id, fin_rec_id, gm_rec_id)
log_rec_id,
log_date,
log_uid,
log_name,
start_rec_id,
start_date,
start_action,
start_uid,
start_name,
fin_rec_id,
fin_date,
fin_action,
fin_uid,
fin_name,
gm_rec_id,
gm_date,
gm_gid,
gm_uid,
gh.rec_id as gh_rec_id,
gh.date as gh_date,
gh.action as gh_action,
gh.gid as gh_gid,
gh.name as gh_name
from (
select *
from group_history
where action <> 1
) as gh
right join (
select log_rec_id,
log_date,
log_uid,
log_name,
start_rec_id,
start_date,
start_action,
start_uid,
start_name,
fin_rec_id,
fin_date,
fin_action,
fin_uid,
fin_name,
max(gm_rec_id) as gm_rec_id,
max(gm_date) as gm_date,
gm_gid,
gm_uid
from (
select
luid.*,
gmh.rec_id as gm_rec_id,
gmh.date as gm_date,
gmh.gid as gm_gid,
gmh.uid as gm_uid,
gmh.action as gm_action
from group_member_history as gmh
right join (
select distinct on (cuh.log_rec_id, cuh.start_rec_id)
cuh.*, duh.*
from (
select rec_id as fin_rec_id,
date as fin_date,
action as fin_action,
uid as fin_uid,
name as fin_name
from "user_history"
where 1 = 1
and action <> 0
) as duh
right join (
select distinct on (log.rec_id)
log.rec_id as log_rec_id,
log.date as log_date,
log.uid as log_uid,
log.name as log_name,
uh.rec_id as start_rec_id,
uh.date as start_date,
uh.action as start_action,
uh.uid as start_uid,
uh.name as start_name
from (
select *
from "user_history"
where 1 = 1
and action <> 1
order by date
) as uh
right join log_example_3 as log
on log.name = uh.name
and uh.date <= log.date
order by log.rec_id, start_date desc
) as cuh
on cuh.start_uid = duh.fin_uid
and duh.fin_date > cuh.start_date and duh.fin_date <= cuh.log_date
order by cuh.log_rec_id, cuh.start_rec_id, duh.fin_rec_id
) as luid
on gmh.uid = luid.start_uid
and gmh.date <= luid.log_date
) as lgm
group by
log_rec_id,
log_date,
log_uid,
log_name,
start_rec_id,
start_date,
start_action,
start_uid,
start_name,
fin_rec_id,
fin_date,
fin_action,
fin_uid,
fin_name,
gm_gid,
gm_uid
having count(gm_action) % 2 = 1 or count(gm_action) = 0
order by log_date
) as lgm
on gh.gid = lgm.gm_gid
and gh.date <= lgm.log_date
order by log_rec_id, start_rec_id, fin_rec_id, gm_rec_id, gh.date desc
) as lgs
group by log_rec_id,
log_date,
log_uid,
log_name
order by log_date;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Sort (cost=474081.11..474081.61 rows=200 width=44) (actual time=106257.763..106257.826 rows=99 loops=1)
Sort Key: log_date
-> HashAggregate (cost=474071.97..474073.47 rows=200 width=44) (actual time=106256.992..106257.370 rows=99 loops=1)
-> Subquery Scan lgs (cost=473762.44..474069.47 rows=200 width=44) (actual time=106120.752..106252.791 rows=439 loops=1)
-> Unique (cost=473762.44..474067.47 rows=200 width=146) (actual time=106120.730..106250.633 rows=439 loops=1)
-> Sort (cost=473762.44..473823.45 rows=24402 width=146) (actual time=106120.725..106167.605 rows=26139 loops=1)
Sort Key: lgm.log_rec_id, lgm.start_rec_id, lgm.fin_rec_id, lgm.gm_rec_id, group_history.date
-> Nested Loop Left Join (cost=423167.49..470717.12 rows=24402 width=146) (actual time=38008.544..104621.914 rows=26139 loops=1)
-> Subquery Scan lgm (cost=423167.49..423180.10 rows=1009 width=114) (actual time=37999.620..38020.013 rows=439 loops=1)
-> Sort (cost=423167.49..423170.01 rows=1009 width=116) (actual time=37999.577..38000.906 rows=439 loops=1)
Sort Key: luid.log_date
-> HashAggregate (cost=423099.49..423117.15 rows=1009 width=116) (actual time=37987.015..37992.474 rows=439 loops=1)
Filter: (((count("action") % 2::bigint) = 1) OR (count("action") = 0))
-> Nested Loop Left Join (cost=420324.50..423049.04 rows=1009 width=116) (actual time=23095.772..37964.811 rows=649 loops=1)
-> Subquery Scan luid (cost=420324.50..420401.68 rows=200 width=94) (actual time=23008.447..23013.898 rows=100 loops=1)
-> Unique (cost=420324.50..420399.68 rows=200 width=94) (actual time=23008.423..23010.056 rows=100 loops=1)
-> Sort (cost=420324.50..420349.56 rows=10023 width=94) (actual time=23008.420..23008.685 rows=100 loops=1)
Sort Key: cuh.log_rec_id, cuh.start_rec_id, user_history.rec_id
-> Nested Loop Left Join (cost=393212.64..419349.16 rows=10023 width=94) (actual time=22970.868..23008.138 rows=100 loops=1)
-> Subquery Scan cuh (cost=393212.64..397929.07 rows=1270 width=62) (actual time=22970.581..23002.793 rows=100 loops=1)
-> Unique (cost=393212.64..397916.37 rows=1270 width=62) (actual time=22970.552..23002.062 rows=100 loops=1)
-> Sort (cost=393212.64..395564.50 rows=940745 width=62) (actual time=22970.545..22991.513 rows=13370 loops=1)
Sort Key: log.rec_id, uh.date
-> Merge Left Join (cost=96489.11..145884.54 rows=940745 width=62) (actual time=19912.409..21387.461 rows=13370 loops=1)
Merge Cond: ("outer".name = "inner".name)
Join Filter: ("inner".date <= "outer".date)
-> Sort (cost=88.17..91.35 rows=1270 width=30) (actual time=0.883..0.978 rows=100 loops=1)
Sort Key: log.name
-> Seq Scan on log_example_3 log (cost=0.00..22.70 rows=1270 width=30) (actual time=0.095..0.226 rows=100 loops=1)
-> Sort (cost=96400.94..97512.05 rows=444446 width=32) (actual time=19911.406..20538.097 rows=442847 loops=1)
Sort Key: uh.name
-> Subquery Scan uh (cost=0.00..25148.24 rows=444446 width=32) (actual time=0.311..3701.655 rows=442203 loops=1)
-> Index Scan using indx_date_action02_user_history on user_history (cost=0.00..20703.78 rows=444446 width=32) (actual time=0.283..2116.739 rows=442203 loops=1)
Filter: ("action" <> 1)
-> Index Scan using indx_date_action12_uid_user_his on user_history (cost=0.00..16.73 rows=8 width=32) (actual time=0.039..0.039 rows=0 loops=100)
Index Cond: ((user_history.date > "outer".start_date) AND (user_history.date <= "outer".log_date) AND ("outer".start_uid = user_history.uid))
Filter: ("action" <> 0)
-> Index Scan using indx_date_uid_on_group_member_h on group_member_history gmh (cost=0.00..13.15 rows=6 width=22) (actual time=91.857..149.215 rows=6 loops=100)
Index Cond: ((gmh.date <= "outer".log_date) AND (gmh.uid = "outer".start_uid))
-> Index Scan using indx_date_action02_gid_group_hist on group_history (cost=0.00..46.74 rows=25 width=32) (actual time=18.426..150.047 rows=59 loops=439)
Index Cond: ((group_history.date <= "outer".log_date) AND (group_history.gid = "outer".gm_gid))
Filter: ("action" <> 1)
Total runtime: 106286.624 ms
(43 rows)
Time: 106316.253 ms
;
Time: 0.344 ms
8.0.1.txt (text/plain, 11.7K) download
Timing is on.
explain analyze
select log_rec_id,
log_date,
log_uid,
log_name,
array_accum(trim(trailing ' ' from gh_name)) as groups
from (
select distinct on (log_rec_id, start_rec_id, fin_rec_id, gm_rec_id)
log_rec_id,
log_date,
log_uid,
log_name,
start_rec_id,
start_date,
start_action,
start_uid,
start_name,
fin_rec_id,
fin_date,
fin_action,
fin_uid,
fin_name,
gm_rec_id,
gm_date,
gm_gid,
gm_uid,
gh.rec_id as gh_rec_id,
gh.date as gh_date,
gh.action as gh_action,
gh.gid as gh_gid,
gh.name as gh_name
from (
select *
from group_history
where action <> 1
) as gh
right join (
select log_rec_id,
log_date,
log_uid,
log_name,
start_rec_id,
start_date,
start_action,
start_uid,
start_name,
fin_rec_id,
fin_date,
fin_action,
fin_uid,
fin_name,
max(gm_rec_id) as gm_rec_id,
max(gm_date) as gm_date,
gm_gid,
gm_uid
from (
select
luid.*,
gmh.rec_id as gm_rec_id,
gmh.date as gm_date,
gmh.gid as gm_gid,
gmh.uid as gm_uid,
gmh.action as gm_action
from group_member_history as gmh
right join (
select distinct on (cuh.log_rec_id, cuh.start_rec_id)
cuh.*, duh.*
from (
select rec_id as fin_rec_id,
date as fin_date,
action as fin_action,
uid as fin_uid,
name as fin_name
from "user_history"
where 1 = 1
and action <> 0
) as duh
right join (
select distinct on (log.rec_id)
log.rec_id as log_rec_id,
log.date as log_date,
log.uid as log_uid,
log.name as log_name,
uh.rec_id as start_rec_id,
uh.date as start_date,
uh.action as start_action,
uh.uid as start_uid,
uh.name as start_name
from (
select *
from "user_history"
where 1 = 1
and action <> 1
order by date
) as uh
right join log_example_3 as log
on log.name = uh.name
and uh.date <= log.date
order by log.rec_id, start_date desc
) as cuh
on cuh.start_uid = duh.fin_uid
and duh.fin_date > cuh.start_date and duh.fin_date <= cuh.log_date
order by cuh.log_rec_id, cuh.start_rec_id, duh.fin_rec_id
) as luid
on gmh.uid = luid.start_uid
and gmh.date <= luid.log_date
) as lgm
group by
log_rec_id,
log_date,
log_uid,
log_name,
start_rec_id,
start_date,
start_action,
start_uid,
start_name,
fin_rec_id,
fin_date,
fin_action,
fin_uid,
fin_name,
gm_gid,
gm_uid
having count(gm_action) % 2 = 1 or count(gm_action) = 0
order by log_date
) as lgm
on gh.gid = lgm.gm_gid
and gh.date <= lgm.log_date
order by log_rec_id, start_rec_id, fin_rec_id, gm_rec_id, gh.date desc
) as lgs
group by log_rec_id,
log_date,
log_uid,
log_name
order by log_date;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Sort (cost=138756.59..138757.09 rows=200 width=44) (actual time=105687.904..105687.957 rows=99 loops=1)
Sort Key: log_date
-> HashAggregate (cost=138747.45..138748.95 rows=200 width=44) (actual time=105687.144..105687.514 rows=99 loops=1)
-> Subquery Scan lgs (cost=138590.27..138744.95 rows=200 width=44) (actual time=105551.353..105682.866 rows=439 loops=1)
-> Unique (cost=138590.27..138742.95 rows=200 width=146) (actual time=105551.331..105680.743 rows=439 loops=1)
-> Sort (cost=138590.27..138620.81 rows=12214 width=146) (actual time=105551.327..105597.393 rows=26139 loops=1)
Sort Key: lgm.log_rec_id, lgm.start_rec_id, lgm.fin_rec_id, lgm.gm_rec_id, group_history.date
-> Nested Loop Left Join (cost=113409.50..137207.88 rows=12214 width=146) (actual time=37839.806..104026.224 rows=26139 loops=1)
-> Subquery Scan lgm (cost=113409.50..113415.82 rows=505 width=114) (actual time=37822.684..37843.423 rows=439 loops=1)
-> Sort (cost=113409.50..113410.77 rows=505 width=116) (actual time=37822.644..37823.883 rows=439 loops=1)
Sort Key: luid.log_date
-> HashAggregate (cost=113377.99..113386.83 rows=505 width=116) (actual time=37815.181..37820.611 rows=439 loops=1)
Filter: (((count("action") % 2::bigint) = 1) OR (count("action") = 0))
-> Nested Loop Left Join (cost=112022.13..113352.74 rows=505 width=116) (actual time=22976.275..37793.331 rows=649 loops=1)
-> Subquery Scan luid (cost=112022.13..112029.06 rows=100 width=94) (actual time=22890.053..22894.801 rows=100 loops=1)
-> Unique (cost=112022.13..112028.06 rows=100 width=94) (actual time=22890.029..22891.684 rows=100 loops=1)
-> Sort (cost=112022.13..112024.11 rows=790 width=94) (actual time=22890.025..22890.289 rows=100 loops=1)
Sort Key: cuh.log_rec_id, cuh.start_rec_id, user_history.rec_id
-> Nested Loop Left Join (cost=109926.12..111984.11 rows=790 width=94) (actual time=22853.127..22889.760 rows=100 loops=1)
-> Subquery Scan cuh (cost=109926.12..110297.49 rows=100 width=62) (actual time=22852.816..22884.625 rows=100 loops=1)
-> Unique (cost=109926.12..110296.49 rows=100 width=62) (actual time=22852.787..22883.904 rows=100 loops=1)
-> Sort (cost=109926.12..110111.30 rows=74075 width=62) (actual time=22852.781..22872.931 rows=13370 loops=1)
Sort Key: log.rec_id, uh.date
-> Merge Left Join (cost=96406.26..101406.78 rows=74075 width=62) (actual time=21302.804..22659.069 rows=13370 loops=1)
Merge Cond: ("outer".name = "inner".name)
Join Filter: ("inner".date <= "outer".date)
-> Sort (cost=5.32..5.57 rows=100 width=30) (actual time=0.917..1.012 rows=100 loops=1)
Sort Key: log.name
-> Seq Scan on log_example_3 log (cost=0.00..2.00 rows=100 width=30) (actual time=0.106..0.243 rows=100 loops=1)
-> Sort (cost=96400.94..97512.05 rows=444446 width=32) (actual time=21301.771..21903.964 rows=442847 loops=1)
Sort Key: uh.name
-> Subquery Scan uh (cost=0.00..25148.24 rows=444446 width=32) (actual time=0.295..3731.180 rows=442203 loops=1)
-> Index Scan using indx_date_action02_user_history on user_history (cost=0.00..20703.78 rows=444446 width=32) (actual time=0.265..2139.737 rows=442203 loops=1)
Filter: ("action" <> 1)
-> Index Scan using indx_date_action12_uid_user_his on user_history (cost=0.00..16.73 rows=8 width=32) (actual time=0.039..0.039 rows=0 loops=100)
Index Cond: ((user_history.date > "outer".start_date) AND (user_history.date <= "outer".log_date) AND ("outer".start_uid = user_history.uid))
Filter: ("action" <> 0)
-> Index Scan using indx_date_uid_on_group_member_h on group_member_history gmh (cost=0.00..13.15 rows=6 width=22) (actual time=91.421..148.684 rows=6 loops=100)
Index Cond: ((gmh.date <= "outer".log_date) AND (gmh.uid = "outer".start_uid))
-> Index Scan using indx_date_action02_gid_group_hist on group_history (cost=0.00..46.74 rows=25 width=32) (actual time=18.262..149.055 rows=59 loops=439)
Index Cond: ((group_history.date <= "outer".log_date) AND (group_history.gid = "outer".gm_gid))
Filter: ("action" <> 1)
Total runtime: 105718.695 ms
(43 rows)
Time: 105767.508 ms
;
Time: 0.336 ms
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-sql@postgresql.org
Cc: aleksandr.vin@gmail.com
Subject: Re: 8.0.1 to 8.0.13 upgrade added 15% lack of time of query execution
In-Reply-To: <46DD3570.5090801@gmail.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox