Troubleshoot: optimizador confundido

mayo 17, 2014
No Comments

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.

Copiar

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.

Copiar

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:

Copiar

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:

Copiar

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!

Copiar

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 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!

¿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!