8.0.1 to 8.0.13 upgrade added 15% lack of time of query execution - Mailing list pgsql-sql
| From | Aleksandr Vinokurov |
|---|---|
| Subject | 8.0.1 to 8.0.13 upgrade added 15% lack of time of query execution |
| Date | |
| Msg-id | 46DD3570.5090801@gmail.com Whole thread Raw |
| Responses |
Re: 8.0.1 to 8.0.13 upgrade added 15% lack of time of query execution
|
| List | pgsql-sql |
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.
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=439loops=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=26139loops=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.914rows=26139 loops=1)
-> Subquery Scan lgm (cost=423167.49..423180.10 rows=1009 width=114) (actual
time=37999.620..38020.013rows=439 loops=1)
-> Sort (cost=423167.49..423170.01 rows=1009 width=116) (actual
time=37999.577..38000.906rows=439 loops=1)
Sort Key: luid.log_date
-> HashAggregate (cost=423099.49..423117.15 rows=1009 width=116) (actual
time=37987.015..37992.474rows=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.16rows=10023 width=94) (actual time=22970.868..23008.138 rows=100 loops=1)
-> Subquery Scan cuh
(cost=393212.64..397929.07rows=1270 width=62) (actual time=22970.581..23002.793 rows=100 loops=1)
-> Unique
(cost=393212.64..397916.37rows=1270 width=62) (actual time=22970.552..23002.062 rows=100 loops=1)
-> Sort
(cost=393212.64..395564.50rows=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.54rows=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.35rows=1270 width=30) (actual time=0.883..0.978 rows=100 loops=1)
Sort
Key:log.name
-> Seq
Scanon 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.05rows=444446 width=32) (actual time=19911.406..20538.097 rows=442847 loops=1)
Sort
Key:uh.name
->
SubqueryScan 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.739rows=442203 loops=1)
Filter: ("action" <> 1)
-> Index Scan using
indx_date_action12_uid_user_hison 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_historygmh (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.74rows=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
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=439loops=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=26139loops=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.224rows=26139 loops=1)
-> Subquery Scan lgm (cost=113409.50..113415.82 rows=505 width=114) (actual
time=37822.684..37843.423rows=439 loops=1)
-> Sort (cost=113409.50..113410.77 rows=505 width=116) (actual
time=37822.644..37823.883rows=439 loops=1)
Sort Key: luid.log_date
-> HashAggregate (cost=113377.99..113386.83 rows=505 width=116) (actual
time=37815.181..37820.611rows=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.11rows=790 width=94) (actual time=22853.127..22889.760 rows=100 loops=1)
-> Subquery Scan cuh
(cost=109926.12..110297.49rows=100 width=62) (actual time=22852.816..22884.625 rows=100 loops=1)
-> Unique
(cost=109926.12..110296.49rows=100 width=62) (actual time=22852.787..22883.904 rows=100 loops=1)
-> Sort
(cost=109926.12..110111.30rows=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.78rows=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.57rows=100 width=30) (actual time=0.917..1.012 rows=100 loops=1)
Sort
Key:log.name
-> Seq
Scanon 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.05rows=444446 width=32) (actual time=21301.771..21903.964 rows=442847 loops=1)
Sort
Key:uh.name
->
SubqueryScan 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.737rows=442203 loops=1)
Filter: ("action" <> 1)
-> Index Scan using
indx_date_action12_uid_user_hison 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_historygmh (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.74rows=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