Re: possible wrong query plan on pg 8.3.5,

> 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)