Guys ! as a software engineer you need to know how to work round the clock and also to be idle for weeks, even months. Though I have experienced the former for most part of my career, last couple of months I was bound to undergo the second and most boring phase. Fortunately, I have identified this within a couple of days and also figured out a possible remedy for this monotonous phase I was heading towards. That is my friends… “Installation and configuration of Metasolv” . I have to agree that it was really challenging to install M6 from scratch. Amid my new learning, the notable one is Trace files in Oracle. Despite the trace option in Metasolv, I had to avail Oracle trace option to troubleshoot some privilege issue.
Trace is a feature in oracle which enables you to log minute details of a session. Enabling trace for a session will make oracle to log the session details in a file called trace file with extension “.trc”. A proper naming convention has been followed by oracle for these trace files.
“DB_NAME”_ORA_”SID”.trc |
Example: mssdev_ora_2308.trc
Enabling trace
Trace can be enabled session wise. We can enable session using a simple alter statement from a particular session or using DBMS_SUPPORT package provided by oracle.
- ALTER SYSTEM SET trace_enabled = TRUE; for enabling trace.
- ALTER SYSTEM SET trace_enabled = FALSE;for disabling trace.
If you would like to enable trace for another session apart from your current session, you can use DBMS_SUPPORT package.
SQL> desc dbms_support
Element Type
---------------------- ---------
PACKAGE_VERSION FUNCTION
MYSID FUNCTION
START_TRACE PROCEDURE
STOP_TRACE PROCEDURE
START_TRACE_IN_SESSION PROCEDURE
STOP_TRACE_IN_SESSION ROCEDURE
Last two procedures described above are used for starting and stopping tracing for any session that currently exists in the database. Lets see a method for enabling trace for all active sessions for a particular user using a simple BEGIN-END block.
BEGIN
for c in (select s.sid sid,
s.serial# serial
from v$session s
where s.USERNAME = 'ASAP' and
s.status = ’ACTIVE’)
loop
dbms_support.start_trace_in_session(c.sid, c.serial);
end loop;
END;
Use dbms_support.stop_trace_in_session (c.sid,c.serial); for stopping the tracing. Trace file provides each and every details of the session. A sample trace file will be like this.
=====================================================================
Dump file c:\oracle\admin\mssdev\udump\mssdev_ora_2308.trc
Wed Feb 18 13:01:42 2009
ORACLE V9.2.0.1.0 - Production vsnsta=0
vsnsql=12 vsnxtr=3
Windows 2000 Version 5.1 Service Pack 2, CPU type 586
Oracle9i Enterprise Edition Release 9.2.0.1.0 - Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.1.0 - Production
Windows 2000 Version 5.1 Service Pack 2, CPU type 586
Instance name: mssdevRedo thread mounted by this instance: 1
Oracle process number: 15
Windows thread id: 2308, image: ORACLE.EXE
*** 2009-02-18 13:01:42.000
*** SESSION ID:(9.23) 2009-02-18 13:01:42.000PARSING IN CURSOR #2 len=79 dep=0 uid=73 oct=3 lid=73 tim=259898785365 hv=4060294543 ad='1cd62f00'
SELECT global_name FROM global_name
END OF STMT
PARSE #8:c=15625,e=17422,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=4,tim=2592960232
BINDS #8:
EXEC #8:c=0,e=1358,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=2592968343
WAIT #8: nam='SQL*Net message to client' ela= 3 p1=1952673792 p2=1 p3=0
WAIT #8: nam='SQL*Net message from client' ela= 3338 p1=1952673792 p2=1 p3=0
WAIT #8: nam='SQL*Net message to client' ela= 1 p1=1952673792 p2=1 p3=0
FETCH #8:c=0,e=1422,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=4,tim=2592977265
WAIT #8: nam='SQL*Net message from client' ela= 36895 p1=1952673792 p2=1 p3=0
=====================================================================
Every line in the trace file has statistics embedded in it, we have to decipher the trace file to understand the details of the session. For example PARSE line shows, the length of the cursor (len=79), the user id of the person parsing the cursor (uid=73), the time the parse began (tim=) and the SQL address of the cursor (ad=). As you will see shortly, we can reference the ad= line to v$sqlarea and get the text of this cursor.
Some commonly used variable in the trace file are
C= cpu time, e=elapsed time, p=number of database blocks read, cr=number of consistent mode blocks read. cu=number of current mode blocks read, mis=number of library cache misses, r=number of rows, og=optimizer goal (1=all_rows, 2=first_rows, 3=rule and 4=choose)
It shows values of these variables for each each section like parsing, binding with variable values, executing, waiting and fetching the records. Reading this file would gives us the understanding of
- Client used for execution
- Time and resource involved in executing the query
- Number of rows fetched along with optimizer goal
You can read more on Output format of Trace file.
2 comments:
The post looks interesting. So, finding enough time at last.
nice article.
I read the other link you mentioned and i noticed this statment.
"If there are TIMESTAMPS in the file you can use the difference between 'tim' values to determine an absolute time."
This is what i am trying to achieve..basically the absolute times between all the query's shown in the trace. Would you know what query or technique I could use extract that output?
thanks!
Post a Comment