Análisis de SQL usando trace con eventos y variables de bind

-
Al analizar un proceso de carga se pudo determinar que cuál sentencia SQL era la mas consumidora. A continuación se muestra un extracto de la salida de tkprof:

SELECT
    LTCD_CDG_IATA_ITN_ORI,LTCD_CDG_IATA_ITN_DES,LTFC_DIA_CDG_ITN_ARR_DATE
   ,LTFC_DIA_CDG_ITN_DEP_DATE
FROM
   FTPS
WHERE
   FTPS_PNR_CDG = :b1  AND FTPS_SEG_NMR = :b2  AND LTFV_DIA_CDG =  :b3

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute   9413      0.52       0.44          0          0          0           0
Fetch     9412     18.90    1484.11      18926     108613          0        9405
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    18825     19.42    1484.55      18926     108613          0        9405

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 18  (GEOWBAPN)   (recursive depth: 1)

Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   GOAL: CHOOSE
      0   TABLE ACCESS   GOAL: ANALYZED (BY INDEX ROWID) OF
              'FT_PASAJEROS_SEGMENTO'
      0    INDEX   GOAL: ANALYZED (RANGE SCAN) OF 'FTPS_PK2' (UNIQUE)

Cada ejecución de la query tomaba 0.1 segundos, pero por la cantidad de veces que se ejecuta era importante. Lo que parecía extraño es la cantidad de operaciones de I/O que hacía el query eran 2 por cada ejecución. El índice que estaba usando esta formado por la concatenación de las columnas FTPS_PNR_CDG, FTPS_SEG_NMR, LTFV_DIA_CDG, y éste era prácticamente único. Además estaba la cantidad de bloques en modo query que se visitaban.

Se hizo un ejercicio en modo controlado y arrojó los siguientes resultados:

SELECT
    LTCD_CDG_IATA_ITN_ORI,LTCD_CDG_IATA_ITN_DES,LTFC_DIA_CDG_ITN_ARR_DATE
   ,LTFC_DIA_CDG_ITN_DEP_DATE
FROM
   FTPS
WHERE
   FTPS_PNR_CDG = :b1  AND FTPS_SEG_NMR = :b2  AND LTFV_DIA_CDG = to_date(:b3,'MM/DD/YYYY')

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.00          0         10          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0         10          0           1

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 25  (GEOWBAPN)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS BY INDEX ROWID FT_PASAJEROS_SEGMENTO
      8   INDEX RANGE SCAN (object id 13562)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   GOAL: CHOOSE
      1   TABLE ACCESS   GOAL: ANALYZED (BY INDEX ROWID) OF
              'FT_PASAJEROS_SEGMENTO'
      8    INDEX   GOAL: ANALYZED (RANGE SCAN) OF 'FTPS_AK_2' (NON-UNIQUE)


Lo importante aquí es que se observó que en el índice se estan obteniendo 8 filas y en la tabla se produce un filtro del cual se resulta una sola fila. Este comportamiento es anómalo ya que todas las condiciones deberían aplicarse al índice. Se hizo un trace con variables de bind y eventos, el cual mostró:

PARSING IN CURSOR #23 len=188 dep=1 uid=18 oct=3 lid=18 tim=2407550951 hv=882178843 ad='c08db948'
SELECT LTCD_CDG_IATA_ITN_ORI,LTCD_CDG_IATA_ITN_DES,LTFC_DIA_CDG_ITN_ARR_DATE,LTFC_DIA_CDG_ITN_DEP_DATE   FROM FTPS  WHER
E FTPS_PNR_CDG = :b1  AND FTPS_SEG_NMR = :b2  AND LTFV_DIA_CDG = :b3
END OF STMT
BINDS #23:
 bind 0: dty=1 mxl=32(05) mal=00 scl=00 pre=00 oacflg=03 oacfl2=1 size=64 offset=0
   bfp=018e6ff4 bln=32 avl=05 flg=05
   value="H4V2X"
 bind 1: dty=2 mxl=22(21) mal=00 scl=00 pre=00 oacflg=03 oacfl2=1 size=0 offset=32
   bfp=018e7014 bln=22 avl=02 flg=01
   value=1
 bind 2: dty=12 mxl=07(07) mal=00 scl=00 pre=00 oacflg=03 oacfl2=1 size=0 offset=56
   bfp=018e702c bln=07 avl=07 flg=01
   value="11/10/2001 0:0:0"
EXEC #23:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2407678076
WAIT #23: nam='db file sequential read' ela= 0 p1=11 p2=10085 p3=1
WAIT #23: nam='db file sequential read' ela= 15 p1=38 p2=29946 p3=1
WAIT #23: nam='db file sequential read' ela= 22 p1=39 p2=59771 p3=1
WAIT #23: nam='db file sequential read' ela= 0 p1=38 p2=73425 p3=1
WAIT #23: nam='db file sequential read' ela= 0 p1=39 p2=67945 p3=1
FETCH #23:c=0,e=37,p=5,cr=11,cu=0,mis=0,r=1,dep=1,og=4,tim=2407678113

Lo que se puede ver en este trace es que:

  • Para la query se leyó un bloque de índices (p1=11, es decir datafile 11) y 4 bloques de datos (p1=38 y 39) (esto se sabe gracias a que los índices están en tablespaces distintos y por ende datafiles distintos).
  • Lo indicado calza con la estadística p=5 de la linea FETCH. En ella está informando que para fetch se hicieron 5 operaciones de I/O.

El misterio es porqué, si se obtiene una sola fila de la tabla del índice se obtienen más?

  • Puede ser por chaining. Pero las estdísticas indican que no hay chaining.
  • El ancho promedio de fila es 360. Entonces tampoco puede ser que las filas no caben en un solo bloque.
  • La explicación provino de las variables de bind. El segundo bind es tipo number pero el campo en la tabla es varchar2.
  • Lo que Oracle hace en forma implícita este caso es: to_number(FTPS_SEG_NMR)=:b2 ya que siempre se comparan números con números.
  • Esto hace que el índice sea menos útil de lo que se esperaba.
Al hacer el cambio de la sentencia SQL podemos ver:

SELECT
    LTCD_CDG_IATA_ITN_ORI,LTCD_CDG_IATA_ITN_DES,LTFC_DIA_CDG_ITN_ARR_DATE
   ,LTFC_DIA_CDG_ITN_DEP_DATE
FROM
   FTPS
WHERE
   FTPS_PNR_CDG = :b1 AND FTPS_SEG_NMR = to_char(:b2)  AND LTFV_DIA_CDG = to_date(:b3,'MM/DD/YYYY')

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.43          3          4          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.43          3          4          0           1

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 25  (GEOWBAPN)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS BY INDEX ROWID FT_PASAJEROS_SEGMENTO
      2   INDEX RANGE SCAN (object id 13573)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   GOAL: CHOOSE
      1   TABLE ACCESS   GOAL: ANALYZED (BY INDEX ROWID) OF
              'FT_PASAJEROS_SEGMENTO'
      2    INDEX   GOAL: ANALYZED (RANGE SCAN) OF 'FTPS_AK_2' (NON-UNIQUE)

El número de filas obtenido del índice es 2. Probablemente está contando el scan para saber que no hay mas filas, ya que el índice no es único. Con esto la query al ejecutarla repetidas veces resulta:

SELECT
    LTCD_CDG_IATA_ITN_ORI,LTCD_CDG_IATA_ITN_DES,LTFC_DIA_CDG_ITN_ARR_DATE
   ,LTFC_DIA_CDG_ITN_DEP_DATE
FROM
   FTPS
WHERE
   FTPS_PNR_CDG = :b1  AND FTPS_SEG_NMR = TO_CHAR(:b2)  AND LTFV_DIA_CDG = :b3


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute  19769      1.23       1.44          0          0          0           0
Fetch    19769      2.93      67.10       1103      79467          0       19769
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    39538      4.16      68.54       1103      79467          0       19769

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 18  (GEOWBAPN)   (recursive depth: 1)

Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   GOAL: CHOOSE
      0   TABLE ACCESS   GOAL: ANALYZED (BY INDEX ROWID) OF
              'FT_PASAJEROS_SEGMENTO'
      0    INDEX   GOAL: ANALYZED (RANGE SCAN) OF 'FTPS_PK2' (UNIQUE)

En que cada ejecución toma en promedio 0,0034 seg. Es decir bajó en 29 veces su tiempo gracias a que la cantidad de operaciones de I/O disminuyó a una tasa de 0,05 operaciones de I/O por cada query.

Comentarios

Publicar un comentario

Entradas más populares de este blog

Algoritmo de Merge con Delete

-
En ciertas ocasiones debemos actualizar un conjunto de datos de tal forma que queden idénticos al resultado de una query. Como requisito adicional, tanto los datos de la query origen como la tabla destino tienen un mismo conjunto de columnas que podría ser considerada llave primaria, es decir, que no tienen valores nulos y que no producen registros duplicados. Por ejemplo: hay una tabla con transacciones diarias y es posible que después de cargar las transacciones haya que reprocesar los datos por algún motivo en particular. En este ejemplo, es claro que no existe la alternativa de truncar la tabla original y cargar los datos a partir de la tabla de paso ya que no solo se estarían truncando los registros que se van a cargar sino que también se truncarían los registros de otros días. Otro ejemplo: una tabla debe ser refrescada todos los días. Algunos registros son nuevos, otros se mantienen y otros desaparecen. De los que se mantienen, una gran mayoría queda intacto y unos poco...
Leer más

columna xid en dba_hist_active_sess_history

-
La vista DBA_HIST_ACTIVE_SESS_HISTORY y su origen GV$ACTIVE_SESSION_HISTORY mantienen un muestreo de lo que hacen las sesiones que tienen actividad en el sistema. La primera mantiene un historial de lo capturado por la vista VG$ y de acuerdo a la retención especificada en el repositorio AWR y la segunda sólo mantiene algunas horas. Estas vistas se pueden usar de muchas maneras distintas para entender y mejorar el desempeño de una BD. La plataforma Cloud Control la utiliza en la gran mayoría de las páginas del pack de diagnóstico. El uso de estas vistas requiere poseer la licencia del pack de diagnóstico. En este artículo nos concentramos en el uso de la columna XID de estas vistas. XID es el identificador de transacción, es decir, cada transacción tiene un valor distinto de XID. Esta columna nos permite entonces agrupar una serie de filas de la vista agrupadas por XID, es decir agrupadas por transacción. Pero cómo se relaciona este valor con el resto de vistas del diccionario que...
Leer más