Thread: 8.0.1 to 8.0.13 upgrade added 15% lack of time of query execution
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
Re: 8.0.1 to 8.0.13 upgrade added 15% lack of time of query execution
From
Aleksandr Vinokurov
Date:
Sorry, just noticed that both query plans are actually for the 8.0.13 release. This one is right: "Total runtime: 93866.526 ms" Any suggestions? Please. Aleksandr Vinokurov wrote: > Both plans with queries echoed are attached to this email. 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=114905.79..114905.79 rows=1 width=44) (actual time=93817.815..93817.870 rows=99 loops=1) Sort Key: log_date -> HashAggregate (cost=114905.77..114905.78 rows=1 width=44) (actual time=93817.110..93817.450 rows=99 loops=1) -> Subquery Scan lgs (cost=114888.70..114905.69 rows=6 width=44) (actual time=93704.252..93812.964 rows=439 loops=1) -> Unique (cost=114888.70..114905.63 rows=6 width=146) (actual time=93704.229..93811.067 rows=439 loops=1) -> Sort (cost=114888.70..114892.08 rows=1355 width=146) (actual time=93704.223..93749.037 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=112179.18..114818.21 rows=1355 width=146) (actual time=33848.546..92399.306rows=26139 loops=1) -> Subquery Scan lgm (cost=112179.18..112179.88 rows=56 width=114) (actual time=33833.584..33853.948rows=439 loops=1) -> Sort (cost=112179.18..112179.32 rows=56 width=116) (actual time=33833.546..33834.852rows=439 loops=1) Sort Key: luid.log_date -> HashAggregate (cost=112176.57..112177.55 rows=56 width=116) (actual time=33826.827..33831.630rows=439 loops=1) Filter: (((count("action") % 2::bigint) = 1) OR (count("action") = 0)) -> Nested Loop Left Join (cost=112022.13..112173.77 rows=56 width=116)(actual time=20817.795..33804.325 rows=649 loops=1) -> Subquery Scan luid (cost=112022.13..112028.17 rows=11 width=94)(actual time=20743.169..20748.324 rows=100 loops=1) -> Unique (cost=112022.13..112028.06 rows=11 width=94) (actualtime=20743.147..20744.932 rows=100 loops=1) -> Sort (cost=112022.13..112024.11 rows=790 width=94)(actual time=20743.144..20743.426 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=20709.280..20742.897 rows=100 loops=1) -> Subquery Scan cuh (cost=109926.12..110297.49rows=100 width=62) (actual time=20708.952..20737.891 rows=100 loops=1) -> Unique (cost=109926.12..110296.49rows=100 width=62) (actual time=20708.920..20737.145 rows=100 loops=1) -> Sort (cost=109926.12..110111.30rows=74075 width=62) (actual time=20708.914..20727.984 rows=13370 loops=1) Sort Key: log.rec_id,uh.date -> Merge Left Join (cost=96406.26..101406.78rows=74075 width=62) (actual time=19252.554..20523.253 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.869..0.948 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.112..0.245 rows=100 loops=1) -> Sort (cost=96400.94..97512.05rows=444446 width=32) (actual time=19251.556..19819.983 rows=442847 loops=1) Sort Key:uh.name -> SubqueryScan uh (cost=0.00..25148.24 rows=444446 width=32) (actual time=0.353..3422.179 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.326..2018.154rows=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.038..0.038 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=80.107..130.251 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=16.099..131.682 rows=59 loops=439) Index Cond: ((group_history.date <= "outer".log_date) AND (group_history.gid = "outer".gm_gid)) Filter: ("action" <> 1) Total runtime: 93866.526 ms (43 rows) Time: 94083.803 ms