Re: Leer plan de ejecución

[Horacio Miranda]

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"