Обсуждение: possible wrong query plan on pg 8.3.5,
Hi,
I am running a relativ complex query on pg 8.3.5 and have (possible)
wrong query plan.
My select :
explain analyze select d.ids from a_doc d join a_sklad s on
(d.ids=s.ids_doc) join a_nomen n on (n.ids=s.ids_num) join a_nom_gr
nmgr on (nmgr.ids=n.ids_grupa) join a_gar_prod_r gr on
(gr.ids_a_sklad=s.ids and gr.sernum!='ok') join a_location l on
(l.ids=s.ids_sklad) join a_klienti kl on (kl.ids=d.ids_ko) left
outer join a_slujiteli sl on (sl.ids=d.ids_slu_ka) left outer join
a_slujiteli slu on (slu.ids=d.ids_slu_targ) where d.op=1 AND
d.date_op >= 12320 AND d.date_op <= 12362 and n.num like '191%';
If I run the query without thle last part : and n.num like '191%'
it work ok as speed ~ 30 sec on not very big db.
If I run the full query it take very long time to go ( i never waited
to the end but it take > 60 min.)
The filed n.num is indexed and looks ok for me.
I post explan analyze for query without n.num like '191%' and only
explain for query with n.num like '191%' :
explain analyze select d.ids from a_doc d join a_sklad s on
(d.ids=s.ids_doc) join a_nomen n on (n.ids=s.ids_num) join a_nom_gr
nmgr on (nmgr.ids=n.ids_grupa) join a_gar_prod_r gr on
(gr.ids_a_sklad=s.ids and gr.sernum!='ok') join a_location l on
(l.ids=s.ids_sklad) join a_klienti kl on (kl.ids=d.ids_ko) left
outer join a_slujiteli sl on (sl.ids=d.ids_slu_ka) left outer join
a_slujiteli slu on (slu.ids=d.ids_slu_targ) where d.op=1 AND
d.date_op >= 12320 AND d.date_op <= 12362 ;
-------------
Nested Loop Left Join (cost=345.50..190641.97 rows=1488 width=64)
(actual time=446.905..30681.604 rows=636 loops=1)
-> Nested Loop (cost=345.50..189900.14 rows=1488 width=128)
(actual time=446.870..30676.472 rows=636 loops=1)
-> Nested Loop (cost=345.50..189473.66 rows=1488
width=192) (actual time=427.522..30595.438 rows=636 loops=1)
-> Nested Loop (cost=345.50..189049.52 rows=1488
width=192) (actual time=370.034..29609.647 rows=636 loops=1)
-> Hash Join (cost=345.50..178565.42 rows=7204
width=256) (actual time=363.667..29110.776 rows=9900 loops=1)
Hash Cond: (s.ids_sklad = l.ids)
-> Nested Loop (cost=321.79..178442.65
rows=7204 width=320) (actual time=363.163..29096.591 rows=9900 loops=1)
-> Hash Left Join
(cost=321.79..80186.96 rows=4476 width=128) (actual
time=278.277..13852.952 rows=8191 loops=1)
Hash Cond: (d.ids_slu_ka = sl.ids)
-> Nested Loop
(cost=223.17..80065.83 rows=4476 width=192) (actual
time=164.664..13731.739 rows=8191 loops=1)
-> Bitmap Heap Scan on
a_doc d (cost=223.17..36926.67 rows=6598 width=256) (actual
time=121.306..587.479 rows=8191 loops=1)
Recheck Cond:
((date_op >= 12320) AND (date_op <= 12362))
Filter: (op = 1)
-> Bitmap Index
Scan on i_doc_date_op (cost=0.00..221.52 rows=10490 width=0) (actual
time=107.212..107.212 rows=11265 loops=1)
Index Cond:
((date_op >= 12320) AND (date_op <= 12362))
-> Index Scan using
a_klienti_pkey on a_klienti kl (cost=0.00..6.53 rows=1 width=64)
(actual time=1.598..1.602 rows=1 loops=8191)
Index Cond:
(kl.ids = d.ids_ko)
-> Hash (cost=77.72..77.72
rows=1672 width=64) (actual time=113.591..113.591 rows=1672 loops=1)
-> Seq Scan on
a_slujiteli sl (cost=0.00..77.72 rows=1672 width=64) (actual
time=10.434..112.508 rows=1672 loops=1)
-> Index Scan using i_sklad_ids_doc
on a_sklad s (cost=0.00..21.90 rows=4 width=256) (actual
time=1.582..1.859 rows=1 loops=8191)
Index Cond: (s.ids_doc = d.ids)
-> Hash (cost=19.43..19.43 rows=343
width=64) (actual time=0.460..0.460 rows=343 loops=1)
-> Seq Scan on a_location l
(cost=0.00..19.43 rows=343 width=64) (actual time=0.017..0.248
rows=343 loops=1)
-> Index Scan using i_a_gar_prod_r_ids_a_sklad
on a_gar_prod_r gr (cost=0.00..1.44 rows=1 width=64) (actual
time=0.049..0.049 rows=0 loops=9900)
Index Cond: (gr.ids_a_sklad = s.ids)
Filter: (gr.sernum <> 'ok'::text)
-> Index Scan using a_nomen_pkey on a_nomen n
(cost=0.00..0.27 rows=1 width=128) (actual time=1.548..1.548 rows=1
loops=636)
Index Cond: (n.ids = s.ids_num)
-> Index Scan using a_nom_gr_pkey on a_nom_gr nmgr
(cost=0.00..0.27 rows=1 width=64) (actual time=0.125..0.126 rows=1
loops=636)
Index Cond: (nmgr.ids = n.ids_grupa)
-> Index Scan using a_slujiteli_pkey on a_slujiteli slu
(cost=0.00..0.49 rows=1 width=64) (actual time=0.006..0.006 rows=1
loops=636)
Index Cond: (slu.ids = d.ids_slu_targ)
Total runtime: 30682.134 ms
(33 rows)
explain select d.ids from a_doc d join a_sklad s on
(d.ids=s.ids_doc) join a_nomen n on (n.ids=s.ids_num) join a_nom_gr
nmgr on (nmgr.ids=n.ids_grupa) join a_gar_prod_r gr on
(gr.ids_a_sklad=s.ids and gr.sernum!='ok') join a_location l on
(l.ids=s.ids_sklad) join a_klienti kl on (kl.ids=d.ids_ko) left
outer join a_slujiteli sl on (sl.ids=d.ids_slu_ka) left outer join
a_slujiteli slu on (slu.ids=d.ids_slu_targ) where d.op=1 AND
d.date_op >= 12320 AND d.date_op <= 12362 and n.num like '191%';
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop Left Join (cost=63.61..133467.00 rows=4 width=64)
-> Nested Loop (cost=63.61..133433.87 rows=4 width=128)
-> Nested Loop (cost=63.61..133422.75 rows=4 width=192)
-> Nested Loop Left Join (cost=63.61..133421.63
rows=4 width=256)
-> Nested Loop (cost=63.61..133420.31 rows=4 width=320)
-> Nested Loop (cost=63.61..133381.08
rows=6 width=384)
-> Nested Loop
(cost=63.61..127621.55 rows=2833 width=192)
-> Nested Loop
(cost=63.61..107660.43 rows=13716 width=256)
-> Index Scan using
i_nomen_num on a_nomen n (cost=0.00..56.39 rows=24 width=128)
Index Cond:
(((num)::text >= '191'::text) AND ((num)::text < '192'::text))
Filter:
((num)::text ~~ '191%'::text)
-> Bitmap Heap Scan on
a_sklad s (cost=63.61..4468.84 rows=1173 width=256)
Recheck Cond:
(s.ids_num = n.ids)
-> Bitmap Index
Scan on i_sklad_ids_num (cost=0.00..63.32 rows=1173 width=0)
Index Cond:
(s.ids_num = n.ids)
-> Index Scan using
i_a_gar_prod_r_ids_a_sklad on a_gar_prod_r gr (cost=0.00..1.44 rows=1
width=64)
Index Cond:
(gr.ids_a_sklad = s.ids)
Filter: (gr.sernum <> 'ok'::text)
-> Index Scan using a_doc_pkey on
a_doc d (cost=0.00..2.02 rows=1 width=256)
Index Cond: (d.ids = s.ids_doc)
Filter: ((d.date_op >= 12320)
AND (d.date_op <= 12362) AND (d.op = 1))
-> Index Scan using a_klienti_pkey on
a_klienti kl (cost=0.00..6.53 rows=1 width=64)
Index Cond: (kl.ids = d.ids_ko)
-> Index Scan using a_slujiteli_pkey on
a_slujiteli sl (cost=0.00..0.32 rows=1 width=64)
Index Cond: (sl.ids = d.ids_slu_ka)
-> Index Scan using a_location_pkey on a_location l
(cost=0.00..0.27 rows=1 width=64)
Index Cond: (l.ids = s.ids_sklad)
-> Index Scan using a_nom_gr_pkey on a_nom_gr nmgr
(cost=0.00..2.77 rows=1 width=64)
Index Cond: (nmgr.ids = n.ids_grupa)
-> Index Scan using a_slujiteli_pkey on a_slujiteli slu
(cost=0.00..8.27 rows=1 width=64)
Index Cond: (slu.ids = d.ids_slu_targ)
(31 rows)
I can not find the reason for this problem.
Is it bug or configuration problem ?
I am running the pg on Contos 5.2 8 GB RAM.
Regards, Ivan.
-------------------------------------
ICN.Bg с най-богатата гама от Хостинг услуги на Българския пазар -
Професионален Хостинг за 23 стотинки на ден с ДДС, 18 GB място,
Неограничен трафик и Безплатен домейн
http://www.icn.bg/?referer=MailBg
zz_11@mail.bg writes:
> I am running a relativ complex query on pg 8.3.5 and have (possible)
> wrong query plan.
> ...
> If I run the query without thle last part : and n.num like '191%'
> it work ok as speed ~ 30 sec on not very big db.
> If I run the full query it take very long time to go ( i never waited
> to the end but it take > 60 min.)
I'm betting that it's badly underestimating the number of rows
satisfying the LIKE condition:
> -> Index Scan using
> i_nomen_num on a_nomen n (cost=0.00..56.39 rows=24 width=128)
> Index Cond:
> (((num)::text >= '191'::text) AND ((num)::text < '192'::text))
> Filter:
> ((num)::text ~~ '191%'::text)
Is 24 the right number of rows for that, or anywhere close? If not, try
raising the statistics target for this table.
regards, tom lane
Цитат от Tom Lane <tgl@sss.pgh.pa.us>: > zz_11@mail.bg writes: >> I am running a relativ complex query on pg 8.3.5 and have (possible) >> wrong query plan. >> ... >> If I run the query without thle last part : and n.num like '191%' >> it work ok as speed ~ 30 sec on not very big db. >> If I run the full query it take very long time to go ( i never waited >> to the end but it take > 60 min.) > > I'm betting that it's badly underestimating the number of rows > satisfying the LIKE condition: > >> -> Index Scan using >> i_nomen_num on a_nomen n (cost=0.00..56.39 rows=24 width=128) >> Index Cond: >> (((num)::text >= '191'::text) AND ((num)::text < '192'::text)) >> Filter: >> ((num)::text ~~ '191%'::text) > > Is 24 the right number of rows for that, or anywhere close? If not, try > raising the statistics target for this table. > > regards, tom lane > > -- > Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) > To make changes to your subscription: > http://www.postgresql.org/mailpref/pgsql-performance > > Hi Tom, Yes, 24 is relative ok ( the real number is 20). And the statistic target for the database is 800 at the moment. If needet I can set it to 1000 ( the maximum). Also I waited to the end of this query to gather info for explain analyze. It is it: explain analyze select d.ids from a_doc d join a_sklad s on (d.ids=s.ids_doc) join a_nomen n on (n.ids=s.ids_num) join a_nom_gr nmgr on (nmgr.ids=n.ids_grupa) join a_gar_prod_r gr on (gr.ids_a_sklad=s.ids and gr.sernum!='ok') join a_location l on (l.ids=s.ids_sklad) join a_klienti kl on (kl.ids=d.ids_ko) left outer join a_slujiteli sl on (sl.ids=d.ids_slu_ka) left outer join a_slujiteli slu on (slu.ids=d.ids_slu_targ) where d.op=1 AND d.date_op >= 12320 AND d.date_op <= 12362 and n.num like '191%'; QUERY PLAN -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Nested Loop Left Join (cost=63.64..133732.47 rows=4 width=64) (actual time=616059.833..1314396.823 rows=91 loops=1) -> Nested Loop (cost=63.64..133699.35 rows=4 width=128) (actual time=616033.205..1313991.756 rows=91 loops=1) -> Nested Loop (cost=63.64..133688.22 rows=4 width=192) (actual time=616033.194..1313991.058 rows=91 loops=1) -> Nested Loop Left Join (cost=63.64..133687.10 rows=4 width=256) (actual time=616033.183..1313936.577 rows=91 loops=1) -> Nested Loop (cost=63.64..133685.78 rows=4 width=320) (actual time=616033.177..1313929.258 rows=91 loops=1) -> Nested Loop (cost=63.64..133646.56 rows=6 width=384) (actual time=616007.069..1313008.701 rows=91 loops=1) -> Nested Loop (cost=63.64..127886.54 rows=2833 width=192) (actual time=376.309..559763.450 rows=211357 loops=1) -> Nested Loop (cost=63.64..107934.83 rows=13709 width=256) (actual time=224.058..148475.499 rows=370803 loops=1) -> Index Scan using i_nomen_num on a_nomen n (cost=0.00..56.39 rows=24 width=128) (actual time=15.702..198.049 rows=20 loops=1) Index Cond: (((num)::text >= '191'::text) AND ((num)::text < '192'::text)) Filter: ((num)::text ~~ '191%'::text) -> Bitmap Heap Scan on a_sklad s (cost=63.64..4480.23 rows=1176 width=256) (actual time=93.223..7398.764 rows=18540 loops=20) Recheck Cond: (s.ids_num = n.ids) -> Bitmap Index Scan on i_sklad_ids_num (cost=0.00..63.34 rows=1176 width=0) (actual time=78.430..78.430 rows=18540 loops=20) Index Cond: (s.ids_num = n.ids) -> Index Scan using i_a_gar_prod_r_ids_a_sklad on a_gar_prod_r gr (cost=0.00..1.44 rows=1 width=64) (actual time=1.098..1.108 rows=1 loops=370803) Index Cond: (gr.ids_a_sklad = s.ids) Filter: (gr.sernum <> 'ok'::text) -> Index Scan using a_doc_pkey on a_doc d (cost=0.00..2.02 rows=1 width=256) (actual time=3.563..3.563 rows=0 loops=211357) Index Cond: (d.ids = s.ids_doc) Filter: ((d.date_op >= 12320) AND (d.date_op <= 12362) AND (d.op = 1)) -> Index Scan using a_klienti_pkey on a_klienti kl (cost=0.00..6.53 rows=1 width=64) (actual time=10.109..10.113 rows=1 loops=91) Index Cond: (kl.ids = d.ids_ko) -> Index Scan using a_slujiteli_pkey on a_slujiteli sl (cost=0.00..0.32 rows=1 width=64) (actual time=0.078..0.078 rows=0 loops=91) Index Cond: (sl.ids = d.ids_slu_ka) -> Index Scan using a_location_pkey on a_location l (cost=0.00..0.27 rows=1 width=64) (actual time=0.596..0.597 rows=1 loops=91) Index Cond: (l.ids = s.ids_sklad) -> Index Scan using a_nom_gr_pkey on a_nom_gr nmgr (cost=0.00..2.77 rows=1 width=64) (actual time=0.005..0.006 rows=1 loops=91) Index Cond: (nmgr.ids = n.ids_grupa) -> Index Scan using a_slujiteli_pkey on a_slujiteli slu (cost=0.00..8.27 rows=1 width=64) (actual time=4.448..4.449 rows=1 loops=91) Index Cond: (slu.ids = d.ids_slu_targ) Total runtime: 1314397.153 ms (32 rows) And if I try this query for second time it is working very fast: ----------------------------------------- Nested Loop Left Join (cost=63.64..133732.47 rows=4 width=64) (actual time=9438.195..29429.861 rows=91 loops=1) -> Nested Loop (cost=63.64..133699.35 rows=4 width=128) (actual time=9438.155..29363.045 rows=91 loops=1) -> Nested Loop (cost=63.64..133688.22 rows=4 width=192) (actual time=9438.145..29355.229 rows=91 loops=1) -> Nested Loop Left Join (cost=63.64..133687.10 rows=4 width=256) (actual time=9438.132..29335.008 rows=91 loops=1) -> Nested Loop (cost=63.64..133685.78 rows=4 width=320) (actual time=9438.128..29314.640 rows=91 loops=1) -> Nested Loop (cost=63.64..133646.56 rows=6 width=384) (actual time=9438.087..29312.490 rows=91 loops=1) -> Nested Loop (cost=63.64..127886.54 rows=2833 width=192) (actual time=192.451..21060.439 rows=211357 loops=1) -> Nested Loop (cost=63.64..107934.83 rows=13709 width=256) (actual time=192.367..11591.661 rows=370803 loops=1) -> Index Scan using i_nomen_num on a_nomen n (cost=0.00..56.39 rows=24 width=128) (actual time=0.045..0.434 rows=20 loops=1) Index Cond: (((num)::text >= '191'::text) AND ((num)::text < '192'::text)) Filter: ((num)::text ~~ '191%'::text) -> Bitmap Heap Scan on a_sklad s (cost=63.64..4480.23 rows=1176 width=256) (actual time=14.333..565.417 rows=18540 loops=20) Recheck Cond: (s.ids_num = n.ids) -> Bitmap Index Scan on i_sklad_ids_num (cost=0.00..63.34 rows=1176 width=0) (actual time=9.164..9.164 rows=18540 loops=20) Index Cond: (s.ids_num = n.ids) -> Index Scan using i_a_gar_prod_r_ids_a_sklad on a_gar_prod_r gr (cost=0.00..1.44 rows=1 width=64) (actual time=0.024..0.024 rows=1 loops=370803) Index Cond: (gr.ids_a_sklad = s.ids) Filter: (gr.sernum <> 'ok'::text) -> Index Scan using a_doc_pkey on a_doc d (cost=0.00..2.02 rows=1 width=256) (actual time=0.038..0.038 rows=0 loops=211357) Index Cond: (d.ids = s.ids_doc) Filter: ((d.date_op >= 12320) AND (d.date_op <= 12362) AND (d.op = 1)) -> Index Scan using a_klienti_pkey on a_klienti kl (cost=0.00..6.53 rows=1 width=64) (actual time=0.021..0.022 rows=1 loops=91) Index Cond: (kl.ids = d.ids_ko) -> Index Scan using a_slujiteli_pkey on a_slujiteli sl (cost=0.00..0.32 rows=1 width=64) (actual time=0.222..0.222 rows=0 loops=91) Index Cond: (sl.ids = d.ids_slu_ka) -> Index Scan using a_location_pkey on a_location l (cost=0.00..0.27 rows=1 width=64) (actual time=0.220..0.220 rows=1 loops=91) Index Cond: (l.ids = s.ids_sklad) -> Index Scan using a_nom_gr_pkey on a_nom_gr nmgr (cost=0.00..2.77 rows=1 width=64) (actual time=0.083..0.084 rows=1 loops=91) Index Cond: (nmgr.ids = n.ids_grupa) -> Index Scan using a_slujiteli_pkey on a_slujiteli slu (cost=0.00..8.27 rows=1 width=64) (actual time=0.731..0.732 rows=1 loops=91) Index Cond: (slu.ids = d.ids_slu_targ) Total runtime: 29430.170 ms After this I wait a little time ( ~30 min) and all works bad again. I think it is related to cache or not ? Can I disable using index of n.num field for this query onli ( I know it is wrong direction, but I have no idea how to solve this situaion) ? Regards, Ivan. ------------------------------------- 3.5 Mbps Сателитен достъп до Интернет навсякъде в България www.tooway.bg http://www.tooway.bg/
> Hi Tom, > > Yes, 24 is relative ok ( the real number is 20). > And the statistic target for the database is 800 at the moment. If > needet I can set it to 1000 ( the maximum). > > Also I waited to the end of this query to gather info for explain analyze. > It is it: > > explain analyze select d.ids from a_doc d join a_sklad s on > (d.ids=s.ids_doc) join a_nomen n on (n.ids=s.ids_num) join a_nom_gr > nmgr on (nmgr.ids=n.ids_grupa) join a_gar_prod_r gr on > (gr.ids_a_sklad=s.ids and gr.sernum!='ok') join a_location l on > (l.ids=s.ids_sklad) join a_klienti kl on (kl.ids=d.ids_ko) left > outer join a_slujiteli sl on (sl.ids=d.ids_slu_ka) left outer join > a_slujiteli slu on (slu.ids=d.ids_slu_targ) where d.op=1 AND > d.date_op >= 12320 AND d.date_op <= 12362 and n.num like '191%'; > > QUERY PLAN > -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- > Nested Loop Left Join (cost=63.64..133732.47 rows=4 width=64) > (actual time=616059.833..1314396.823 rows=91 loops=1) > -> Nested Loop (cost=63.64..133699.35 rows=4 width=128) (actual > time=616033.205..1313991.756 rows=91 loops=1) > -> Nested Loop (cost=63.64..133688.22 rows=4 width=192) > (actual time=616033.194..1313991.058 rows=91 loops=1) > -> Nested Loop Left Join (cost=63.64..133687.10 > rows=4 width=256) (actual time=616033.183..1313936.577 rows=91 loops=1) > -> Nested Loop (cost=63.64..133685.78 rows=4 > width=320) (actual time=616033.177..1313929.258 rows=91 loops=1) > -> Nested Loop (cost=63.64..133646.56 > rows=6 width=384) (actual time=616007.069..1313008.701 rows=91 loops=1) > -> Nested Loop > (cost=63.64..127886.54 rows=2833 width=192) (actual > time=376.309..559763.450 rows=211357 loops=1) > -> Nested Loop > (cost=63.64..107934.83 rows=13709 width=256) (actual > time=224.058..148475.499 rows=370803 loops=1) > -> Index Scan using > i_nomen_num on a_nomen n (cost=0.00..56.39 rows=24 width=128) (actual > time=15.702..198.049 rows=20 loops=1) > Index Cond: > (((num)::text >= '191'::text) AND ((num)::text < '192'::text)) > Filter: > ((num)::text ~~ '191%'::text) > -> Bitmap Heap Scan on > a_sklad s (cost=63.64..4480.23 rows=1176 width=256) (actual > time=93.223..7398.764 rows=18540 loops=20) > Recheck Cond: > (s.ids_num = n.ids) > -> Bitmap Index > Scan on i_sklad_ids_num (cost=0.00..63.34 rows=1176 width=0) (actual > time=78.430..78.430 rows=18540 loops=20) > Index Cond: > (s.ids_num = n.ids) > -> Index Scan using > i_a_gar_prod_r_ids_a_sklad on a_gar_prod_r gr (cost=0.00..1.44 rows=1 > width=64) (actual time=1.098..1.108 rows=1 loops=370803) > Index Cond: > (gr.ids_a_sklad = s.ids) > Filter: (gr.sernum <> > 'ok'::text) > -> Index Scan using a_doc_pkey on > a_doc d (cost=0.00..2.02 rows=1 width=256) (actual time=3.563..3.563 > rows=0 loops=211357) > Index Cond: (d.ids = s.ids_doc) > Filter: ((d.date_op >= 12320) > AND (d.date_op <= 12362) AND (d.op = 1)) > -> Index Scan using a_klienti_pkey on > a_klienti kl (cost=0.00..6.53 rows=1 width=64) (actual > time=10.109..10.113 rows=1 loops=91) > Index Cond: (kl.ids = d.ids_ko) > -> Index Scan using a_slujiteli_pkey on > a_slujiteli sl (cost=0.00..0.32 rows=1 width=64) (actual > time=0.078..0.078 rows=0 loops=91) > Index Cond: (sl.ids = d.ids_slu_ka) > -> Index Scan using a_location_pkey on a_location l > (cost=0.00..0.27 rows=1 width=64) (actual time=0.596..0.597 rows=1 > loops=91) > Index Cond: (l.ids = s.ids_sklad) > -> Index Scan using a_nom_gr_pkey on a_nom_gr nmgr > (cost=0.00..2.77 rows=1 width=64) (actual time=0.005..0.006 rows=1 > loops=91) > Index Cond: (nmgr.ids = n.ids_grupa) > -> Index Scan using a_slujiteli_pkey on a_slujiteli slu > (cost=0.00..8.27 rows=1 width=64) (actual time=4.448..4.449 rows=1 > loops=91) > Index Cond: (slu.ids = d.ids_slu_targ) > Total runtime: 1314397.153 ms > (32 rows) > > > And if I try this query for second time it is working very fast: > > > ----------------------------------------- > Nested Loop Left Join (cost=63.64..133732.47 rows=4 width=64) > (actual time=9438.195..29429.861 rows=91 loops=1) > -> Nested Loop (cost=63.64..133699.35 rows=4 width=128) (actual > time=9438.155..29363.045 rows=91 loops=1) > -> Nested Loop (cost=63.64..133688.22 rows=4 width=192) > (actual time=9438.145..29355.229 rows=91 loops=1) > -> Nested Loop Left Join (cost=63.64..133687.10 > rows=4 width=256) (actual time=9438.132..29335.008 rows=91 loops=1) > -> Nested Loop (cost=63.64..133685.78 rows=4 > width=320) (actual time=9438.128..29314.640 rows=91 loops=1) > -> Nested Loop (cost=63.64..133646.56 > rows=6 width=384) (actual time=9438.087..29312.490 rows=91 loops=1) > -> Nested Loop > (cost=63.64..127886.54 rows=2833 width=192) (actual > time=192.451..21060.439 rows=211357 loops=1) > -> Nested Loop > (cost=63.64..107934.83 rows=13709 width=256) (actual > time=192.367..11591.661 rows=370803 loops=1) > -> Index Scan using > i_nomen_num on a_nomen n (cost=0.00..56.39 rows=24 width=128) (actual > time=0.045..0.434 rows=20 loops=1) > Index Cond: > (((num)::text >= '191'::text) AND ((num)::text < '192'::text)) > Filter: > ((num)::text ~~ '191%'::text) > -> Bitmap Heap Scan on > a_sklad s (cost=63.64..4480.23 rows=1176 width=256) (actual > time=14.333..565.417 rows=18540 loops=20) > Recheck Cond: > (s.ids_num = n.ids) > -> Bitmap Index > Scan on i_sklad_ids_num (cost=0.00..63.34 rows=1176 width=0) (actual > time=9.164..9.164 rows=18540 loops=20) > Index Cond: > (s.ids_num = n.ids) > -> Index Scan using > i_a_gar_prod_r_ids_a_sklad on a_gar_prod_r gr (cost=0.00..1.44 rows=1 > width=64) (actual time=0.024..0.024 rows=1 loops=370803) > Index Cond: > (gr.ids_a_sklad = s.ids) > Filter: (gr.sernum <> > 'ok'::text) > -> Index Scan using a_doc_pkey on > a_doc d (cost=0.00..2.02 rows=1 width=256) (actual time=0.038..0.038 > rows=0 loops=211357) > Index Cond: (d.ids = s.ids_doc) > Filter: ((d.date_op >= 12320) > AND (d.date_op <= 12362) AND (d.op = 1)) > -> Index Scan using a_klienti_pkey on > a_klienti kl (cost=0.00..6.53 rows=1 width=64) (actual > time=0.021..0.022 rows=1 loops=91) > Index Cond: (kl.ids = d.ids_ko) > -> Index Scan using a_slujiteli_pkey on > a_slujiteli sl (cost=0.00..0.32 rows=1 width=64) (actual > time=0.222..0.222 rows=0 loops=91) > Index Cond: (sl.ids = d.ids_slu_ka) > -> Index Scan using a_location_pkey on a_location l > (cost=0.00..0.27 rows=1 width=64) (actual time=0.220..0.220 rows=1 > loops=91) > Index Cond: (l.ids = s.ids_sklad) > -> Index Scan using a_nom_gr_pkey on a_nom_gr nmgr > (cost=0.00..2.77 rows=1 width=64) (actual time=0.083..0.084 rows=1 > loops=91) > Index Cond: (nmgr.ids = n.ids_grupa) > -> Index Scan using a_slujiteli_pkey on a_slujiteli slu > (cost=0.00..8.27 rows=1 width=64) (actual time=0.731..0.732 rows=1 > loops=91) > Index Cond: (slu.ids = d.ids_slu_targ) > Total runtime: 29430.170 ms > > > > After this I wait a little time ( ~30 min) and all works bad again. > I think it is related to cache or not ? > > Can I disable using index of n.num field for this query onli ( I know > it is wrong direction, but I have no idea how to solve this situaion) ? > > Regards, > Ivan. I have entered the two execution plans to explain.depesz.com - the results are here: slow (first execution): http://explain.depesz.com/s/tvd fast (second execution): http://explain.depesz.com/s/3C It seems there's something very wrong - the plans are "equal" but in the first case the results (actual time) are multiplied by 100. Eithere there is some sort of cache (so the second execution is much faster), or the system was busy during the first execution, or there is something wrong with the hardware. regards Tom (not Lane)
Hi , >> Hi Tom, >> >> Yes, 24 is relative ok ( the real number is 20). >> And the statistic target for the database is 800 at the moment. If >> needet I can set it to 1000 ( the maximum). >> >> Also I waited to the end of this query to gather info for explain analyze. >> It is it: >> >> explain analyze select d.ids from a_doc d join a_sklad s on >> (d.ids=s.ids_doc) join a_nomen n on (n.ids=s.ids_num) join a_nom_gr >> nmgr on (nmgr.ids=n.ids_grupa) join a_gar_prod_r gr on >> (gr.ids_a_sklad=s.ids and gr.sernum!='ok') join a_location l on >> (l.ids=s.ids_sklad) join a_klienti kl on (kl.ids=d.ids_ko) left >> outer join a_slujiteli sl on (sl.ids=d.ids_slu_ka) left outer join >> a_slujiteli slu on (slu.ids=d.ids_slu_targ) where d.op=1 AND >> d.date_op >= 12320 AND d.date_op <= 12362 and n.num like '191%'; >> >> QUERY PLAN >> -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- >> Nested Loop Left Join (cost=63.64..133732.47 rows=4 width=64) >> (actual time=616059.833..1314396.823 rows=91 loops=1) >> -> Nested Loop (cost=63.64..133699.35 rows=4 width=128) (actual >> time=616033.205..1313991.756 rows=91 loops=1) >> -> Nested Loop (cost=63.64..133688.22 rows=4 width=192) >> (actual time=616033.194..1313991.058 rows=91 loops=1) >> -> Nested Loop Left Join (cost=63.64..133687.10 >> rows=4 width=256) (actual time=616033.183..1313936.577 rows=91 loops=1) >> -> Nested Loop (cost=63.64..133685.78 rows=4 >> width=320) (actual time=616033.177..1313929.258 rows=91 loops=1) >> -> Nested Loop (cost=63.64..133646.56 >> rows=6 width=384) (actual time=616007.069..1313008.701 rows=91 loops=1) >> -> Nested Loop >> (cost=63.64..127886.54 rows=2833 width=192) (actual >> time=376.309..559763.450 rows=211357 loops=1) >> -> Nested Loop >> (cost=63.64..107934.83 rows=13709 width=256) (actual >> time=224.058..148475.499 rows=370803 loops=1) >> -> Index Scan using >> i_nomen_num on a_nomen n (cost=0.00..56.39 rows=24 width=128) (actual >> time=15.702..198.049 rows=20 loops=1) >> Index Cond: >> (((num)::text >= '191'::text) AND ((num)::text < '192'::text)) >> Filter: >> ((num)::text ~~ '191%'::text) >> -> Bitmap Heap Scan on >> a_sklad s (cost=63.64..4480.23 rows=1176 width=256) (actual >> time=93.223..7398.764 rows=18540 loops=20) >> Recheck Cond: >> (s.ids_num = n.ids) >> -> Bitmap Index >> Scan on i_sklad_ids_num (cost=0.00..63.34 rows=1176 width=0) (actual >> time=78.430..78.430 rows=18540 loops=20) >> Index Cond: >> (s.ids_num = n.ids) >> -> Index Scan using >> i_a_gar_prod_r_ids_a_sklad on a_gar_prod_r gr (cost=0.00..1.44 rows=1 >> width=64) (actual time=1.098..1.108 rows=1 loops=370803) >> Index Cond: >> (gr.ids_a_sklad = s.ids) >> Filter: (gr.sernum <> >> 'ok'::text) >> -> Index Scan using a_doc_pkey on >> a_doc d (cost=0.00..2.02 rows=1 width=256) (actual time=3.563...3.563 >> rows=0 loops=211357) >> Index Cond: (d.ids = s.ids_doc) >> Filter: ((d.date_op >= 12320) >> AND (d.date_op <= 12362) AND (d.op = 1)) >> -> Index Scan using a_klienti_pkey on >> a_klienti kl (cost=0.00..6.53 rows=1 width=64) (actual >> time=10.109..10.113 rows=1 loops=91) >> Index Cond: (kl.ids = d.ids_ko) >> -> Index Scan using a_slujiteli_pkey on >> a_slujiteli sl (cost=0.00..0.32 rows=1 width=64) (actual >> time=0.078..0.078 rows=0 loops=91) >> Index Cond: (sl.ids = d.ids_slu_ka) >> -> Index Scan using a_location_pkey on a_location l >> (cost=0.00..0.27 rows=1 width=64) (actual time=0.596..0.597 rows=1 >> loops=91) >> Index Cond: (l.ids = s.ids_sklad) >> -> Index Scan using a_nom_gr_pkey on a_nom_gr nmgr >> (cost=0.00..2.77 rows=1 width=64) (actual time=0.005..0.006 rows=1 >> loops=91) >> Index Cond: (nmgr.ids = n.ids_grupa) >> -> Index Scan using a_slujiteli_pkey on a_slujiteli slu >> (cost=0.00..8.27 rows=1 width=64) (actual time=4.448..4.449 rows=1 >> loops=91) >> Index Cond: (slu.ids = d.ids_slu_targ) >> Total runtime: 1314397.153 ms >> (32 rows) >> >> >> And if I try this query for second time it is working very fast: >> >> >> ----------------------------------------- >> Nested Loop Left Join (cost=63.64..133732.47 rows=4 width=64) >> (actual time=9438.195..29429.861 rows=91 loops=1) >> -> Nested Loop (cost=63.64..133699.35 rows=4 width=128) (actual >> time=9438.155..29363.045 rows=91 loops=1) >> -> Nested Loop (cost=63.64..133688.22 rows=4 width=192) >> (actual time=9438.145..29355.229 rows=91 loops=1) >> -> Nested Loop Left Join (cost=63.64..133687.10 >> rows=4 width=256) (actual time=9438.132..29335.008 rows=91 loops=1) >> -> Nested Loop (cost=63.64..133685.78 rows=4 >> width=320) (actual time=9438.128..29314.640 rows=91 loops=1) >> -> Nested Loop (cost=63.64..133646.56 >> rows=6 width=384) (actual time=9438.087..29312.490 rows=91 loops=1) >> -> Nested Loop >> (cost=63.64..127886.54 rows=2833 width=192) (actual >> time=192.451..21060.439 rows=211357 loops=1) >> -> Nested Loop >> (cost=63.64..107934.83 rows=13709 width=256) (actual >> time=192.367..11591.661 rows=370803 loops=1) >> -> Index Scan using >> i_nomen_num on a_nomen n (cost=0.00..56.39 rows=24 width=128) (actual >> time=0.045..0.434 rows=20 loops=1) >> Index Cond: >> (((num)::text >= '191'::text) AND ((num)::text < '192'::text)) >> Filter: >> ((num)::text ~~ '191%'::text) >> -> Bitmap Heap Scan on >> a_sklad s (cost=63.64..4480.23 rows=1176 width=256) (actual >> time=14.333..565.417 rows=18540 loops=20) >> Recheck Cond: >> (s.ids_num = n.ids) >> -> Bitmap Index >> Scan on i_sklad_ids_num (cost=0.00..63.34 rows=1176 width=0) (actual >> time=9.164..9.164 rows=18540 loops=20) >> Index Cond: >> (s.ids_num = n.ids) >> -> Index Scan using >> i_a_gar_prod_r_ids_a_sklad on a_gar_prod_r gr (cost=0.00..1.44 rows=1 >> width=64) (actual time=0.024..0.024 rows=1 loops=370803) >> Index Cond: >> (gr.ids_a_sklad = s.ids) >> Filter: (gr.sernum <> >> 'ok'::text) >> -> Index Scan using a_doc_pkey on >> a_doc d (cost=0.00..2.02 rows=1 width=256) (actual time=0.038...0.038 >> rows=0 loops=211357) >> Index Cond: (d.ids = s.ids_doc) >> Filter: ((d.date_op >= 12320) >> AND (d.date_op <= 12362) AND (d.op = 1)) >> -> Index Scan using a_klienti_pkey on >> a_klienti kl (cost=0.00..6.53 rows=1 width=64) (actual >> time=0.021..0.022 rows=1 loops=91) >> Index Cond: (kl.ids = d.ids_ko) >> -> Index Scan using a_slujiteli_pkey on >> a_slujiteli sl (cost=0.00..0.32 rows=1 width=64) (actual >> time=0.222..0.222 rows=0 loops=91) >> Index Cond: (sl.ids = d.ids_slu_ka) >> -> Index Scan using a_location_pkey on a_location l >> (cost=0.00..0.27 rows=1 width=64) (actual time=0.220..0.220 rows=1 >> loops=91) >> Index Cond: (l.ids = s.ids_sklad) >> -> Index Scan using a_nom_gr_pkey on a_nom_gr nmgr >> (cost=0.00..2.77 rows=1 width=64) (actual time=0.083..0.084 rows=1 >> loops=91) >> Index Cond: (nmgr.ids = n.ids_grupa) >> -> Index Scan using a_slujiteli_pkey on a_slujiteli slu >> (cost=0.00..8.27 rows=1 width=64) (actual time=0.731..0.732 rows=1 >> loops=91) >> Index Cond: (slu.ids = d.ids_slu_targ) >> Total runtime: 29430.170 ms >> >> >> >> After this I wait a little time ( ~30 min) and all works bad again. >> I think it is related to cache or not ? >> >> Can I disable using index of n.num field for this query onli ( I know >> it is wrong direction, but I have no idea how to solve this situaion) ? >> >> Regards, >> Ivan. > > I have entered the two execution plans to explain.depesz.com - the results > are here: > > slow (first execution): http://explain.depesz.com/s/tvd > fast (second execution): http://explain.depesz.com/s/3C > > It seems there's something very wrong - the plans are "equal" but in the > first case the results (actual time) are multiplied by 100. Eithere there > is some sort of cache (so the second execution is much faster), or the > system was busy during the first execution, or there is something wrong > with the hardware. > Yes, I think it is the cache. I am running the first and the second query on my test server and no one is working on it at this time. My general problem is tath the query without and n.num like '191%' is much faster. I detect the same also with many other field on the n-table. I think planer expect to find all the records in cache but it is not there. Can I tune some parameters in postgres.conf (effective_cache_size for example) ? > regards > Tom (not Lane) > > > regards, Ivan. ------------------------------------- Powered by Mail.BG - http://mail.bg
2009/9/14 <tv@fuzzy.cz>: > It seems there's something very wrong - the plans are "equal" but in the > first case the results (actual time) are multiplied by 100. Eithere there > is some sort of cache (so the second execution is much faster), or the > system was busy during the first execution, or there is something wrong > with the hardware. I think you should run this query more than twice. If it's slow the first time and fast every time for many executions after that, then it's probably just the data getting loaded into the OS cache (or shared buffers). If it's bouncing back and forth between fast and slow, you might want to check whether your machine is swapping. It might also be helpful to post all the uncommented settings from your postgresql.conf file. ...Robert
Цитат от Robert Haas <robertmhaas@gmail.com>: > 2009/9/14 <tv@fuzzy.cz>: >> It seems there's something very wrong - the plans are "equal" but in the >> first case the results (actual time) are multiplied by 100. Eithere there >> is some sort of cache (so the second execution is much faster), or the >> system was busy during the first execution, or there is something wrong >> with the hardware. > > I think you should run this query more than twice. If it's slow the > first time and fast every time for many executions after that, then > it's probably just the data getting loaded into the OS cache (or > shared buffers). If it's bouncing back and forth between fast and > slow, you might want to check whether your machine is swapping. I did it many times. Alter the first atempt it works fast, but after a couple of minutes ( I think after changing the data in cache) the query is working also very slow. I do not see any swap on OS. > > It might also be helpful to post all the uncommented settings from > your postgresql.conf file. postgresql.conf : max_connections = 2000 shared_buffers = 1800MB temp_buffers = 80MB work_mem = 120MB maintenance_work_mem = 100MB max_fsm_pages = 404800 max_fsm_relations = 5000 max_files_per_process = 2000 wal_buffers = 64MB checkpoint_segments = 30 effective_cache_size = 5000MB default_statistics_target = 800 All the rest are default parameters. Ivan. > > ...Robert > > -- > Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) > To make changes to your subscription: > http://www.postgresql.org/mailpref/pgsql-performance > > ------------------------------------- Powered by Mail.BG - http://mail.bg
2009/9/14 <zz_11@mail.bg>: > Цитат от Robert Haas <robertmhaas@gmail.com>: > >> 2009/9/14 <tv@fuzzy.cz>: >>> >>> It seems there's something very wrong - the plans are "equal" but in the >>> first case the results (actual time) are multiplied by 100. Eithere there >>> is some sort of cache (so the second execution is much faster), or the >>> system was busy during the first execution, or there is something wrong >>> with the hardware. >> >> I think you should run this query more than twice. If it's slow the >> first time and fast every time for many executions after that, then >> it's probably just the data getting loaded into the OS cache (or >> shared buffers). If it's bouncing back and forth between fast and >> slow, you might want to check whether your machine is swapping. > > I did it many times. Alter the first atempt it works fast, but after a > couple of minutes ( I think after changing the data in cache) the query is > working also very slow. > > I do not see any swap on OS. > >> >> It might also be helpful to post all the uncommented settings from >> your postgresql.conf file. > > postgresql.conf : > > max_connections = 2000 > shared_buffers = 1800MB > temp_buffers = 80MB > work_mem = 120MB > > maintenance_work_mem = 100MB > max_fsm_pages = 404800 > max_fsm_relations = 5000 > > max_files_per_process = 2000 > wal_buffers = 64MB > checkpoint_segments = 30 > effective_cache_size = 5000MB > default_statistics_target = 800 I think you're exhausting the physical memory on your machine. How much RAM do you have? How many active connections at one time? 120MB is a HUGE value for work_mem. I would try reducing that to, say, 4 MB, and see what happens. Your setting for temp_buffers also seems way too high. I would put that one back to the default, at least for starters. And for that matter, why have you increased the value for wal_buffers to over 1000 times the default value? The reason you may not be seeing evidence of swapping is that it may be happening quite briefly during query execution. But I have to think it's happening, because otherwise the performance drop-off is hard to account for. ...Robert
2009/9/14 <zz_11@mail.bg>: > Also I waited to the end of this query to gather info for explain analyze. > It is it: > > explain analyze select d.ids from a_doc d join a_sklad s on > (d.ids=s.ids_doc) join a_nomen n on (n.ids=s.ids_num) join a_nom_gr nmgr > on (nmgr.ids=n.ids_grupa) join a_gar_prod_r gr on (gr.ids_a_sklad=s.ids and > gr.sernum!='ok') join a_location l on (l.ids=s.ids_sklad) join a_klienti > kl on (kl.ids=d.ids_ko) left outer join a_slujiteli sl on > (sl.ids=d.ids_slu_ka) left outer join a_slujiteli slu on > (slu.ids=d.ids_slu_targ) where d.op=1 AND d.date_op >= 12320 AND d.date_op > <= 12362 and n.num like '191%'; > > QUERY PLAN > -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- > Nested Loop Left Join (cost=63.64..133732.47 rows=4 width=64) (actual > time=616059.833..1314396.823 rows=91 loops=1) > -> Nested Loop (cost=63.64..133699.35 rows=4 width=128) (actual > time=616033.205..1313991.756 rows=91 loops=1) > -> Nested Loop (cost=63.64..133688.22 rows=4 width=192) (actual > time=616033.194..1313991.058 rows=91 loops=1) > -> Nested Loop Left Join (cost=63.64..133687.10 rows=4 > width=256) (actual time=616033.183..1313936.577 rows=91 loops=1) > -> Nested Loop (cost=63.64..133685.78 rows=4 > width=320) (actual time=616033.177..1313929.258 rows=91 loops=1) > -> Nested Loop (cost=63.64..133646.56 rows=6 > width=384) (actual time=616007.069..1313008.701 rows=91 loops=1) > -> Nested Loop (cost=63.64..127886.54 > rows=2833 width=192) (actual time=376.309..559763.450 rows=211357 loops=1) > -> Nested Loop > (cost=63.64..107934.83 rows=13709 width=256) (actual > time=224.058..148475.499 rows=370803 loops=1) > -> Index Scan using i_nomen_num This nested loop looks like the big problem, although it could also be that it's running an index scan earlier that should be a seq scan given the amount the estimate is off on rows. For grins, try running your query after issuing this command: set enable_nestloop=off; and see what the run time looks like.
Цитат от Scott Marlowe <scott.marlowe@gmail.com>:
> 2009/9/14 <zz_11@mail.bg>:
>> Also I waited to the end of this query to gather info for explain analyze..
>> It is it:
>>
>> explain analyze select d.ids from a_doc d join a_sklad s on
>> (d.ids=s.ids_doc) join a_nomen n on (n.ids=s.ids_num) join a_nom_gr nmgr
>> on (nmgr.ids=n.ids_grupa) join a_gar_prod_r gr on (gr.ids_a_sklad=s.ids and
>> gr.sernum!='ok') join a_location l on (l.ids=s.ids_sklad) join a_klienti
>> kl on (kl.ids=d.ids_ko) left outer join a_slujiteli sl on
>> (sl.ids=d.ids_slu_ka) left outer join a_slujiteli slu on
>> (slu.ids=d.ids_slu_targ) where d.op=1 AND d.date_op >= 12320 AND d.date_op
>> <= 12362 and n.num like '191%';
>>
>> QUERY PLAN
>>
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>> Nested Loop Left Join (cost=63.64..133732.47 rows=4 width=64) (actual
>> time=616059.833..1314396.823 rows=91 loops=1)
>> -> Nested Loop (cost=63.64..133699.35 rows=4 width=128) (actual
>> time=616033.205..1313991.756 rows=91 loops=1)
>> -> Nested Loop (cost=63.64..133688.22 rows=4 width=192) (actual
>> time=616033.194..1313991.058 rows=91 loops=1)
>> -> Nested Loop Left Join (cost=63.64...133687.10 rows=4
>> width=256) (actual time=616033.183..1313936.577 rows=91 loops=1)
>> -> Nested Loop (cost=63.64..133685.78 rows=4
>> width=320) (actual time=616033.177..1313929.258 rows=91 loops=1)
>> -> Nested Loop (cost=63.64..133646.56 rows=6
>> width=384) (actual time=616007.069..1313008.701 rows=91 loops=1)
>> -> Nested Loop (cost=63.64..127886.54
>> rows=2833 width=192) (actual time=376.309..559763.450 rows=211357 loops=1)
>> -> Nested Loop
>> (cost=63.64..107934.83 rows=13709 width=256) (actual
>> time=224.058..148475.499 rows=370803 loops=1)
>> -> Index Scan using i_nomen_num
>
> This nested loop looks like the big problem, although it could also be
> that it's running an index scan earlier that should be a seq scan
> given the amount the estimate is off on rows.
>
> For grins, try running your query after issuing this command:
>
> set enable_nestloop=off;
>
> and see what the run time looks like.
>
>
Hi Scott,
alter set enable_nestloop=off, it is new new plan ( and the speed is
relative good):
Hash Left Join (cost=647541.56..804574.64 rows=4 width=64) (actual
time=40535.547..40554.502 rows=91 loops=1)
Hash Cond: (d.ids_slu_targ = slu.ids)
-> Hash Join (cost=647442.94..804475.96 rows=4 width=128)
(actual time=40533.886..40552.729 rows=91 loops=1)
Hash Cond: (n.ids_grupa = nmgr.ids)
-> Hash Join (cost=647425.37..804458.34 rows=4 width=192)
(actual time=40533.354..40552.112 rows=91 loops=1)
Hash Cond: (s.ids_sklad = l.ids)
-> Hash Left Join (cost=647401.65..804434.56 rows=4
width=256) (actual time=40532.880..40551.540 rows=91 loops=1)
Hash Cond: (d.ids_slu_ka = sl.ids)
-> Hash Join (cost=647303.03..804335.91 rows=4
width=320) (actual time=40530.704..40549.279 rows=91 loops=1)
Hash Cond: (d.ids_ko = kl.ids)
-> Hash Join (cost=592217.17..749249.95
rows=6 width=384) (actual time=37874.787..37893.110 rows=91 loops=1)
Hash Cond: (gr.ids_a_sklad = s.ids)
-> Seq Scan on a_gar_prod_r gr
(cost=0.00..152866.95 rows=1110870 width=64) (actual
time=8.596..5839.771 rows=1112081 loops=1)
Filter: (sernum <> 'ok'::text)
-> Hash (cost=592216.84..592216.84
rows=27 width=448) (actual time=31275.699..31275.699 rows=193 loops=1)
-> Hash Join
(cost=37061.98..592216.84 rows=27 width=448) (actual
time=6046.588..31275.047 rows=193 loops=1)
Hash Cond: (s.ids_doc = d.ids)
-> Hash Join
(cost=52.77..555070.26 rows=13709 width=256) (actual
time=19.962..30406.478 rows=370803 loops=1)
Hash Cond:
(s.ids_num = n.ids)
-> Seq Scan on
a_sklad s (cost=0.00..534721.93 rows=5375593 width=256) (actual
time=5.867..27962.054 rows=5375690 loops=1)
-> Hash
(cost=52.47..52.47 rows=24 width=128) (actual time=0.299..0.299
rows=20 loops=1)
-> Bitmap
Heap Scan on a_nomen n (cost=4.39..52.47 rows=24 width=128) (actual
time=0.061..0.276 rows=20 loops=1)
Filter: ((num)::text ~~ '191%'::text)
->
Bitmap Index Scan on i_nomen_num (cost=0.00..4.38 rows=13 width=0)
(actual time=0.043..0.043 rows=20 loops=1)
Index Cond: (((num)::text >= '191'::text) AND ((num)::text <
'192'::text))
-> Hash
(cost=36926.74..36926.74 rows=6598 width=256) (actual
time=485.920..485.920 rows=8191 loops=1)
-> Bitmap Heap
Scan on a_doc d (cost=223.17..36926.74 rows=6598 width=256) (actual
time=55.896..477.811 rows=8191 loops=1)
Recheck
Cond: ((date_op >= 12320) AND (date_op <= 12362))
Filter: (op = 1)
-> Bitmap
Index Scan on i_doc_date_op (cost=0.00..221.52 rows=10490 width=0)
(actual time=46.639..46.639 rows=11265 loops=1)
Index
Cond: ((date_op >= 12320) AND (date_op <= 12362))
-> Hash (cost=49563.16..49563.16
rows=441816 width=64) (actual time=2655.370..2655.370 rows=441806
loops=1)
-> Seq Scan on a_klienti kl
(cost=0.00..49563.16 rows=441816 width=64) (actual
time=10.237..2334.909 rows=441806 loops=1)
-> Hash (cost=77.72..77.72 rows=1672 width=64)
(actual time=2.138..2.138 rows=1672 loops=1)
-> Seq Scan on a_slujiteli sl
(cost=0.00..77.72 rows=1672 width=64) (actual time=0.019..1.005
rows=1672 loops=1)
-> Hash (cost=19.43..19.43 rows=343 width=64)
(actual time=0.464..0.464 rows=343 loops=1)
-> Seq Scan on a_location l (cost=0.00..19.43
rows=343 width=64) (actual time=0.012..0.263 rows=343 loops=1)
-> Hash (cost=12.81..12.81 rows=381 width=64) (actual
time=0.493..0.493 rows=381 loops=1)
-> Seq Scan on a_nom_gr nmgr (cost=0.00..12.81
rows=381 width=64) (actual time=0.024..0.276 rows=381 loops=1)
-> Hash (cost=77.72..77.72 rows=1672 width=64) (actual
time=1.633..1.633 rows=1672 loops=1)
-> Seq Scan on a_slujiteli slu (cost=0.00..77.72 rows=1672
width=64) (actual time=0.004..0.674 rows=1672 loops=1)
Total runtime: 40565.832 ms
regards,
Ivan.
-------------------------------------
Powered by Mail.BG - http://mail.bg
Цитат от Robert Haas <robertmhaas@gmail.com>: > 2009/9/14 <zz_11@mail.bg>: >> Цитат от Robert Haas <robertmhaas@gmail.com>: >> >>> 2009/9/14 <tv@fuzzy.cz>: >>>> >>>> It seems there's something very wrong - the plans are "equal" but in the >>>> first case the results (actual time) are multiplied by 100. Eithere there >>>> is some sort of cache (so the second execution is much faster), or the >>>> system was busy during the first execution, or there is something wrong >>>> with the hardware. >>> >>> I think you should run this query more than twice. If it's slow the >>> first time and fast every time for many executions after that, then >>> it's probably just the data getting loaded into the OS cache (or >>> shared buffers). If it's bouncing back and forth between fast and >>> slow, you might want to check whether your machine is swapping. >> >> I did it many times. Alter the first atempt it works fast, but after a >> couple of minutes ( I think after changing the data in cache) the query is >> working also very slow. >> >> I do not see any swap on OS. >> >>> >>> It might also be helpful to post all the uncommented settings from >>> your postgresql.conf file. >> >> postgresql.conf : >> >> max_connections = 2000 >> shared_buffers = 1800MB >> temp_buffers = 80MB >> work_mem = 120MB >> >> maintenance_work_mem = 100MB >> max_fsm_pages = 404800 >> max_fsm_relations = 5000 >> >> max_files_per_process = 2000 >> wal_buffers = 64MB >> checkpoint_segments = 30 >> effective_cache_size = 5000MB >> default_statistics_target = 800 > > I think you're exhausting the physical memory on your machine. How > much RAM do you have? How many active connections at one time? 120MB > is a HUGE value for work_mem. I would try reducing that to, say, 4 > MB, and see what happens. Your setting for temp_buffers also seems > way too high. I would put that one back to the default, at least for > starters. And for that matter, why have you increased the value for > wal_buffers to over 1000 times the default value? > We have 8 GB RAM, running Centos 64-bit and ~10 to 15 active connections ( using connection pool). 120 MB for work mem is good. If I drop this value I will receive very bad performance for the hole system. I will try to reduce wal_buffers ( is this value connected to ram usage ? ). > The reason you may not be seeing evidence of swapping is that it may > be happening quite briefly during query execution. But I have to > think it's happening, because otherwise the performance drop-off is > hard to account for. > On linux if I have swap the os never restores the ram used for swap. And I do not see any swap on OS. I send the vmstat for the server: 0 0 1388 44852 25160 6225316 0 0 304 0 1018 201 0 0 100 0 0 procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------ r b swpd free buff cache si so bi bo in cs us sy id wa st 0 0 1388 47612 25148 6222364 0 0 332 4 1015 194 0 0 100 0 0 0 0 1388 47072 25156 6222900 0 0 268 8 1015 190 0 0 100 0 0 0 0 1388 46532 25160 6223656 0 0 270 0 1014 194 0 0 100 0 0 > ...Robert > > -- > Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) > To make changes to your subscription: > http://www.postgresql.org/mailpref/pgsql-performance > > ------------------------------------- Powered by Mail.BG - http://mail.bg
May be you have very bad disk access times (e.g. slow random access)? In this case everything should be OK while data in cache and awful, when not.
Could you check disk IO speed && IO wait while doing slow & fast query.
BTW: In this case, increasing shared buffers may help. At least this will prevent other applications & AFAIK sequence scans to move your index data from cache.
Best regards, Vitalii Tymchyshyn
Could you check disk IO speed && IO wait while doing slow & fast query.
BTW: In this case, increasing shared buffers may help. At least this will prevent other applications & AFAIK sequence scans to move your index data from cache.
Best regards, Vitalii Tymchyshyn
Цитат от Віталій Тимчишин <tivv00@gmail.com>: > May be you have very bad disk access times (e.g. slow random access)? In > this case everything should be OK while data in cache and awful, when not. > Could you check disk IO speed && IO wait while doing slow & fast query. > No, I think all is ok with disks. On my test server I have 8 SATA in RAID 10 and on my production server I have 16 SATA in RAID10 dedicated for pg data and also 8 SATA in RAID 10 for OS and pg_x_log and I do not have any IO wait. It is true, disks are much slower compared to RAM. > BTW: In this case, increasing shared buffers may help. At least this will > prevent other applications & AFAIK sequence scans to move your index data > from cache. I will try to increase this value. I think recomendation in docs was 1/4 from RAM, and on production server I have it setup to 1/4 from RAM ( 32 GB). Will os not cache the data from shared buffers for second time ? The next step will be to move to pg 8.4, but I i twill tak etime for testing. > > Best regards, Vitalii Tymchyshyn > regards, ivan. ------------------------------------- http://www.tooway.bg/