Re: Leer plan de ejecución

On 22/03/2019 6:33 AM, Stephen Amell wrote:
> Hola,
>
> Conoces explain.depesz.com?
>
Estes es un buen lugar para visualizar los explain plan
> https://explain.depesz.com/s/Tr3k
>
> Ahi lo vas a poder ver un poco mas comodo, en la parte de stats, vas a
> ver en que se te va el plan... en este caso hay un "CTE Scan" y al
> usar fact_acct se va de viaje leyendo.
>
En lo persona me fijo que los where tengan indices y me fijo en los seq
scans.

A todo esto, esto tiene pinta de Adempiere ( puedo estar equivocado ).

Seq Scan
<http://www.depesz.com/2013/04/27/explaining-the-unexplainable-part-2/#seq-scan>
on fact_acct (cost=0.00..2,225.25 rows=2,317 width=11) (actual
time=17.046..23.482 rows=2,136 loops=211)

* Filter: (c_period_id = $9)
* Rows Removed by Filter: 46524

Revisa que tengas indices aquí.

Sobre el CTE Scan no es mucho lo que puedes hacer, estas haciendo OR, y
usando <> le estas diciendo a la maquina hace un full scan..  puedes
crear un indice compuesto para ayudar la busqueda.

create index on fact_acct (c_period_id) ;
create index on CTE_SCAN (inicio,debe,haber,fin) ;

Y ve como te va, corre el plan de execution de nuevo y sigues
optimizando, haciendo esto hace poco baje un reporte de 1 hora a 2 min.
( 10 segundos en la base de datos y casi dos minutos moviendo datos
entre la aplicación y la base de datos ).
OJO: Lo mejor que puedes hacer es ponerte a leer planes y a crear
indices en reportes, pero ten en cuenta que para updates, delete los
indices se deben actualizar ( es rapido pero siempre y cuando tu Storage
no tenga problemas de rendimiento ), un sinple IO de disco que falte
puede ser mucho cuando no se tiene...  ( no creo que sea tu caso ).

>
> On 2019-03-21 12:36, Hamilton Marenco wrote:
>> "CTE Scan on data (cost=751548.65..751551.65 rows=100 width=1036)
>> (actual time=208954.192..208956.133 rows=866 loops=1)"
>> "  Filter: ((inicio <> '0'::numeric) OR (debe <> '0'::numeric) OR
>> (haber <> '0'::numeric) OR (fin <> '0'::numeric))"
>> "  Rows Removed by Filter: 1617"
>> "  CTE parameters"
>> "    -> Seq Scan on c_period  (cost=0.00..6.40 rows=1 width=14)
>> (actual time=0.103..0.120 rows=1 loops=1)"
>> " Filter: (c_period_id = '1000394'::numeric)"
>> " Rows Removed by Filter: 191"
>> "  CTE data"
>> "    -> Sort  (cost=751542.00..751542.25 rows=100 width=350) (actual
>> time=208954.182..208954.561 rows=2483 loops=1)"
>> " Sort Key: val.value"
>> " Sort Method: quicksort  Memory: 464kB"
>> " ->  Hash Join  (cost=124.76..751538.68 rows=100 width=350) (actual
>> time=99.584..208932.477 rows=2483 loops=1)"
>> "     Hash Cond: ("substring"((val.value)::text, 1, 4) =
>> (gp.value)::text)"
>> "     ->  Nested Loop  (cost=2.54..7.18 rows=100 width=190) (actual
>> time=47.159..90.465 rows=2483 loops=1)"
>> "           ->  Nested Loop  (cost=2.26..4.28 rows=1 width=186)
>> (actual time=47.138..53.093 rows=2483 loops=1)"
>> "                 ->  CTE Scan on parameters p (cost=0.00..0.02
>> rows=1 width=154) (actual time=0.110..0.111 rows=1 loops=1)"
>> "                 ->  HashAggregate  (cost=2.26..3.26 rows=100
>> width=32) (actual time=47.024..51.500 rows=2483 loops=1)"
>> "                       Group Key:
>> unnest(getrecursiveacctsi(getrecursiveacctslvl('{1003174,1003452,1003569,1003605,1003652,1003972,1004173}'::numeric[],
>> '1'::numeric, '4'::numeric)))"
>> "                       ->  Result  (cost=0.00..1.01 rows=100
>> width=32) (actual time=45.289..45.708 rows=2483 loops=1)"
>> "           ->  Index Scan using c_elementvalue_pkey on
>> c_elementvalue val  (cost=0.28..2.90 rows=1 width=36) (actual
>> time=0.010..0.011 rows=1 loops=2483)"
>> "                 Index Cond: (c_elementvalue_id =
>> (unnest(getrecursiveacctsi(getrecursiveacctslvl('{1003174,1003452,1003569,1003605,1003652,1003972,1004173}'::numeric[],
>> '1'::numeric, '4'::numeric)))))"
>> "     ->  Hash  (cost=88.21..88.21 rows=2721 width=29) (actual
>> time=2.358..2.358 rows=2721 loops=1)"
>> "           Buckets: 4096  Batches: 1  Memory Usage: 199kB"
>> "           ->  Seq Scan on c_elementvalue gp (cost=0.00..88.21
>> rows=2721 width=29) (actual time=0.022..1.194 rows=2721 loops=1)"
>> "     SubPlan 2"
>> "       ->  Result  (cost=0.00..0.26 rows=1 width=32) (actual
>> time=0.876..0.876 rows=1 loops=2483)"
>> "     SubPlan 3"
>> "       ->  Result  (cost=0.00..0.26 rows=1 width=32) (actual
>> time=0.801..0.801 rows=1 loops=2483)"
>> "     SubPlan 5"
>> "       ->  Result  (cost=0.26..0.52 rows=1 width=32) (actual
>> time=167.654..167.655 rows=1 loops=211)"
>> "             InitPlan 4 (returns $4)"
>> "               ->  Result  (cost=0.00..0.26 rows=1 width=32) (actual
>> time=1.539..1.540 rows=1 loops=211)"
>> "     SubPlan 6"
>> "       ->  Result  (cost=0.00..0.26 rows=1 width=32) (actual
>> time=9.366..9.366 rows=1 loops=2272)"
>> "     SubPlan 7"
>> "       ->  Result  (cost=0.00..0.26 rows=1 width=32) (actual
>> time=0.892..0.892 rows=1 loops=2483)"
>> "     SubPlan 10"
>> "       ->  Aggregate  (cost=2238.58..2238.59 rows=1 width=32)
>> (actual time=25.526..25.526 rows=1 loops=211)"
>> "             InitPlan 8 (returns $9)"
>> "               ->  CTE Scan on parameters  (cost=0.00..0.02 rows=1
>> width=16) (actual time=0.002..0.003 rows=1 loops=1)"
>> "             ->  Hash Semi Join  (cost=3.02..2237.79 rows=309
>> width=4) (actual time=24.567..25.496 rows=14 loops=211)"
>> "                   Hash Cond: (fact_acct.account_id = (unnest($11)))"
>> "                   ->  Seq Scan on fact_acct (cost=0.00..2225.25
>> rows=2317 width=11) (actual time=17.046..23.482 rows=2136 loops=211)"
>> "                         Filter: (c_period_id = $9)"
>> "                         Rows Removed by Filter: 46524"
>> "                   ->  Hash  (cost=1.77..1.77 rows=100 width=32)
>> (actual time=1.616..1.616 rows=19 loops=211)"
>> "                         Buckets: 1024  Batches: 1  Memory Usage: 9kB"
>> "                         ->  Result  (cost=0.26..0.77 rows=100
>> width=32) (actual time=1.604..1.607 rows=19 loops=211)"
>> "                               InitPlan 9 (returns $11)"
>> "                                 ->  Result (cost=0.00..0.26 rows=1
>> width=32) (actual time=1.598..1.598 rows=1 loops=211)"
>> "     SubPlan 12"
>> "       ->  Aggregate  (cost=1517.00..1517.01 rows=1 width=32)
>> (actual time=6.580..6.580 rows=1 loops=2272)"
>> "             InitPlan 11 (returns $12)"
>> "               ->  CTE Scan on parameters parameters_1
>> (cost=0.00..0.02 rows=1 width=16) (actual time=0.003..0.021 rows=1
>> loops=1)"
>> "             ->  Index Scan using factacct_idxmayor2 on fact_acct
>> fact_acct_1  (cost=0.41..1516.97 rows=3 width=4) (actual
>> time=6.149..6.574 rows=1 loops=2272)"
>> "                   Index Cond: (account_id = val.c_elementvalue_id)"
>> "                   Filter: (c_period_id = $12)"
>> "                   Rows Removed by Filter: 20"
>> "     SubPlan 13"
>> "       ->  Result  (cost=0.00..0.26 rows=1 width=32) (actual
>> time=0.861..0.862 rows=1 loops=2483)"
>> "     SubPlan 16"
>> "       ->  Aggregate  (cost=2238.58..2238.59 rows=1 width=32)
>> (actual time=25.647..25.647 rows=1 loops=211)"
>> "             InitPlan 14 (returns $15)"
>> "               ->  CTE Scan on parameters parameters_2
>> (cost=0.00..0.02 rows=1 width=16) (actual time=0.003..0.003 rows=1
>> loops=1)"
>> "             ->  Hash Semi Join  (cost=3.02..2237.79 rows=309
>> width=5) (actual time=24.698..25.620 rows=14 loops=211)"
>> "                   Hash Cond: (fact_acct_2.account_id = (unnest($17)))"
>> "                   ->  Seq Scan on fact_acct fact_acct_2
>> (cost=0.00..2225.25 rows=2317 width=12) (actual time=17.178..23.602
>> rows=2136 loops=211)"
>> "                         Filter: (c_period_id = $15)"
>> "                         Rows Removed by Filter: 46524"
>> "                   ->  Hash  (cost=1.77..1.77 rows=100 width=32)
>> (actual time=1.626..1.626 rows=19 loops=211)"
>> "                         Buckets: 1024  Batches: 1  Memory Usage: 9kB"
>> "                         ->  Result  (cost=0.26..0.77 rows=100
>> width=32) (actual time=1.614..1.618 rows=19 loops=211)"
>> "                               InitPlan 15 (returns $17)"
>> "                                 ->  Result (cost=0.00..0.26 rows=1
>> width=32) (actual time=1.608..1.608 rows=1 loops=211)"
>> "     SubPlan 18"
>> "       ->  Aggregate  (cost=1517.00..1517.01 rows=1 width=32)
>> (actual time=6.568..6.568 rows=1 loops=2272)"
>> "             InitPlan 17 (returns $18)"
>> "               ->  CTE Scan on parameters parameters_3
>> (cost=0.00..0.02 rows=1 width=16) (actual time=0.004..0.004 rows=1
>> loops=1)"
>> "             ->  Index Scan using factacct_idxmayor2 on fact_acct
>> fact_acct_3  (cost=0.41..1516.97 rows=3 width=5) (actual
>> time=6.133..6.562 rows=1 loops=2272)"
>> "                   Index Cond: (account_id = val.c_elementvalue_id)"
>> "                   Filter: (c_period_id = $18)"
>> "                   Rows Removed by Filter: 20"
>> "     SubPlan 19"
>> "       ->  Result  (cost=0.00..0.26 rows=1 width=32) (actual
>> time=0.855..0.856 rows=1 loops=2483)"
>> "     SubPlan 21"
>> "       ->  Result  (cost=0.26..0.52 rows=1 width=32) (actual
>> time=289.982..289.982 rows=1 loops=211)"
>> "             InitPlan 20 (returns $22)"
>> "               ->  Result  (cost=0.00..0.26 rows=1 width=32) (actual
>> time=1.553..1.554 rows=1 loops=211)"
>> "     SubPlan 22"
>> "       ->  Result  (cost=0.00..0.26 rows=1 width=32) (actual
>> time=17.417..17.417 rows=1 loops=2272)"
>> "Planning time: 14.832 ms"
>> "Execution time: 208957.198 ms"
>