Líneas del trace 10046 que lee WaitScope

El trace 10046 es un archivo de texto: cada línea empieza por el tipo (PARSE, WAIT, STAT...) y sigue con campos en el formato nombre=valor. Esta página enumera las líneas que WaitScope lee, los campos que usa y dónde aparece cada uno en el informe. Los ejemplos son del trace sintético de ejemplo, el mismo del informe de ejemplo.

Un trace corto

En el trace sintético, un SELECT de nivel 0 dispara una consulta recursiva al diccionario y después espera a la aplicación:

Trace file /u01/app/oracle/diag/rdbms/orcl/ORCL1/trace/ORCL1_ora_4242.trc
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.3.0.0.0
Node name: db-exemplo
Instance name: ORCL1
Unix process pid: 4242, image: oracle@db-exemplo

*** 2024-01-02T10:00:00.000000-03:00
*** SESSION ID:(10.20) 2024-01-02T10:00:00.000000-03:00
*** MODULE NAME:(app-exemplo) 2024-01-02T10:00:00.000000-03:00

=====================
PARSING IN CURSOR #1 len=26 dep=0 uid=1 oct=3 lid=1 tim=1000100 hv=111 ad='a' sqlid='7zq3k1c9m2x4p'
select * from t where id=1
END OF STMT
PARSE #1:c=50,e=100,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=10,tim=1000100
EXEC #1:c=10,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=10,tim=1000150
WAIT #1: nam='SQL*Net message to client' ela= 2 driver id=1 #bytes=1 p3=0 obj#=-1 tim=1000160
=====================
PARSING IN CURSOR #2 len=31 dep=1 uid=0 oct=3 lid=0 tim=1000200 hv=222 ad='b' sqlid='0w5n8r2t6v1yb'
select obj# from obj$ where x=1
END OF STMT
EXEC #2:c=5,e=10,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=20,tim=1000210
BINDS #2:
 Bind#0
  value=1
WAIT #2: nam='db file sequential read' ela= 300 file#=1 block#=100 blocks=1 obj#=50 tim=1000520
FETCH #2:c=40,e=380,p=1,cr=3,cu=0,mis=0,r=1,dep=1,og=4,plh=20,tim=1000600
WAIT #1: nam='db file sequential read' ela= 1000 file#=1 block#=100 blocks=1 obj#=50 tim=1001700
FETCH #1:c=200,e=1600,p=1,cr=10,cu=0,mis=0,r=1,dep=0,og=1,plh=10,tim=1001800
WAIT #1: nam='SQL*Net message from client' ela= 5000 driver id=1 #bytes=1 p3=0 obj#=-1 tim=1006900
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=50 op='TABLE ACCESS BY INDEX ROWID T (cr=10 pr=1 pw=0 time=1500 us cost=2 size=10 card=1)'
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=51 op='INDEX UNIQUE SCAN T_PK (cr=2 pr=0 pw=0 time=30 us cost=1 size=0 card=1)'
CLOSE #1:c=1,e=2,dep=0,type=0,tim=1007000
XCTEND rlbk=0, rd_only=1, tim=1007010

El tiempo total de este trace es de 7.010 microsegundos: desde el inicio del primer PARSE (tim 1000100 menos e 100) hasta el tim del XCTEND.

Unidad de tiempo

Desde Oracle 9i, los tiempos del trace (c, e, ela y tim) están en microsegundos. En los traces de Oracle 7 y 8, están en centésimas de segundo. WaitScope reconoce el trace antiguo por la versión de la base de datos en el encabezado y convierte todo a microsegundos. El resumen muestra la unidad en Unidad de tiempo: microsegundos o centésimas de segundo (trace antiguo).

El tim es el instante en que terminó la llamada o la espera. El inicio es el tim menos el e, o menos el ela. En un trace antiguo, la espera puede venir sin tim: en ese caso, la separación entre esperas dentro y fuera de las llamadas usa el nombre del evento, y el informe lo avisa.

Encabezado y líneas con ***

Estos campos quedan en la tarjeta Sesión y entorno del resumen, sin máscara: vea Resumen.

PARSING IN CURSOR

PARSING IN CURSOR #1 len=26 dep=0 uid=1 oct=3 lid=1 tim=1000100 hv=111 ad='a' sqlid='7zq3k1c9m2x4p'
select * from t where id=1
END OF STMT

Trae el texto del SQL del cursor, en las líneas siguientes, hasta END OF STMT. A partir de ahí, las líneas con el mismo número de cursor (#1) son de esa sentencia, hasta que el cursor recibe otro texto.

PARSE, EXEC, FETCH y CLOSE

PARSE #1:c=50,e=100,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=10,tim=1000100
FETCH #1:c=200,e=1600,p=1,cr=10,cu=0,mis=0,r=1,dep=0,og=1,plh=10,tim=1001800
CLOSE #1:c=1,e=2,dep=0,type=0,tim=1007000

Una línea por llamada a la base de datos, con el número del cursor después de #. Las mismas reglas valen para UNMAP, SORT UNMAP y las llamadas de LOB (LOBREAD:, LOBWRITE: y las demás), que entran en Tipos de llamada por el nombre. La llamada sin tim queda fuera.

La CPU, las esperas y las llamadas recursivas que terminan dentro de una llamada cuentan para ella. Lo que sobra de la duración pasa a ser tiempo no contabilizado dentro de las llamadas.

WAIT

WAIT #1: nam='db file sequential read' ela= 1000 file#=1 block#=100 blocks=1 obj#=50 tim=1001700
WAIT #1: nam='SQL*Net message from client' ela= 5000 driver id=1 #bytes=1 p3=0 obj#=-1 tim=1006900

Una línea por espera. Los parámetros después de ela= cambian con el evento. En los traces recientes, vienen con nombre (file#, block#, driver id); en los antiguos, como p1, p2 y p3.

La espera que termina dentro de una llamada cuenta para esa llamada. La que queda entre el fin de una llamada de nivel 0 y el inicio de la siguiente es espera entre llamadas, como la SQL*Net message from client del ejemplo.

STAT

STAT #1 id=1 cnt=1 pid=0 pos=1 obj=50 op='TABLE ACCESS BY INDEX ROWID T (cr=10 pr=1 pw=0 time=1500 us cost=2 size=10 card=1)'
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=51 op='INDEX UNIQUE SCAN T_PK (cr=2 pr=0 pw=0 time=30 us cost=1 size=0 card=1)'

Una línea por operación del plan del cursor. Cada plan grabado pasa a ser un bloque Plan de ejecución en el detalle de la sentencia. Cuando el mismo plan se graba más de una vez, el informe muestra el último.

Vea Plan de ejecución para leer estas columnas en el detalle de la sentencia.

BINDS

BINDS #2:
 Bind#0
  value=1

Los valores de bind aparecen en los niveles 4 y 12 del 10046, o con binds => TRUE en DBMS_MONITOR. WaitScope reconoce la línea BINDS e ignora el bloque entero: los valores no entran en el informe. Aun así, es preferible generar el trace sin ellos (valores de bind).

XCTEND

XCTEND rlbk=0, rd_only=1, tim=1007010

El fin de una transacción. rlbk=0 es commit y rlbk=1 es rollback: el resumen cuenta los dos, como “N commits · N rollbacks”. El tim entra en el tiempo total y en el período; rd_only no se usa.

ERROR y PARSE ERROR

PARSE ERROR #2:len=24 dep=0 uid=1 oct=3 lid=1 tim=150 err=942
select * from nao_existe
ERROR #1:err=1403 tim=201

ERROR registra un error ORA- en una llamada del cursor: WaitScope lee el código (err=) y lo vincula con la llamada anterior del mismo cursor. PARSE ERROR registra el error en el parse, con el texto del SQL en las líneas siguientes. Los dos van a la sección Errores, con el código, cuántas veces apareció y dónde. El trace guarda solo el código: el texto completo del mensaje lo tiene quien recibió el error. Vea Errores.

Bloque de deadlock

DEADLOCK DETECTED ( ORA-00060 )

[Transaction Deadlock]

Deadlock graph:
                                          ------------Blocker(s)-----------  ------------Waiter(s)------------
Resource Name                             process session holds waits serial  process session holds waits serial
TX-00090014-00000A01-00000000-00000000         31      10     X           20      32      11           X     30
TX-00170008-00000B02-00000000-00000000         32      11     X           30      31      10           X     20

Cuando la sesión recibe el ORA-00060, Oracle graba en su trace el bloque que empieza en DEADLOCK DETECTED. WaitScope lee el grafo (Deadlock graph:), las filas esperadas (Rows waited on:), las otras sesiones involucradas, el SQL de la sesión que recibió el error y la pila PL/SQL (PL/SQL Call Stack). El bloque vale tanto en el trace solo de deadlock como dentro de un 10046. Vea trace de deadlock y Deadlocks.

TRACE CONTINUES IN FILE

*** TRACE CONTINUES IN FILE /u01/trace/ORCL1_ora_4242_etapa2.trc ***

Cuando la aplicación cambia el tracefile_identifier, Oracle cierra el tramo con *** TRACE CONTINUES IN FILE y sigue en otro archivo, que empieza con *** TRACE CONTINUED FROM FILE. En el análisis de un solo archivo, estas líneas no cambian nada. En la colección, WaitScope corta cada archivo en esos puntos y junta los tramos de la misma sesión en el orden del tim: vea analizar varios traces juntos.

Líneas ignoradas

• Los valores de bind, en el bloque BINDS.
• Las líneas de separación (=====================).
• Cualquier línea que no sea de uno de los tipos de esta página.

Un archivo sin ninguna línea del 10046 ni bloque de deadlock se rechaza: vea archivos rechazados.

Adónde ir después

• Qué contiene un trace 10046: qué trae el archivo y qué datos lleva.
• Niveles del evento 10046: qué líneas graba cada nivel.
• Glosario: los términos del informe y del trace.