sábado, 17 de mayo de 2014

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' );

Sin embargo los planes de ejecución permanecieron intactos, por lo que como segunda medida, y considerando que se trataba de Oracle Server 10.2.0.4, se procedió a asignar SQL Profiles. Para la primera sentencia se logró obtenerlo mediante el uso de SQL Advisor, pero para la segunda sentencia no fue posible, siendo necesario recurrir al procedimiento señalado en el Note 1400903.1 How to use hints to customize SQL Profile or SQL PLAN Baseline. Luego de esto se obtuvieron finalmente los planes eficientes para ambas sentencias SQL.

----------------------------------------------------------------------
| Id  | Operation                    | Name                          |
----------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                               |
|   1 |  SORT AGGREGATE              |                               |
|   2 |   TABLE ACCESS BY INDEX ROWID| CSTB_CONTRACT_CHANGE_LOG      |
|*  3 |    INDEX RANGE SCAN          | IX03_CSTB_CONTRACT_CHANGE_LOG |
----------------------------------------------------------------------

--------------------------------------------------------------
| Id  | Operation                    | Name                  |
--------------------------------------------------------------
|   0 | SELECT STATEMENT             |                       |
|   1 |  SORT AGGREGATE              |                       |
|   2 |   TABLE ACCESS BY INDEX ROWID| ISTB_CONTRACTIS       |
|*  3 |    INDEX RANGE SCAN          | IX03_ ISTB_CONTRACTIS |
--------------------------------------------------------------

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');
    . . .
    
    . . . 
    -- 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 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";

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.

(1) Situación original                              34.2"
(2) Luego de aplicar SQL Profile (2 SQLs)            8.7"
(3) Luego de deshabilitar fix del BUG 5611962        0.8"

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!

Posts Relacionados:

¿Te pareció interesante este artículo?, ¿te quedaron algunas dudas?, ¿quieres sugerirme un tema a tratar?, pues déjame tus comentarios o envíame un email y para que NO te pierdas ningún Post, suscríbete por email ahora mismo!

2 comentarios, agrega el tuyo!

Developing Solutions dijo...

Hola Kike porque indicas que acceder desde un PK es menos eficiente que un indice?, siempre pense que era mas optimo.

Enrique Orbegozo dijo...

@Developing Solutions: Pues el mejor índice a usar depende exclusivamente de los datos que se proporcionen al hacer la búsqueda. En este caso puntual, los queries filtran por la columna contract_ref_no, que no eran columnas de la clave primaria, de allí que se terminara haciendo muchas más lecturas de las necesarias, esto teniendo en cuenta que sí existían indices por la columna señalada, y por cuyo acceso se hacían menos lecturas.
Saludos y gracias por participar.