Thread: possible wrong query plan on pg 8.3.5,

possible wrong query plan on pg 8.3.5,

From
zz_11@mail.bg
Date:
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


Re: possible wrong query plan on pg 8.3.5,

From
Tom Lane
Date:
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

Re: possible wrong query plan on pg 8.3.5,

From
zz_11@mail.bg
Date:
Цитат от 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/


Re: possible wrong query plan on pg 8.3.5,

From
tv@fuzzy.cz
Date:
> 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)


Re: possible wrong query plan on pg 8.3.5,

From
zz_11@mail.bg
Date:
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


Re: possible wrong query plan on pg 8.3.5,

From
Robert Haas
Date:
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

Re: possible wrong query plan on pg 8.3.5,

From
zz_11@mail.bg
Date:
Цитат от 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


Re: possible wrong query plan on pg 8.3.5,

From
Robert Haas
Date:
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

Re: possible wrong query plan on pg 8.3.5,

From
Scott Marlowe
Date:
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.

Re: possible wrong query plan on pg 8.3.5,

From
zz_11@mail.bg
Date:
Цитат от 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


Re: possible wrong query plan on pg 8.3.5,

From
zz_11@mail.bg
Date:
Цитат от 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


Re: possible wrong query plan on pg 8.3.5,

From
Віталій Тимчишин
Date:
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

Re: possible wrong query plan on pg 8.3.5,

From
zz_11@mail.bg
Date:
Цитат от Віталій Тимчишин <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/