Dentro de un E-Business suite, un usuario se quejaba sobre el desempeño de una forma de Order Entry que al hacer un drilldown de GL a XLAIQDRL,
el sistema no respondía en mucho tiempo.
Lo que logramos identificar en este problema, fue un acceso muy pesado a la tabla MTL_TRANSACTION_ACCOUNTS.
Como primer intento de solución, encontramos una nota en metalink que pudiera ayudar a resolver el problema, la cual indica aplicar un
parche junto con la creación de un índice.
CREATE INDEX "INV"."MTL_TRANSACTION_ACCOUNTS_N79" ON
"INV"."MTL_TRANSACTION_ACCOUNTS" ("GL_BATCH_ID", "REFERENCE_ACCOUNT", "TRANSACTION_DATE")
COMPUTE STATISTICS
TABLESPACE "APPS_TS_TX_IDX";
Al hacer los cambios sugeridos, y al revisar el proceso nuevamente, nos encontramos con las siguientes estadísticas en el trace
call count cpu elapsed disk query
------- ------ -------- ---------- ---------- ----------
Parse 1 2.86 2.78 0 0
Execute 1 28.87 28.43 0 0
Fetch 1 114.17 111.90 120 756369
------- ------ -------- ---------- ---------- ----------
total 3 145.90 143.12 120 756369
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 44
Rows Row Source Operation
------- ---------------------------------------------------
10 SORT ORDER BY (cr=756369 pr=120 pw=0 time=111904779 us)
11176 UNION-ALL (cr=756369 pr=120 pw=0 time=22934845 us)
0 FILTER (cr=0 pr=0 pw=0 time=7 us)
La cantidad de bloques leídos de memoria es mucha, pero quizás por el tipo de accesos que hace, pudiera considerarse normal, el plan de ejecución
consta de más de 590 líneas.
Al hacer un cambio en el índice de orden de columnas
CREATE INDEX "INV"."MTL_TRANSACTION_ACCOUNTS_N79" ON
"INV"."MTL_TRANSACTION_ACCOUNTS" ("GL_BATCH_ID", "REFERENCE_ACCOUNT", "TRANSACTION_DATE")
COMPUTE STATISTICS
TABLESPACE "APPS_TS_TX_IDX";
se logró lo siguiente:
call count cpu elapsed disk query
------- ------ -------- ---------- ---------- ----------
Parse 1 3.31 3.23 0 0
Execute 1 34.25 33.44 0 0
Fetch 1 27.81 27.15 0 331474
------- ------ -------- ---------- ---------- ----------
total 3 65.37 63.83 0 331474
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 44
Rows Row Source Operation
------- ---------------------------------------------------
10 SORT ORDER BY (cr=331474 pr=0 pw=0 time=27155623 us)
11176 UNION-ALL (cr=331474 pr=0 pw=0 time=22074357 us)
0 FILTER (cr=0 pr=0 pw=0 time=8 us)
0 FAST DUAL (cr=0 pr=0 pw=0 time=0 us)
Como se puede ver, el cambio del orden de las columnas, hizo que se leyeran menos de la mitad de los bloques de memoria, y por lo mismo, el query se ejecutó en menos de la mitad del tiempo que antes.
Pero hay un detalle importante a notar,
call count cpu elapsed
------- ------ -------- ----------
Parse 1 3.31 3.23
Execute 1 34.25 33.44
Fetch 1 27.81 27.15
Misses in library cache during parse: 1
10 SORT ORDER BY (cr=331474 pr=0 pw=0 time=27155623 us)
Como se puede observar, la sentencia SQL no se encontraba en memoria, por lo cuál se obligó a un Hard Parse. La llamada execute, se dice que nos muestra
estadísticas en la fase de ejecución de un cursor "y... ¿qué diablos es eso?"... Pues bien, parece ser que para una sentencia select, el tiempo de esta llamada,
es el tiempo que Oracle gasta en generar el plan de ejecución.
En el trace, justo después de la llamada
PARSING IN CURSOR #47 len=7409 dep=0 uid=44 oct=3 lid=44 tim=7410852239759 hv=948570397 ad='bd8a6170'
SELECT TRX_CLASS_NAME,TRX_TYPE_NAME,TRX_NUMBER_DISPLAYED,TRX_DATE
PARSING IN CURSOR #49 len=198 dep=2 uid=0 oct=3 lid=0 tim=7410852558503 hv=4125641360 ad='bebe5ac0'
EXEC #49:c=0,e=931,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=7410852560307
PARSING IN CURSOR #49 len=493 dep=2 uid=0 oct=3 lid=0 tim=7410852561080 hv=2584065658 ad='bdfbfd78'
EXEC #49:c=0,e=514,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=7410852563193
PARSING IN CURSOR #49 len=789 dep=2 uid=0 oct=3 lid=0 tim=7410852564507 hv=3159716790 ad='baf88850'
... (60 llamadas similares) ...
EXEC #49:c=0,e=617,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=7410880914683
PARSING IN CURSOR #50 len=192 dep=1 uid=0 oct=3 lid=0 tim=7410880915705 hv=3136611056 ad='bea06ed8'
EXEC #50:c=0,e=614,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=7410880916713
EXEC #47:c=34380000,e=33582714,p=1,cr=244,cu=0,mis=0,r=0,dep=0,og=1,tim=7410885823104
Todas las llamadas de cursor #49 y #50 eran queries recursivos, muchos sobre la tabla association$. Y claro, si vas a generar un plan de ejecución de +550 líneas, pues imagínense las posibilidades. Por supuesto que esto no sucedía si la sentencia SQL ya estaba en memoria y sólo un "Soft Parse" sucedía, pero por la naturaleza de la aplicación, y de la lógica del negocio, no solía ser un query tan frecuente, y generalmente a los 10 minutos se encontraba fuera del shared_pool, obligando a un "hard parse" en la siguiente ejecución (34 segundos en el execute).
Así que opté por una solución alterna.
¿Cómo se puede precalcular el plan de ejecución de una sentencia SQL?
La respuesta es sencilla. OUTLINES.
Yo había usado con anterioridad Outlines para hacer cambios en los planes de ejecución en aplicaciones de código cerrado, y la lógica que usaba era:
Cuando Oracle reciba una sentencia SQL y se calcule su Hash_value (soft parse), al usar outlines, en lugar de generar un plan de ejecución, use este otro ya "PRECALCULADO". Así que, ¿Qué sucedería si genero un outline para que use su mismo plan de ejecución?, el resultado fue el siguiente:
Al yo conocer el Hash Value "hv=948570397", y sabiendo que en ese momento, la sentencia estaba en el shared_pool, ejecuté lo siguiente:
SQL> BEGIN
2 DBMS_OUTLN.create_outline(
3 hash_value => 948570397,
4 child_number => 0,
5 category => 'RIT_OUTLINES');
6 END;
7 /
Procedimiento PL/SQL terminado correctamente.
Algunas veces marca un error de End Of Communication Chanel, pero sí genera el outline (me ha sucedido con 10.2.0.2 en linux suse y solaris).
SQL> SELECT name,
2 category,
3 used
4 FROM dba_outlines;
NAME CATEGORY USED
------------------------------ -------------- ------
SYS_OUTLINE_08110513401290701 RIT_OUTLINES UNUSED
Ahora alteramos el sistema para que se use nuestro outline
SQL> ALTER system
2 SET use_stored_outlines = rit_outlines;
Sistema modificado.
SQL> alter system flush shared_pool;
Sistema modificado.
De esta forma bajamos la sentencia SQL de memoria y obligamos a un "Hard Parse". Intentamos nuestra prueba nuevamente, y estos fueron los resultados:
call count cpu elapsed disk query
------- ------ -------- ---------- ---------- ----------
Parse 1 3.98 3.98 0 449
Execute 1 2.70 2.62 0 0
Fetch 1 28.92 28.24 0 331299
------- ------ -------- ---------- ---------- ----------
total 3 35.60 34.85 0 331748
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 44
Rows Row Source Operation
------- ---------------------------------------------------
10 SORT ORDER BY (cr=331299 pr=0 pw=0 time=28242017 us)
11176 UNION-ALL (cr=331299 pr=0 pw=0 time=22968921 us)
Como se puede ver, se realizo un "hard parse", y el tiempo que se utilizó en la llamada Execute fue de menos de 3 segundos (comparado contra los 34 segundos).
Revisamos que nuestro outline haya sido utilizado:
SQL> SELECT name,
2 category,
3 used
4 FROM dba_outlines;
NAME CATEGORY USED
------------------------------ -------------- ------
SYS_OUTLINE_08110513401290701 RIT_OUTLINES USED
Cabe decir que no se puede usar un parámetro de init para usar los outlines, por lo que se recomienda un trigger para dejarlo activarlo en cada startup (o bien a nivel sesión). Debe de estar habilitado el Query Rewrite y se debe de tener mucho cuidado al usarlos, ya que puede haber algunas implicaciones al hacer uso de outlines.
Para el usuario final, el tiempo bajó de 5 minutos a sólo 30 segundos, lo cual fue muy bueno. Así que ya saben, cuando su generación de un plan de ejecución sea muy tardado, siempre está la opción de precompilarlo en un outline.
