¿Cómo interpretar la salida de un trace?

Ha pasado mucho tiempo desde que publiqué mi post ¿Cómo realizar un trace?, y se quedó pendiente el hablar de la interpretación de una salida de un trace. Aquí lo hago ahora, espero les sea de utilidad.

Archivo de trace (en crudo)

Ok, partamos de que se ha generado un archivo trace como lo vimos en el post que publiqué con anterioridad:

E:\oracle\product\admin\udump>dir lab_ora_6100.trc
 El volumen de la unidad E es MetalliOra
 El número de serie del volumen es: 64EE-EC62

 Directorio de E:\oracle\product\admin\udump

03/03/2010  06:53 p.m.        21,314,829 lab_ora_6100.trc
               1 archivos     21,314,829 bytes
               0 dirs   1,627,136,000 bytes libres

El tamaño del archivo, dependerá de la cantidad de consultas que se realizaron desde que se inició el evento del trace hasta que terminó. Este archivo lo podemos ver con un more simple. Sin embargo, la información se verá un tanto difusa, porque es el trace “crudo” que realizamos a nuestra sesión:

E:\oracle\product\admin\udump>more lab_ora_6100.trc
Dump file e:\oracle\product\admin\udump\lab_ora_6100.trc
Wed Mar 03 18:44:34 2010
ORACLE V10.2.0.4.0 - Production vsnsta=0
vsnsql=14 vsnxtr=3
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
Windows XP Version V5.1 Service Pack 2
CPU                 : 2 - type 586
Process Affinity    : 0x00000000
Memory (Avail/Total): Ph:2451M/3571M, Ph+PgF:3885M/5453M, VA:1233M/2047M
Instance name: lab

Redo thread mounted by this instance: 1

Oracle process number: 15

Windows thread id: 6100, image: ORACLE.EXE (SHAD)

*** 2010-03-03 18:44:34.109
*** ACTION NAME:() 2010-03-03 18:44:34.078
*** MODULE NAME:(SQL*Plus) 2010-03-03 18:44:34.078
*** SERVICE NAME:(SYS$USERS) 2010-03-03 18:44:34.078
*** SESSION ID:(434.5) 2010-03-03 18:44:34.078
WAIT #1: nam='SQL*Net message to client' ela= 5 driver id=1111838976 #bytes=1 p3=0 obj#=9867 tim=33262084329
WAIT #1: nam='SQL*Net message from client' ela= 370 driver id=1111838976 #bytes=1 p3=0 obj#=9867 tim=33262130713
=====================
PARSING IN CURSOR #2 len=52 dep=0 uid=27 oct=47 lid=27 tim=33262133548 hv=1029988163 ad='2fd9f3fc'
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
END OF STMT
PARSE #2:c=0,e=346,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=33262133539
WAIT #2: nam='SQL*Net message to client' ela= 4 driver id=1111838976 #bytes=1 p3=0 obj#=9867 tim=33262147074
EXEC #2:c=0,e=3028,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,tim=33262149726
*** 2010-03-03 18:46:33.796
WAIT #2: nam='SQL*Net message from client' ela= 119639435 driver id=1111838976 #bytes=1 p3=0 obj#=9867 tim=33381791859
=====================
PARSING IN CURSOR #4 len=17 dep=0 uid=27 oct=3 lid=27 tim=33382106233 hv=1745700775 ad='2fcf35c0'
select * from emp
END OF STMT
PARSE #4:c=218750,e=308492,p=7,cr=71,cu=0,mis=1,r=0,dep=0,og=1,tim=33382106229
EXEC #4:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=33382106305
WAIT #4: nam='SQL*Net message to client' ela= 3 driver id=1111838976 #bytes=1 p3=0 obj#=9942 tim=33382106336
FETCH #4:c=0,e=29,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,tim=33382106395
WAIT #4: nam='SQL*Net message from client' ela= 1607 driver id=1111838976 #bytes=1 p3=0 obj#=9942 tim=33382108046
WAIT #4: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=9942 tim=33382108084
FETCH #4:c=0,e=46,p=0,cr=5,cu=0,mis=0,r=13,dep=0,og=1,tim=33382108119
WAIT #4: nam='SQL*Net message from client' ela= 58669 driver id=1111838976 #bytes=1 p3=0 obj#=9942 tim=33382166824
=====================
PARSING IN CURSOR #1 len=52 dep=0 uid=27 oct=47 lid=27 tim=33382166885 hv=1029988163 ad='2fd9f3fc'
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
END OF STMT
PARSE #1:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=33382166881
WAIT #1: nam='SQL*Net message to client' ela= 3 driver id=1111838976 #bytes=1 p3=0 obj#=9942 tim=33382167076
EXEC #1:c=0,e=138,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=33382167105
WAIT #1: nam='SQL*Net message from client' ela= 5312053 driver id=1111838976 #bytes=1 p3=0 obj#=9942 tim=33387479212
STAT #4 id=1 cnt=14 pid=0 pos=1 obj=9942 op='TABLE ACCESS FULL EMP (cr=8 pr=0 pw=0 time=23 us)'
=====================
PARSING IN CURSOR #2 len=24 dep=0 uid=27 oct=3 lid=27 tim=33387481663 hv=2343063137 ad='2fcac54c'
select sysdate from dual
END OF STMT
PARSE #2:c=0,e=1153,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=33387481654
EXEC #2:c=0,e=55,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=33387481906
WAIT #2: nam='SQL*Net message to client' ela= 6 driver id=1111838976 #bytes=1 p3=0 obj#=9942 tim=33387481995
FETCH #2:c=0,e=41,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=33387482108
WAIT #2: nam='SQL*Net message from client' ela= 879 driver id=1111838976 #bytes=1 p3=0 obj#=9942 tim=33387483093
FETCH #2:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=33387483179
WAIT #2: nam='SQL*Net message to client' ela= 4 driver id=1111838976 #bytes=1 p3=0 obj#=9942 tim=33387483249
WAIT #2: nam='SQL*Net message from client' ela= 1549 driver id=1111838976 #bytes=1 p3=0 obj#=9942 tim=33387484857
=====================
PARSING IN CURSOR #4 len=52 dep=0 uid=27 oct=47 lid=27 tim=33387485001 hv=1029988163 ad='2fd9f3fc'
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
END OF STMT
PARSE #4:c=0,e=42,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=33387484994
WAIT #4: nam='SQL*Net message to client' ela= 4 driver id=1111838976 #bytes=1 p3=0 obj#=9942 tim=33387485522
EXEC #4:c=0,e=367,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=33387485605
*** 2010-03-03 18:46:49.000
WAIT #4: nam='SQL*Net message from client' ela= 9520902 driver id=1111838976 #bytes=1 p3=0 obj#=9942 tim=33397006632
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=16 us)'
=====================
PARSING IN CURSOR #1 len=36 dep=0 uid=27 oct=3 lid=27 tim=33397008750 hv=2607913065 ad='2fca9dc0'
select * from emp where empno = 7369
END OF STMT
PARSE #1:c=0,e=1723,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=33397008742
EXEC #1:c=0,e=60,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=33397008989
WAIT #1: nam='SQL*Net message to client' ela= 5 driver id=1111838976 #bytes=1 p3=0 obj#=9942 tim=33397009067
WAIT #1: nam='db file sequential read' ela= 13805 file#=4 block#=32 blocks=1 obj#=9943 tim=33397023023
FETCH #1:c=0,e=14007,p=1,cr=2,cu=0,mis=0,r=1,dep=0,og=1,tim=33397023151
WAIT #1: nam='SQL*Net message from client' ela= 5256 driver id=1111838976 #bytes=1 p3=0 obj#=9943 tim=33397028522
FETCH #1:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=33397028611
WAIT #1: nam='SQL*Net message to client' ela= 4 driver id=1111838976 #bytes=1 p3=0 obj#=9943 tim=33397028681
WAIT #1: nam='SQL*Net message from client' ela= 2276 driver id=1111838976 #bytes=1 p3=0 obj#=9943 tim=33397031014

El archivo de este ejemplo que estoy integrando es mucho más grande, pero dejé unas muestras de cómo se ven las consultas que se ejecutaron. Así, veremos separada por líneas formadas por signos de igual (=), la información de cada consulta. En el último ejemplo, tenemos:

select * from emp where empno = 7369

En ella, se ejecutó un PARSE para la instrucción en sí. Después, se realizó una ejecución EXEC para después tener esperas WAIT y extracciones de información FETCH.

Hay que hacer mención, de que cada vez que se ejecutó una consulta por el usuario, Oracle realizó algunas actividades y consultas para poder dar solución a la primera. Por eso, en este archivo y en el traducido, se podrá ver información como:

BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;

ó

select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1,
  spare2
from
 obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null
  and linkname is null and subname is null

que no serán parte de nuestro análisis, porque al final, si resolvemos las consultas hechas por nosotros, este otro tipo de consultas también mejorarán.

No ahondaré más en el tema del trace en crudo. Nos enfocaremos más en la traducción de este archivo en crudo para tener algo más legible.

Archivo de trace (traducido)

¿Cómo traducimos todo el texto que vimos en la sección anterior? Para eso, usaremos la herramienta que viene con el RDBMS de Oracle: tkprof. Este archivo está localizado en el ORACLE_HOME/bin y puede ser ejecutado desde la línea de comando.

Si se ejecuta sin ningún parámetro se obtiene la ayuda de las opciones que pueden ser utilizadas para traducir el archivo crudo del trace:

E:\oracle\product\admin\udump>tkprof
Usage: tkprof tracefile outputfile [explain= ] [table= ]
              [print= ] [insert= ] [sys= ] [sort= ]
  table=schema.tablename   Use 'schema.tablename' with 'explain=' option.
  explain=user/password    Connect to ORACLE and issue EXPLAIN PLAN.
  print=integer    List only the first 'integer' SQL statements.
  aggregate=yes|no
  insert=filename  List SQL statements and data inside INSERT statements.
  sys=no           TKPROF does not list SQL statements run as user SYS.
  record=filename  Record non-recursive statements found in the trace file.
  waits=yes|no     Record summary for any wait events found in the trace file.
  sort=option      Set of zero or more of the following sort options:
    prscnt  number of times parse was called
    prscpu  cpu time parsing
    prsela  elapsed time parsing
    prsdsk  number of disk reads during parse
    prsqry  number of buffers for consistent read during parse
    prscu   number of buffers for current read during parse
    prsmis  number of misses in library cache during parse
    execnt  number of execute was called
    execpu  cpu time spent executing
    exeela  elapsed time executing
    exedsk  number of disk reads during execute
    exeqry  number of buffers for consistent read during execute
    execu   number of buffers for current read during execute
    exerow  number of rows processed during execute
    exemis  number of library cache misses during execute
    fchcnt  number of times fetch was called
    fchcpu  cpu time spent fetching
    fchela  elapsed time fetching
    fchdsk  number of disk reads during fetch
    fchqry  number of buffers for consistent read during fetch
    fchcu   number of buffers for current read during fetch
    fchrow  number of rows fetched
    userid  userid of user that parsed the cursor

De momento, y para efectos del tema de este post, usaremos la opción más común para traducir el archivo crudo del trace:

tkprof archivo_crudo.trc archivo_salida.ext

Por ejemplo,

E:\oracle\product\admin\udump>tkprof lab_ora_6100.trc salida_trace.txt
TKPROF: Release 10.2.0.4.0 - Production on Jue Mar 4 12:30:27 2010
Copyright (c) 1982, 2007, Oracle.  All rights reserved.

E:\oracle\product\admin\udump>

De esta forma, ya tenemos un archivo traducido llamado salida_trace.txt en nuestro directorio UDUMP como se vio en ¿Cómo realizar un trace?. Al darle un more a dicho archivo, podremos ver ya la información en una forma más legible:

E:\oracle\product\admin\udump>more salida_trace.txt
TKPROF: Release 10.2.0.4.0 - Production on Jue Mar 4 12:30:27 2010
Copyright (c) 1982, 2007, Oracle.  All rights reserved.
Trace file: lab_ora_6100.trc
Sort options: default
********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        6      0.00       0.00          0          0          0           0
Execute      6      0.00       0.00          0          3          0           6
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       12      0.00       0.00          0          3          0           6
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 27
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       6        0.00          0.00
  SQL*Net message from client                     6      119.63        183.40
  db file sequential read                         2        0.02          0.02
********************************************************************************
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1,
  spare2
from
 obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null
  and linkname is null and subname is null

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          6          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.00       0.00          0          6          0           2

Nuevamente el archivo es grande, tanto como la cantidad de consultas distintas que fueron ejecutadas mientras se tenía prendido el trace. Por eso, en el ejemplo se encuentra recortada la información.

Vamos a ver ahora, una pequeña explicación de cada sección de este archivo ya traducido. De esta forma, vamos a estar ahondando en el tema principal de este post.

Cuadro de ayuda

Después de la información inicial como la versión, copyright, nombre del archivo; podremos observar un primer cuadro con la ayuda de cada columna de cada cuadro de OCIs (Oracle Call Interface) que aparece para cada consulta ejecutada en el transcurso del trace.

A continuación, se puede ver un ejemplo de dicho cuadro:

********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************

Cuadro de OCIs

Por cada consulta que se ejecutó como parte del trace (directamente por nosotros o indirectamente por Oracle), se podrá ver un cuadro con información importante y relevante para la misma. Así, para la consulta:

select *
from
 emp

Se ve un cuadro como el que sigue:

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        2      0.00       0.00          0          8          0          14
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          8          0          14

Acudiendo a la ayuda como la que puse arriba, veremos lo siguiente:

count

En esta sección, veremos la cantidad de llamadas OCI – Oracle Call Interface para satisfacer el resultado de la consulta. En el ejemplo, se ejecutó 1 Parse, 1 Execute y 2 Fetch.

Esto quiere decir que se realizó una verificación y compilación para la consulta, se ejecutó una vez y se realizaron 2 llamadas de extracción de la información.

Cada una de las columnas restantes, tendrán también un valor para cada OCI.

cpu

Aquí, podremos ver el tiempo en segundos por cada llamada OCI; en este caso, demoró tan poco tiempo que se ve como que está en ceros. Esta columna no nos será de tanta importancia como la siguiente.

elapsed

En esta columna, se puede ver el tiempo acumulado en segundos para cada llamada OCI. El tiempo más importante para nosotros, será el total; esto porque será el tiempo acumulado que tardó la consulta actual en ejecutarse.

En este caso en el ejemplo, podemos ver que tardó tan poco tiempo que se ve como que tardó cero segundos. Al realizar un trace para todo un proceso que se ejecuta en la base de datos, las consultas candidatas a revisión, serán aquellas que demoren demasiados segundos.

disk

Esta es una columna importante en la que podremos ver las lecturas a disco (PIOs – Physical I/O), que la consulta causó por no encontrar en memoria la información a través de los buffer gets (LIOs – Logical I/O). Para ver más información de este tema, pueden visitar mi post: (LIOs vs PIOs) & Hit Ratio.

Hay que recordar que cada una de estas lecturas, es del tamaño del bloque de la base de datos determinado por el parámetro db_block_size.

SQL> show parameter db_block_size
NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_block_size                        integer     16384

En el caso del ejemplo, no requirió leer ningún bloque de disco para satisfacer la consulta.

query

La información que se muestra en esta columna, corresponde a los buffer gets (LIOs – Logical I/O); estos son las lecturas de bloques de memoria, y son dirigidos al área del SGA llamada buffer cache. El valor de este tamaño de memoria se encuentra en el parámetro db_cache_size.

SQL> show parameter db_cache_size
NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_cache_size                        big integer 200M

En esta área, Oracle guarda los registros más comúnmente consultados de las tablas. Si se tiene un tamaño grande de ésta área, se podrá guardar una mayor cantidad de información con lo que al ejecutar una consulta, la información será leída principalmente de memoria. El número que se vea aquí, será la cantidad de bloques de leídos. En este caso, para nuestro ejemplo, fueron leídos 8 bloques de memoria. Si cada bloque es de 16kb, entonces habremos leído un total de 128kb de memoria.

current

En esta columna, veremos bloques actualizados por medio de una instrucción update. De hecho, sólo cuando se ejecuta una de estas instrucciones, es cuando podremos ver información en dicha columna. En este caso, por haber sido un select, no aparece información.

rows

Finalmente, en esta columna podremos observar los registros que se han consultado, insertado, actualizado o borrado  en la instrucción actual. Para nuestro actual ejemplo, esto corresponde 14 registros que fueron extraídos por medio de un fetch.

Información general

Lo siguiente que se puede ver en el trace, será información relacionada con la consulta ejecutada:

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 27

Donde:

Misses in library cache during parse, son los eventos de fallo mientras se buscaba un plan de ejecución en el Shared Pool. En este caso, no hubo ningún fallo ya se había ejecutado previamente esta consulta.

Optimizer mode, es el modo en que el CBO – Cost Based Optimizer se encontraba al momento de la ejecución de la consulta actual. Para nuestro ejemplo, se tenía la opción de ALL_ROWS.

Parsing user id, es el número de identificación del usuario que ejecutó la consulta. En este caso, el número 27 corresponde a mi usuario PRUEBA.

Plan de ejecución

La siguiente parte dentro del archivo trace, muestra el plan de ejecución de la consulta en cuestión:

Rows     Row Source Operation
-------  ---------------------------------------------------
     14  TABLE ACCESS FULL EMP (cr=8 pr=0 pw=0 time=62 us)

Dicho plan, es un poco distinto de los que hacemos con el explain plan for y set autotrace. En este, se ven los registros que se trajeron. En segundo plano, se muestra entre paréntesis información para cada paso ejecutado. Esta información la explico a continuación:

cr – Consistent reads, llamados también buffer gets o LIOs. Son las lecturas de bloques a memoria.

pr – Physical reads, son las lecturas en bloques que se realizaron al disco para traer la información.

pw – Physical writes, son las escrituras a disco en bloques.

time – Es la cantidad de microsegundos que se usaron para traer la información; si queremos ver esta información en segundos, se tiene que dividir sobre 1,000,000.

Esperas

En esa sección, se pueden ver las esperas que se tuvieron para la consulta actual:

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2        0.00          0.00

Las esperas son representadas en segundos, y las columnas que se tienen en dicho cuadro, corresponden a lo siguiente:

Event waited on – En esta columna, se puede ver el evento que causó la espera. Este será muy útil para determinar qué fue propiamente lo que nos causo dicha espera. Unas de las esperas más comunes son:

SQL*Net message to client – Son las esperas que tiene el cliente (conexión desde el usuario) para que la base de datos le envíe algo.

SQL*Net message from client – Son las esperas que tiene la base de datos por el cliente para que le mande algo. Es decir, la base de datos se queda esperando por alguna instrucción por parte del cliente.

DB file sequencial read – Es una espera causada por una lectura a un bloque simple. Generalmente está atribuida a una columna indexada.

DB file scattered read – Es una espera generada en el momento de que una consulta busca información en el SGA y se genera una lectura física en la cual, es donde reside la espera propiamente.

Para más eventos de espera y su descripción, pueden verlos aquí para la versión 10g. En mis ligas de ayuda de Oracle de la derecha de está página, pueden encontrar cosas similares para otras versiones.

Times Waited – Es la cantidad de eventos de espera que ocurrieron.

Max. Wait – Es el máximo tiempo de espera expresado en segundos. No es tan importante como la siguiente columna.

Total Waited – Es el total de tiempo de espera en segundos, que se tuvo para esta consulta y evento.

Toda la información anterior (consulta, cuadro de OCIs, datos generales, plan de ejecución y esperas), se replica para cada consulta ejecutada por el usuario o generada por Oracle para satisfacer las consultas generadas por el usuario. Toda la información de cada consulta, es separada por una línea de asteríscos (*****************). De esta forma, se puede analizar por consulta qué fue lo que pasó.

Resumen de totales

Al final, después de todas estadísticas mostradas por cada una de las consultas, se puede ver la información general para todo lo que se ejecutó en un trace. La primera parte es para los non-recursive statements :

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       10      0.00       0.00          0          0          0           0
Execute     10      0.00       0.00          0          3          0           5
Fetch    71687      2.62       2.84          0      77951          0     1075216
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    71707      2.62       2.85          0      77954          0     1075221
Misses in library cache during parse: 0
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                   71693        0.00          0.15
  SQL*Net message from client                 71693        0.12        261.46

Como se puede ver, es algo similar a lo visto por cada consulta, sólo que agrupa todo lo que se analizó, pero sin planes de ejecución ni algunos otros datos. En el ejemplo, puse en negritas el hecho de que hay dos tipos de resumen, uno para las consultas no son repetidas (NON-RECURSIVE) y otro para las consultas que se repitieron con otra consulta previamente ejecutada durante el trace (RECURSIVE).

Esta información general, se interpreta de manera similar a lo que ya se vio para cada uno de las consultas ejecutadas.

Resumen final

Al final del archivo traducido del trace, se podrá ver información como la siguiente:

Trace file: lab_ora_2892.trc
Trace file compatibility: 10.01.00
Sort options: default
       1  session in tracefile.
      10  user  SQL statements in trace file.
       0  internal SQL statements in trace file.
      10  SQL statements in trace file.
       6  unique SQL statements in trace file.
  215188  lines in trace file.
     268  elapsed seconds in trace file.

En él, se pueden ver datos más genéricos del mismo trace, como las sesiones incluidas en el trace, las consultas del usuario, consultas internas, consultas generales incluidas en el archivo, consultas únicas o no-repetidas, cantidad de líneas en el archivo y la cantidad de segundos acumulada para el mismo.

Conclusiones

El poder realizar y revisar un trace para un proceso, procedimiento, sesión de trabajo, etcétera; es una poderosa herramienta para poder saber qué es lo que está pasando realmente con la base de datos y la forma en que nos está trayendo la información.

Como DBAs, es una herramienta opcional para cuando se quiere saber qué está realizando algún usuario o algún proceso que esté demorando demasiado; o que esté consumiendo muchos recursos del servidor de la base de datos como memoria o procesador.

Como desarrolladores, esta es una herramienta imprescindible para poder validar que las aplicaciones liberadas para un ambiente como Producción son lo más eficientes posible.

Si la información de este post te ha sido de utilidad o quieres que agregue algo más, deja por favor un comentario, contestaré a la brevedad.

Anuncios

17 Responses to ¿Cómo interpretar la salida de un trace?

  1. Jas says:

    Excelente, me ha sido muy útil

  2. orlandoolguin says:

    Hola Jas,

    Qué bueno que te ha sido de utilidad y ojalá que sigas visitando mi blog.

    Orlando.

  3. Victor Pincheira says:

    muchas gracias, estoy comenzando a estudiar este tema y lo encontre super claro

  4. orlandoolguin says:

    Hola Victor,

    Qué bueno que te ha sido de utilidad. Espero me sigas visitando.

    Orlando.

  5. Milton Betancourth says:

    Muy interesante, muchas gracias.

  6. orlandoolguin says:

    Hola Milton

    Qué bueno que te haya sido de utilidad, espero que me sigas visitando.

    Orlando.

  7. Pingback: TKPROF | sersanso

  8. Hola tengo una duda, en la parte de count fila “parse” un valor alto como 130 es normal o se tiene que validar por que analiza tantas veces?

  9. Orlando Olguín Olvera says:

    Hola Jenny.

    Si tu parámetro de base de datos CURSOR_SHARING tiene el valor de EXACT, entonces espera queries iguales para no hacer parse y sólo ejecutar el query desde el Shared Pool.

    Entonces, si tienes 130 ejecuciones PARSE, es muy probable que en tu proceso estén armando varias consultas “diferentes”, por el hecho de pasar un parámetro, por ejemplo: select * from tabla where campo = valor_que_se_pone;

    Orlando.

  10. Carlos says:

    Excelente ! ..muy didactico Orlando …te felicito. Muchas Gracias !

  11. Carlos says:

    Desde SQL Developer estoy intentando crear un Repositorio de Migracion, en esa opcion se ejecuta un proceso y da error …le he puesto un trace (siguiendo tu post de trace). …cual seria el error que se produce?
    Es: select * from md_connections where 1=0
    Error encountered: ORA-00942
    ???

    …a continuacion pongo las 1eras lineas …gracias…

    TKPROF: Release 10.2.0.4.0 – Production on Mar Oct 6 13:48:29 2015

    Copyright (c) 1982, 2007, Oracle. All rights reserved.

    Trace file: orcl10g_ora_6116.trc
    Sort options: default

    ********************************************************************************
    count = number of times OCI procedure was executed
    cpu = cpu time in seconds executing
    elapsed = elapsed time in seconds executing
    disk = number of physical reads of buffers from disk
    query = number of buffers gotten for consistent read
    current = number of buffers gotten in current mode (usually for update)
    rows = number of rows processed by the fetch or execute call
    ********************************************************************************

    The following statement encountered a error during parse:

    select * from md_connections where 1=0

    Error encountered: ORA-00942
    ********************************************************************************

    select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1,
    spare2
    from
    obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null
    and linkname is null and subname is null

    call count cpu elapsed disk query current rows
    ——- —— ——– ———- ———- ———- ———- ———-
    Parse 17 0.00 0.00 0 0 0 0
    Execute 30 0.00 0.00 0 0 0 0
    Fetch 30 0.00 0.00 0 90 0 0
    ——- —— ——– ———- ———- ———- ———- ———-
    total 77 0.00 0.00 0 90 0 0

    Misses in library cache during parse: 0
    Optimizer mode: CHOOSE
    Parsing user id: SYS (recursive depth: 1)

    Rows Row Source Operation
    ——- —————————————————
    0 TABLE ACCESS BY INDEX ROWID OBJ$ (cr=3 pr=0 pw=0 time=38 us)
    0 INDEX RANGE SCAN I_OBJ2 (cr=3 pr=0 pw=0 time=32 us)(object id 37)

    ********************************************************************************

  12. Carlos says:

    Hay un proceso (caja negra) que se ejecuta en la BD y da ERROR, …Orlando, hay alguna forma de identificar que sentencia se ejecuta en la BD que pueda estar fallando?? …pense hacer un TRACE 10046 …pero no me sale el error.
    Gracias.

  13. Orlando Olguín Olvera says:

    Hola Carlos.

    Muchas gracias.

    Orlando.

  14. Orlando Olguín Olvera says:

    Hola Carlos.

    El trace no te va a mostrar el error como tal.

    El error:
    ORA-00942: table or view does not exist

    Corresponde al hecho de que no tienes acceso o permiso a la tabla que quieres ver de MD_CONNECTIONS.

    Verifica que tienes permisos suficientes.

    Orlando.

  15. Orlando Olguín Olvera says:

    Hola Carlos.

    Como ya comenté, el trace no te dará los errores al momento de ejecutar.

    Si el proceso es una caja negra, muy poco te puedo decir sobre en qué sentencia se está ejecutando al momento que dio error.

    ¿Qué error te está arrojando?, si es algo en tiempo ejecución, tal vez se pueda ver a través de la V$SQLAREA.

    En esta vista, se ven las consultas que han sido ejecutadas, si el error es en tiempo de ejecución, entonces tal vez tengas la esperanza de que se alcance a registrar la consulta antes de que truene.

    Así, limpias el SHARED_POOL o reinicias la instancia para que la vista esté limpia y corres el proceso, ahí verás todas las consultas que ejecutó el proceso hasta el error.

    Nota. Si la consulta misma tiene un error como el otro que posteaste de MD_CONNECTIONS, entonces NO se registra la consulta en la V$SQLAREA.

    Espero te sea de utilidad.

    Orlando.

  16. Roberto says:

    Excelente, de mucha utilidad para el desarrollador., Gracias

  17. Orlando Olguín Olvera says:

    Hola Roberto.

    De hecho, con eso, podrás analizar mejor la forma en cómo construyes tus queries y que sean eficientes.

    ¡Qué bueno que te ha sido de utilidad!

    Orlando.

Responder

Introduce tus datos o haz clic en un icono para iniciar sesión:

Logo de WordPress.com

Estás comentando usando tu cuenta de WordPress.com. Cerrar sesión / Cambiar )

Imagen de Twitter

Estás comentando usando tu cuenta de Twitter. Cerrar sesión / Cambiar )

Foto de Facebook

Estás comentando usando tu cuenta de Facebook. Cerrar sesión / Cambiar )

Google+ photo

Estás comentando usando tu cuenta de Google+. Cerrar sesión / Cambiar )

Conectando a %s

A %d blogueros les gusta esto: