Using SQL Trace in oracle

SQL Trace causes trace files to be produced by Oracle Database. Various items of interest are generated into trace files. This information comprises details of CPU and I/O needs plus parsing and execution information, processed rows, commits, and rollbacks. The output in trace files is more or less impossible to interpret by hand.

Setting up SQL Trace

SQL Trace can be configured for instance-level use or for a session, for a session either within a current open session or from one session to another. Setting instance-wide tracing can cause serious performance problems. It is better for performance to enable tracing only from a current session or for a specific session. Not using instance-wide tracing can miss a lot of useful information. I am using instance-level tracing since I am not working on a production server database. Start by setting the TIMED_STATISTICS, TIMED_OS_STATISTICS, and MAX_DUMP_FILE_SIZE parameters.

TIMED_STATISTICS = TRUE
TIMED_OS_STATISTICS = 5
MAX_DUMP_FILE_SIZE = 1M

The effect on performance of setting the TIMED_STATISTICS parameter is negligible. The parameters previously shown enable collection of statistics including CPU and I/O statistics. TIMED_STATISTICS writes information to both trace files plus the V$SYSSTATS and V$SESSSTATS performance views. TIMED_OS_STATISTICS is a timing mechanism for statistics collection, triggering system statistics collection periodically.

The MAX_DUMP_FILE_SIZE parameter will truncate each trace file in the USER_DUMP_DEST directory, the default target directory for trace files, usually the $ORACLE_BASE/admin/$ORACLE_SID/ udump directory.

Next set the SQL_TRACE parameter to switch on SQL Trace. The TRACE_ENABLED parameter could also be set to TRUE but we will avoid that. Setting TRACE_ENABLED tends to produce copious amounts of detail, more relevant to Oracle support personnel than anything else.

SQL_TRACE = TRUE

Trace files contain generated statistics. In past versions of Oracle trace levels could be set. Oracle9i Database has a new parameter called STATISTICS_LEVEL which can be set to BASIC, TYPICAL, or ALL. The default is TYPICAL. Setting ALL would incur significant overhead and a noticeable effect on performance. In my database I will set the STATISTICS_LEVEL parameter to ALL to gather as much information as possible. Note that setting this parameter to ALL automatically sets the TIMED_OS_STATISTICS parameter to 5.

STATISTICS_LEVEL = ALL

Session-Level Tracing

Specific sessions can be traced. Tracing at the session level can help to remove tracing overhead from the database in general and focus on a specific session. Personally I have never seen the value in using the session level of tracing. There is far too much information produced. There are easier ways of tracking down problems than using session-level tracing. This command traces the current session. Tracing a specific session may be most applicable to tracking down some really nasty SQL code such as in a pre-release application, or one which should not have been released, or perhaps in an ad hoc SQL environment.

ALTER SESSION SET SQL_TRACE = TRUE;

This command will trace a session other than the current session, someone else’s session.

DBMS_SYSTEM_SET_SQL_TRACE_IN SESSION(SID, SERIAL#, TRUE);

Finding Trace Files

One of the biggest problems with trace files is finding them. Many files can be generated. You could find the files applicable to specific processes by including tags in your SQL code such as SELECT ‘my trace file’ FROM DUAL; or by checking datestamps in the operating system. Typically a trace file is named in the following format:

$ORACLE_SID_ora_<pid>.trc

“pid” represents the process ID of the process which generated the trace file. The process ID can be found with the following query, which finds the process identifier using the process and session addresses and the session auditing identifier as the session identifier.

SELECT spid FROM v$process
WHERE addr = (SELECT paddr FROM v$session
      WHERE audsid = USERENV('sessionid'));

Using SQL Trace

So the next logical step is to make use of SQL Trace. I have now set up my Oracle Database configuration parameter file (init.ora) with various parameter changes.

TIMED_STATISTICS = TRUE
TIMED_OS_STATISTICS=5
MAX_DUMP_FILE_SIZE = 1M
SQL_TRACE = TRUE
STATISTICS_LEVEL = ALL
Now I bounce my database to instantiate these configuration parameter changes.

Tip Some of these parameters can be updated online using the ALTER SYSTEM command.

The next step is starting up my highly active concurrent database scripting (see Appendix B). These scripts use the DBMS_JOBS package to repetitively execute a slew of database changes to my Accounts schema, from multiple concurrently executed database jobs using the DBMS_JOBS package. Since I am running sessions using the DBMS_JOBS package I have to be able to find trace files for each session. So let’s change the process identifier query to access multiple sessions, and find a trace file that way. So how do I find the appropriate sessions? Log into a database administrator user such as SYSTEM and execute a query something like this.

SELECT audsid, username, saddr, paddr, sid, serial#
FROM v$session WHERE username = ‘ACCOUNTS’ AND audsid != 0;
Then I change my process identifier finding query and find a filename.

SELECT ‘c:\oracle\admin\test\udump\test_ora_’||spid||’.trc’
“Trace File”
FROM v$process
WHERE addr = (
SELECT paddr FROM V$SESSION
WHERE username = ‘ACCOUNTS’ AND audsid != 0);
Trace File
—————————————————
c:\oracle\admin\test\udump\test_ora_972.trc

Trace files can look like the gibberish shown below. Not really very easy to interpret is it? Yes that is sarcastic; certainly the very lowest form of wit but apt in this case. This is where TKPROF comes into play.

======================
PARSING IN CURSOR #3 len=56 dep=1 uid=0 oct=3 lid=0
tim=13822711723 hv=4049165760 ad=’67f67898′
select order#,columns,types from access$ where d_obj#=:1
END OF STMT
PARSE #3:c=0,e=145,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,
tim=13822711703
EXEC #3:c=0,e=136,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,
tim=13822714183
FETCH #3:c=0,e=114,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,
tim=13822714826
FETCH #3:c=0,e=78,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,
tim=13822715459
FETCH #3:c=0,e=67,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,
tim=13822716065
FETCH #3:c=0,e=64,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,
tim=13822716662
FETCH #3:c=0,e=65,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,
tim=13822717260
FETCH #3:c=0,e=42,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,
tim=13822717850
STAT #3 id=1 cnt=5 pid=0 pos=1 obj=97 op=’TABLE ACCESS BY
INDEX ROWID ACCESS$ ‘
STAT #3 id=2 cnt=5 pid=1 pos=1 obj=129 op=’INDEX RANGE
SCAN I_ACCESS1 ‘

Written by admin on December 29th, 2010 with comments disabled.
Read more articles on Oracle Tuning.

Related articles

Comments disabled

Comments on this article have been disabled.