Trace for rookies

Recent event from some days ago when I meet one lady developer with Oracle certificate in Forms and reports, remind me how many developers do not know how is easy to find the cause of performance problems in their code. Result is of course...Oracle trace. Here are very short and easy explanation how to do that. This blog covers 10g and 11g versions and will focus to easiness as much as possible with minimal divergence to become a deeper tutorial. Tracing can be done in next five steps:

1. Find session to trace
2. Start trace
3. Find the trace file
4. Stop trace
5. Analyze trace file

1. Find session to trace

When you want to trace any session, you have to find two values that uniquely identified one session. sid and serial# Here is example how to find it from Oracle username:

col sid_serial for a11;
undefine ora_user;
select s.username,
       s.sid||','||s.serial# sid_serial,
       s.audsid,
       p.spid,
       to_char(s.logon_time, 'dd.mm.yyyy hh24:mi.hh') logon_time, 
       s.status 
from v$session s,
     v$process p
where s.username = '&ora_user'
  and s.paddr = p.addr;

If you have problems look in v$session and look what other data might identified more easy session you look for (MACHINE, PROGRAM or other columns).

2. Start trace

With sid and serial# from previous query, start trace:

EXECUTE DBMS_MONITOR.SESSION_TRACE_ENABLE(session_id => SID, serial_num => serial#, waits => TRUE, binds => TRUE);

If you are in sqlplus session you want to trace then it is even more easy:

ALTER SESSION SET sql_trace = true;

But I prefer previous version (do not want to explain because this is over the scope of this topic)!

3. Find the trace file

Trace file is always in user dump directory, which is on the server, where database (instance) is installed (I have avoided to use $ORACLE_HOME and all other terms in a case of easiness to all kind of user's level of knowledge). Keep in mind that the default name for a trace file is in form INSTANCE_PID_ora_TRACEID.trc where:

• INSTANCE is the name of the Oracle instance,
• PID is the operating system process ID (column from V$PROCESS.OSPID)
• TRACEID is a character string of your choosing.

With audsid from the first query find exact location and name of file that is created:

undefine audsid;
select 
  u_dump.value   || '/'     || 
  db_name.value  || '_ora_' || 
  v$process.spid || 
  nvl2(v$process.traceid,  '_' || v$process.traceid, null ) 
  || '.trc'  "Trace File"
from 
             v$parameter u_dump 
  cross join v$parameter db_name
  cross join v$process 
        join v$session 
          on v$process.addr = v$session.paddr
where 
 u_dump.name   = 'user_dump_dest' and 
 db_name.name  = 'instance_name'  and
 v$session.audsid=&audsid;

If you are in sqlplus session you want to trace then change last line (nr. 17) to:

v$session.audsid=sys_context('userenv','sessionid');  

On Windows server version there is a known bug with trace file name. Here is one example of output from previous query:

Enter value for audsid: 706927

Trace File
-------------------------------------------------------------
c:\oracle\product\diag\rdbms\xe\xe\trace/XE_ora_2316_SID.trc

1 row selected.

SQL> 

Look for name "trace/XE_ora_2316_SID.trc" and the way that "/" is instead of "\"! If you are using RAC then trace filename is a little bit different because we have instances instead of database name, which is in RAC not the same. Example (for instance nr. 4):

c:\oracle\product\diag\rdbms\xe\xe\trace/xe4_ora_2316_SID.trc

Now let us wait (run problematic part)....trace data are generating. Keep in mind that is absolutely normal that ".trc" files are several hundreds of MB in size!

4. Stop trace

When user is finished with problematic part of code, we have to close the trace:

EXECUTE DBMS_MONITOR.SESSION_TRACE_DISABLE (session_id => SID, serial_num => serial#);

Where sid and serial# are data from first query. If you are in sqlplus session where you started trace, then:

ALTER SESSION SET sql_trace = false;

User must end the session so trc file is dumped to disk. If user ends session (logout), trace will be automatically terminated and closed!

5. Analyze trace file

To analyze data from trace file, call oracle tkprof utility in a way (exactly):

tkprof 'trace file.trc' 'trace file.trc.ela' sys=no explain=username/pwd sort=exeela,prsela,fchela

where:

• "trace file.trc" is the file that was generated with trace (in our case XE_ora_2316_SID.trc)
• "trace file.trc.ela" is the name of analyzed file with tkprof-the result (in our case XE_ora_2316_SID.trc.ela)
• "username/pwd" are authentication data of user whose session was traced. If this is a problem ask DBA to explain how to overcome this problem.

This would be sufficient that you can see the problem. Here is an example of tkprofed (analyzed trace file) on famous "emp dept" tables:

SELECT * FROM emp, dept 
WHERE emp.deptno = dept.deptno;

call   count      cpu    elapsed     disk    query current    rows
---- -------  -------  --------- -------- -------- -------  ------
Parse      1     0.16      0.29         3       13       0       0
Execute    1     0.00      0.00         0        0       0       0
Fetch      1     0.03      0.26         2        2       4      14 

Misses in library cache during parse: 1 
Parsing user id: (8) SCOTT 

Rows     Execution Plan
-------  --------------------------------------------------- 

14  MERGE JOIN
 4   SORT JOIN
 4     TABLE ACCESS (FULL) OF 'DEPT'
14    SORT JOIN
14      TABLE ACCESS (FULL) OF 'EMP'

Reason is obvious ... or ? And that is all! Not so hard!?? ;-)

For the end

For full specification of tkprof use Oracle documentation. There might be others needed parameters that might be defined (i.e. MAX_DUMP_FILE_SIZE) but for that, ask your DBA for help! Cheers!