Ejecuciones anuales que provocan timeout

Ejecuciones anuales que provocan timeout

Vamos a contar la historia de como una consulta que se lanza por periodos anuales, pasa de no llegar a ejecutarse a ejecutarse en buenos tiempos.

Lo primero que vamos a hacer es generar el tkprof. Con esto vamos a poder determinar qué está sucediendo internamente en el tiempo de ejecución. Al ser una consulta un poco especial, no respondía para un año, vamos a generar el tkprof por un día, este es el resultado.

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      1.30       1.30          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2    100.50     100.67       3845   37969878          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4    101.80     101.97       3845   37969878          0           2

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 374  
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         2          2          2  SORT GROUP BY (cr=37969878 pr=3845 pw=0 time=100671461 us starts=1 cost=340 size=172 card=2)

Esto ya nos puede dar una pista de que hay algo que no va bien, para un día casi 38 millones de bloques con un tiempo de unos dos minutos aproximadamente en devolver dos únicas filas.

Viendo el árbol de ejecución, vemos el siguiente NESTED LOOPS que se demora y hace que la consulta no se ejecute de manera eficiente

      1771       1771       1771      FILTER  (cr=37912622 pr=0 pw=0 time=90363553 us starts=948293)
     35062      35062      35062       FILTER  (cr=37912556 pr=0 pw=0 time=89955878 us starts=948293)
     35062      35062      35062        NESTED LOOPS  (cr=37912556 pr=0 pw=0 time=89522627 us starts=948293 cost=14 size=47 card=1)
    948293     948293     948293         TABLE ACCESS BY INDEX ROWID BATCHED T_PARTIDAS (cr=1896903 pr=0 pw=0 time=3731434 us starts=948293 cost=2 size=14 card=1)
    948293     948293     948293          INDEX RANGE SCAN D_PAR_PK (cr=948610 pr=0 pw=0 time=2184310 us starts=948293 cost=1 size=0 card=1)(object id 7165351)
     35062      35062      35062         TABLE ACCESS FULL CG_REF_CODES (cr=36015653 pr=0 pw=0 time=85020179 us starts=948293 cost=12 size=33 card=1)
         3          3          3       TABLE ACCESS FULL T_PARTIDAS (cr=66 pr=0 pw=0 time=386 us starts=3 cost=8 size=14 card=1)

Analizando la SQL para ver donde estaba ese punto, vemos que es el siguiente exists

     Exists (Select 1
                            From t_Dominios_Liqui, t_Partidas
                           Where Rv_Domain = 'PARTIDAS_IBOST_REE'
                             And Rv_Low_Value = Par_Des_Corta ---CAMBIADO HIGH POR LOW
                             And Par_Codigo = Tpc_Par_Codigo
                             And Ldf_Rmp_Par_Codigo =
                                 (Select Par_Codigo
                                    From t_Partidas
                                   Where Par_Des_Corta = Rv_High_Value))

Ese exists no es eficiente, además de que no está correcto a nivel de SQL por la cantidad de datos que tiene la tabla principal.

Volvemos a realizar la ejecución, pero con la SQL cambiada. Analizando las volumetrías de las tablas, ví que la mejor opción usar la clausula with.

Esto son los tiempo que tenemos ahora

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      1.33       1.34          0          0          0           0
Execute      1      0.00       0.00          0         84          2           0
Fetch        2     24.98      33.36     242250      55486          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4     26.32      34.71     242250      55570          2           2

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 374  
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         2          2          2  TEMP TABLE TRANSFORMATION  (cr=55571 pr=242250 pw=242250 time=33369770 us starts=1)

El número de bloques se ha reducido de 38 millones a 56.000 bloques y el tiempo ha bajado del minuto. ¡tenemos que bajarlo más!

En próximos capítulos, contaremos como se ha reducido aún más el tiempo de ejecución.