Unos días atrás me reportaron un problema de mal desempeño de una aplicación bancaria. Resulta que si bien el número de transacciones no era alto, el valor monetario si lo era, por lo que era prioritario que se completase casi instantáneamente. Con el pasar del tiempo estas transacciones iban demorando más y más, al punto de que eventualmente alguna de ellas era dada por fallida y debía ser reiniciada, poniendo nerviosos a todos los involucrados en el negocio, y es en este escenario que deciden acudir a mi asesoría.
El primer problema que encontré es que la aplicación no estaba instrumentada y por tanto su código se confunde con el de otras aplicaciones que también se ejecutan en esa instancia. Afortunadamente, de entre todo el universo de SQLs, el DBA había ya identificado un par de sentencias, y que coincidentemente figuraban en los reportes AWR como las principales responsables de buffer gets, por lo que de inmediato procedí a analizarlas.
select nvl(max(event_seq_no), 0)
from cstbs_contract_change_log
where contract_ref_no = :b1
---------------------------------------------------------------------
| Id | Operation | Name |
---------------------------------------------------------------------
| 0 | SELECT STATEMENT | |
| 1 | SORT AGGREGATE | |
| 2 | FIRST ROW | |
| 3 | INDEX FULL SCAN (MIN/MAX)| PK01_CSTB_CONTRACT_CHANGE_LOG |
---------------------------------------------------------------------
select nvl(max(event_seq_no), 0)
from istbs_contractis
where contract_ref_no = :b1
------------------------------------------------------------
| Id | Operation | Name |
------------------------------------------------------------
| 0 | SELECT STATEMENT | |
| 1 | SORT AGGREGATE | |
| 2 | FIRST ROW | |
| 3 | INDEX FULL SCAN (MIN/MAX)| PK01_ISTB_CONTRACTIS |
------------------------------------------------------------Se comprobó que para ambas tablas existían índices por la columna contract_ref_no, que eran desde luego mucho más adecuados que los de clave primaria, pero por alguna razón el optimizador no los estaba tomando en cuenta, por lo que como medida inicial se procedió a generar nuevas estadísticas, con la esperanza de que eso fuese suficiente para que el Optimizador tomara la decisión correcta.
exec dbms_stats.gather_table_stats(
ownname => 'FCCPRD',
tabname => 'CSTB_CONTRACT_CHANGE_LOG'
cascade => TRUE,
estimate_percent => 100,
method_opt => 'FOR ALL INDEXED COLUMNS SIZE AUTO' );
exec dbms_stats.gather_table_stats(
ownname => 'FCCPRD',
tabname => 'ISTB_CONTRACTIS'
cascade => TRUE,
estimate_percent => 100,
method_opt => 'FOR ALL INDEXED COLUMNS SIZE AUTO' );create or replace PACKAGE BODY pks_msg_router AS
. . .
PROCEDURE p_process_req_msg (is_req_clob IN VARCHAR2
. . .
BEGIN
-- Inicio de la instrumentación
dbms_application_info.set_module(
module_name => 'msg_router',
action_name => 'process_req_msg');
. . .
<lógica original de la aplicación>
. . .
-- Fin de la instrumentación
dbms_application_info.set_module(
module_name => NULL,
action_name => NULL);
END p_process_req_msg;
. . .select nvl(max(event_seq_no),0) from cstbs_contract_event_log
where contract_ref_no = :b1
--------------------------------------------------------------------
| Id | Operation | Name |
--------------------------------------------------------------------
| 0 | SELECT STATEMENT | |
| 1 | SORT AGGREGATE | |
| 2 | FIRST ROW | |
| 3 | INDEX FULL SCAN (MIN/MAX)| PK01_CSTB_CONTRACT_EVENT_LOG |
--------------------------------------------------------------------
select nvl(max(change_seq_no),0) from cstbs_contract_change_log
where contract_ref_no = :b2 and event_seq_no = :b1
----------------------------------------------------------------------
| Id | Operation | Name |
----------------------------------------------------------------------
| 0 | SELECT STATEMENT | |
| 1 | SORT AGGREGATE | |
| 2 | FIRST ROW | |
| 3 | INDEX RANGE SCAN (MIN/MAX)| PK01_CSTB_CONTRACT_CHANGE_LOG |
----------------------------------------------------------------------Lo extendido del problema termina por confirmar que no se trata de una situación normal, sino que se trataría de la incidencia de un bug a nivel del optimizador, siendo el común denominador a todas estas sentencias el que incluyen el operador MIN y/o MAX, y es justamente este criterio el que empleamos para hacer una búsqueda en My Oracle Support, encontrando lo siguiente:
| Bug 8467123 | Poor Performance Of Query With Index Full Scan (Min/Max) |
| Bug 11834402 | Cbo Chooses A Slow Index Full Scan (Min/Max) Over A Much Faster Index Range Scan |
| Bug 9140303 | Optimizer Choose Wrong Index For Min/Max Sql |
| Bug 8323407 | Index Range Scan (Min/Max) Cost Change |
Al parecer Oracle introdujo en Oracle Server 10.2.0.4 un fix para el bug 5611962 CBO does not use index full scan (MIN/MAX) with part. range iterator, pero este fix terminó generando un nuevo bug. ¿La solución? Hacer upgrade a 10.2.0.5 o superior, pero no era viable en este escenario ya que tomaría algo de tiempo en implementar. Afortunadamente existe un workaround: ¡deshabilitar el fix!
SQL> alter system set "_fix_control" = "5611962:OFF";| Situación original | 34.2 segundos |
| Luego de aplicar SQL Profile (2 SQLs) | 8.7 segundos |
| Luego de deshabilitar fix del BUG 5611962 | 0.8 segundos |
Con estos resultados se dio por concluido el afinamiento de la aplicación, obteniendo una disminución del tiempo de ejecución en nada menos que un ¡98%! A la fecha la aplicación opera normalmente y los usuarios están contentos con el tiempo de respuesta, por lo que se considera un caso más resuelto satisfactoriamente.
Espero que se hayan entretenido con la resolución de este caso de la vida real. ¡Será hasta la próxima amigos!