Reading a session trace file (basics)

Here is a very basic overview of tracing one statement and reading the raw trace file.


Set the tracefile_identifier so i can find my trace file

SQL> alter session set tracefile_identifier = 'TIM_TRACE';

Now turn tracing on and run one query.

SQL> exec dbms_monitor.session_trace_enable(binds=>true,waits=>true); PL/SQL procedure successfully completed. SQL> select object_name from dba_objects where owner = 'TIM'; OBJECT_NAME -------------------------- CRASH_TEST_DUMMY TRACE_TEST SQL> exec dbms_monitor.session_trace_disable; PL/SQL procedure successfully completed.

Now looking in the background dump dest for TIMTRACE, I can identify my file. And pull out the section for my statement above

===================== PARSING IN CURSOR #140511204450784 len=54 dep=0 uid=90 oct=3 lid=90 tim=1383537697662638 hv=3541327511 ad='a09cf038' sqlid='ag1zhvg9j8rnr' select object_name from TRACE_TEST where owner = 'TIM' END OF STMT PARSE #140511204450784:c=87987,e=269556,p=256,cr=61,cu=0,mis=1,r=0,dep=0,og=1,plh=1558085358,tim=1383537697662627 EXEC #140511204450784:c=0,e=198,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1558085358,tim=1383537697663343 WAIT #140511204450784: nam='SQL*Net message to client' ela= 15 driver id=1650815232 #bytes=1 p3=0 obj#=75809 tim=1383537697663605 WAIT #140511204450784: nam='reliable message' ela= 79923 channel context=2837622280 channel handle=2745660032 broadcast message=2838745232 obj#=75809 tim=1383537697746290 WAIT #140511204450784: nam='enq: KO - fast object checkpoint' ela= 3381 name|mode=1263468550 2=65583 0=1 obj#=75809 tim=1383537697750142 WAIT #140511204450784: nam='enq: KO - fast object checkpoint' ela= 1787 name|mode=1263468545 2=65583 0=2 obj#=75809 tim=1383537697752495 WAIT #140511204450784: nam='direct path read' ela= 893 file number=4 first dba=179 block cnt=13 obj#=75809 tim=1383537697755183 WAIT #140511204450784: nam='direct path read' ela= 458 file number=4 first dba=209 block cnt=15 obj#=75809 tim=1383537697756192 WAIT #140511204450784: nam='direct path read' ela= 992 file number=4 first dba=241 block cnt=15 obj#=75809 tim=1383537697757893 WAIT #140511204450784: nam='direct path read' ela= 540 file number=4 first dba=273 block cnt=15 obj#=75809 tim=1383537697759098 WAIT #140511204450784: nam='direct path read' ela= 3427 file number=4 first dba=386 block cnt=126 obj#=75809 tim=1383537697764691 WAIT #140511204450784: nam='direct path read' ela= 60384 file number=4 first dba=514 block cnt=126 obj#=75809 tim=1383537697830042 WAIT #140511204450784: nam='direct path read' ela= 3145 file number=4 first dba=770 block cnt=126 obj#=75809 tim=1383537697836654 WAIT #140511204450784: nam='direct path read' ela= 2725 file number=4 first dba=1026 block cnt=126 obj#=75809 tim=1383537697841392 WAIT #140511204450784: nam='direct path read' ela= 13589 file number=4 first dba=1154 block cnt=126 obj#=75809 tim=1383537697856350 FETCH #140511204450784:c=26996,e=194010,p=1063,cr=1065,cu=0,mis=0,r=1,dep=0,og=1,plh=1558085358,tim=1383537697857712 WAIT #140511204450784: nam='SQL*Net message from client' ela= 679 driver id=1650815232 #bytes=1 p3=0 obj#=75809 tim=1383537697858903 WAIT #140511204450784: nam='SQL*Net message to client' ela= 11 driver id=1650815232 #bytes=1 p3=0 obj#=75809 tim=1383537697859423 FETCH #140511204450784:c=0,e=193,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=1558085358,tim=1383537697859536 STAT #140511204450784 id=1 cnt=2 pid=0 pos=1 obj=75809 op='TABLE ACCESS FULL TRACE_TEST (cr=1067 pr=1063 pw=0 time=193973 us cost=298 size=996 card=12)' *** 2013-11-03 23:01:50.402 WAIT #140511204450784: nam='SQL*Net message from client' ela= 12542836 driver id=1650815232 #bytes=1 p3=0 obj#=75809 tim=1383537710402597 CLOSE #140511204450784:c=0,e=46,dep=0,type=0,tim=1383537710403196

Now I will attempt to interpret a few of the lines, from what i know ... i am just a humble dba.

Durations in trace files are represented in mircoseconds (divide by 1,000,000 to get seconds).
The Oracle kernel writes to the trace file each time an action or call completes.

PARSE IN CURSOR;

#140511204450784 - The call cursor handle id.
len=54 - the character length of the cursor.
dep=0 - levels of database calls for this cursor, 0 meaning it is a parent call, > 0 meaning it is a child of another call.
uid=90 - User id of the session running the query.
oct=3 - Oracle command type (a query i guess)
lid=90 - Privileged user id.
tim=1383537697662638 - time the cursor started
hv=3541327511 - hash_value of the statement (v$sql_hash_value)
ad='a09cf038' - sql address of the cursor (v$sql.address)
sqlid='ag1zhvg9j8rnr' - SQL_ID of the statement.



PARSE (parsing the statement)

#140511204450784 - the cursor handle id.
c=87987 - consumed CPU time of the parse in micro seconds
e=269556 - consumed elapsed time in micro seconds
p=256 - Oracle blocks obtained via os read calls
cr=61 - consistent mode reads in at the buffer cache
cu=0 - current mode reads in the buffer cache
mis=1 - Misses in the library cache
r=0 - rows returns
dep=0 - levels of db calls for this cursor, 0 meaning it is a parent call, > 0 meaning it is a child of another call.
og=1 - optimizer goal
plh=1558085358 - plan hash value
tim=1383537697662627 - call completed time.


EXEC (executing the statement)

#140511204450784 - the cursor handle id.
c=0 - consumed CPU time of the parse in micro seconds
e=198 - consumed elapsed time in micro seconds
p=0 - Oracle blocks obtained via os read calls
cr=0 - consistent mode reads in the buffer cache
cu=0 - current mode reads in the buffer cache
mis=0 - Misses in the library cache
r=0 - rows returns
dep=0 - levels of db calls for this cursor, 0 meaning it is a parent call, > 0 meaning it is a child of another call.
og=1 - optimizer goal
plh=1558085358 - plan hash value
tim=1383537697663343 - call completed time.

WAIT (OS calls)

There are a few lines of wait calls, I will try to interpret using one of the 'direct path read' waits.
The wait calls are associated with the following fetch call.

#140511204450784 - the cursor handle id.
nam='direct path read' - name of the wait event
ela= 893 - consumed elapsed time in micro seconds
file number=4 - file id in the database (v$datafile.file#)
first dba=179 - ???
block cnt=13 - ???
obj#=75809 - Oracle object id (dba_objects.object_id)
tim=1383537697755183

FETCH (Fetching the rows)

First fetch;
#140511204450784 - the cursor handle id.
c=26996 - consumed CPU time of the parse in micro seconds
e=194010 - consumed elapsed time in micro seconds
p=1063 - Oracle blocks obtained via OS read calls
cr=1065 -  - consistent mode reads in the buffer cache
cu=0 - current mode reads in the buffer cache
mis=0 - Misses in the library cache
r=1 - rows returns
dep=0 - levels of db calls for this cursor, 0 meaning it is a parent call, > 0 meaning it is a child of another call.
og=1 - optimizer goal
plh=1558085358 - plan hash value
tim=1383537697857712 - call completed time.

Second fetch;
#140511204450784 - the cursor handle id.
c=0 - consumed CPU time of the parse in micro seconds
e=193 - consumed elapsed time in micro seconds
p=0 - Oracle blocks obtained via OS read calls
cr=2 -  - consistent mode reads in the buffer cache
cu=0 - current mode reads in the buffer cache
mis=0 - Misses in the library cache
r=1 - rows returns
dep=0 - levels of db calls for this cursor, 0 meaning it is a parent call, > 0 meaning it is a child of another call.
og=1 - optimizer goal
plh=1558085358 - plan hash value
tim=1383537697857712 - call completed time.


******************************************
keywords: trace
******************************************
rdbms version: 11g
******************************************