All Things Oracle

Troubleshoot: optimizador confundido

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' );
Con esto los tiempos de ejecución se redujeron notablemente, de un valor inicial promedio de 34.2″ a solo 8.7″, pero aun así quedaba la percepción de que la transacción podía ser más rápida aun, por lo que era inevitable instrumentar la aplicación y así poder identificar con precisión las sentencias SQL adicionales que pudiesen ser afinadas. Para ello se incorporaron las siguientes líneas de código en la rutina problemática:
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;
. . .
Luego de ser implementado el cambio se pudieron identificar más sentencias SQL ineficientes, como por ejemplo:
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 8467123Poor Performance Of Query With Index Full Scan (Min/Max)
Bug 11834402Cbo Chooses A Slow Index Full Scan (Min/Max) Over A Much Faster Index Range Scan
Bug 9140303Optimizer Choose Wrong Index For Min/Max Sql
Bug 8323407Index 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";
Luego de realizar pruebas preliminares se concluye que el workaround es efectivo, programándose su aplicación a nivel de toda la instancia. Luego de ello se vuelve a analizar el universo de sentencias SQL de la transacción problemática, encontrándose que las sentencias previamente identificadas se ejecutan ahora eficientemente, con nuevos planes de ejecución.
Situación original34.2 segundos
Luego de aplicar SQL Profile (2 SQLs)8.7 segundos
Luego de deshabilitar fix del BUG 56119620.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!

¿Te pareció interesante este artículo?, ¿te quedaron algunas dudas?, ¿quieres sugerirme un tema a tratar?, pues déjame tus comentarios o ¡contáctame ahora mismo!

Agregue un comentario

Su dirección de correo no se hará público. Los campos requeridos están marcados *

Este sitio usa Akismet para reducir el spam. Aprende cómo se procesan los datos de tus comentarios.

Posts Relacionados

Articulo publicado en ToadWorld, sobre cómo superar la falta de archived logs para sincronizar un standby.
El evento enq: CF - contention podría resolverse con mantenimiento al controlfile si este contiene gran numero de registros de archived logs.
Qué hacer si nos topamos con el error ORA-600 [kcrf_resilver_log_1] u ORA-600 [4193].

¿Necesitas Ayuda?

Completa estos datos y estaré en contacto a la brevedad.