10046 trace lines that WaitScope reads

The 10046 trace is a text file: each line starts with its type (PARSE, WAIT, STAT...) and goes on with fields in the name=value format. This page lists the lines WaitScope reads, the fields it uses and where each one appears in the report. The examples come from the synthetic sample trace, the same one behind the sample report.

A short trace

In the synthetic trace, a level-0 SELECT fires a recursive query against the data dictionary and then waits for the application:

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

The total time of this trace is 7,010 microseconds: from the start of the first PARSE (tim 1000100 minus e 100) to the tim of the XCTEND.

Time unit

From Oracle 9i on, the trace times (c, e, ela and tim) are in microseconds. In Oracle 7 and 8 traces, they are in centiseconds. WaitScope recognizes an old trace by the database version in the header and converts everything to microseconds. The summary shows the unit in Time unit: microseconds or centiseconds (old trace).

The tim is the moment the call or the wait ended. The start is tim minus e, or minus ela. In an old trace, a wait may come without tim: then the split between waits within and between calls uses the event name, and the report warns about it.

Header and lines with ***

These fields go to the Session and environment card of the summary, unmasked: see Summary.

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

Carries the SQL text of the cursor, on the following lines, up to END OF STMT. From then on, the lines with the same cursor number (#1) belong to that statement, until the cursor gets another text.

PARSE, EXEC, FETCH and 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

One line per database call, with the cursor number after #. The same rules apply to UNMAP, SORT UNMAP and the LOB calls (LOBREAD:, LOBWRITE: and the others), which enter Call types by name. A call without tim is left out.

The CPU, the waits and the recursive calls that end within a call count toward it. Whatever is left of the duration becomes unaccounted-for time within calls.

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

One line per wait. The parameters after ela= change with the event. In recent traces, they come with names (file#, block#, driver id); in old ones, as p1, p2 and p3.

A wait that ends within a call counts toward that call. A wait between the end of one level-0 call and the start of the next is a wait between calls, like the SQL*Net message from client in the example.

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

One line per operation of the cursor's plan. Each recorded plan becomes an Execution plan block in the statement detail. When the same plan is recorded more than once, the report shows the last one.

See Execution plan to read these columns in the statement detail.

BINDS

BINDS #2:
 Bind#0
  value=1

Bind values appear at levels 4 and 12 of the 10046, or with binds => TRUE in DBMS_MONITOR. WaitScope recognizes the BINDS line and ignores the whole block: the values do not enter the report. Even so, prefer to generate the trace without them (bind values).

XCTEND

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

The end of a transaction. rlbk=0 is a commit and rlbk=1 is a rollback: the summary counts both, as “N commits · N rollbacks”. The tim enters the total time and the period; rd_only is not used.

ERROR and 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 records an ORA- error in a call of the cursor: WaitScope reads the code (err=) and ties it to the previous call of the same cursor. PARSE ERROR records an error at parse time, with the SQL text on the following lines. Both go to the Errors section, with the code, how many times it appeared and where. The trace keeps only the code: the full message text stays with whoever received the error. See Errors.

Deadlock block

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

When the session receives ORA-00060, Oracle writes to its trace the block that starts at DEADLOCK DETECTED. WaitScope reads the graph (Deadlock graph:), the rows waited on (Rows waited on:), the other sessions involved, the SQL of the session that received the error and the PL/SQL stack (PL/SQL Call Stack). The block counts both in a deadlock-only trace and inside a 10046. See deadlock trace and Deadlocks.

TRACE CONTINUES IN FILE

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

When the application changes tracefile_identifier, Oracle closes the segment with *** TRACE CONTINUES IN FILE and goes on in another file, which starts with *** TRACE CONTINUED FROM FILE. When a single file is analyzed, these lines change nothing. In a collection, WaitScope cuts each file at these points and joins the segments of the same session in tim order: see analyze several traces together.

Ignored lines

• The bind values, in the BINDS block.
• The separator lines (=====================).
• Any line that is not one of the types on this page.

A file with no 10046 line and no deadlock block is rejected: see rejected files.

Where to go next

• What a 10046 trace contains: what the file holds and what data it carries.
• Event 10046 levels: which lines each level writes.
• Glossary: the terms of the report and of the trace.