Monday, July 04, 2005

Trace it!

I often give people the advice to trace their SQL session to see what is going on. Knowing how to trace is one of the tools that every developer and DBA should have in their toolbox.

By tracing, I mean capturing all the SQL in a user's session, or a SQL trace. As you can tell from the Oracle Performance Tuning Guide and Reference, there are many ways to enable tracing. Below are two methods I use as a DBA in my day-to-day routine.

Turn tracing on

Enabling tracing in your own session is very easy. From SQL*Plus, just alter your session and set sql_trace=true.
SQL> alter session set sql_trace=true;

Session altered.

Dude, you're tracing. Every query you run from now on will go into a trace file until you set sql_trace to false.

Sometimes, a session is already underway and you need to start a trace midway through it's execution. Here, you need to be a DBA and enable the 10046 event in the user's session. This is a little more tricky since you have to know the sid and serial# from v$session in order to enable the tracing. For example,

SQL> select sid, serial#, username
2 from v$session
3 where username = 'JEFFH';

---------- ---------- ------------------------------
25 5 JEFFH

SQL> exec sys.dbms_system.set_ev(25, 5, 10046,8,'');

PL/SQL procedure successfully completed.

Statements get written to the trace file when they are first encountered after the trace is started. The statement that is executing may not be in the final trace file.

If you are using dedicated servers, the trace file will typically be in the directory on the server specified by the user_dump_dest parameter in the init.ora file. If you are using shared servers, the trace file will be in the directory specified by background_dump_dest. The trace file will have your server process id in it somewhere. If you are running the trace on your own session, you can create a stub with the ALTER SESSION SET TRACEFILE_IDENTIFIER=xxx; This way, your file will have the "xxx" name in it and be easier to identify.

What do I do with it?

OK, so you got this big file. It's just a simple ASCII file, go ahead and read it.

Nah, just kidding. Oracle gives you this program called TKProf that reads your trace file and spits out somewhat meaningful output. (I think Oracle uses tkprof as an acronym for Tom Kyte, Professor, but that's just speculation on my part.) My favorite option to tkprof is sort=prsela,fchela,exeela. This sorts the statements from longest running to shortest running. I prefer this format because I can concentrate on the top two or three statements for the most impact.

SQL> alter session set sql_trace=true;

Session altered.

SQL> alter session set tracefile_identifier='mytest';

Session altered.

SQL> select count(*) from xyz_master;


SQL> select count(*) from xyz_detail;


SQL> exit

D:\oracle\product\admin\xp10\udump>dir *mytest*
Volume in drive D has no label.
Volume Serial Number is 70AE-6E52

Directory of D:\oracle\product\admin\xp10\udump

07/04/2005 08:11 PM 38,785 xp10_ora_1544_mytest.trc
1 File(s) 38,785 bytes
0 Dir(s) 14,751,383,552 bytes free

D:\oracle\product\admin\xp10\udump>tkprof xp10_ora_1544_mytest.trc foo.out sort=prsela,exeela,fchela

TKPROF: Release - Production on Mon Jul 4 20:16:53 2005

Copyright (c) 1982, 2004, Oracle. All rights reserved.

D:\oracle\product\admin\xp10\udump>dir /od foo.out
Volume in drive D has no label.
Volume Serial Number is 70AE-6E52

Directory of D:\oracle\product\admin\xp10\udump

07/04/2005 08:16 PM 21,368 foo.out
1 File(s) 21,368 bytes
0 Dir(s) 14,751,358,976 bytes free


Things you will want to know about tracing

  • The timed_statistics init.ora parameter must be set to true in order to get any meaningful timing data out of tkprof.

  • I prefer to set the max_dump_file_size init.ora parameter to either unlimited or a really large value (2G). If you're going through the extra work of tracing a process you don't want to potentially miss the most important part.

For more details
Pete Finnigan


Tim... said...

Nice one.

I've consolidated all the methods I know, including the 10g variations, into this article:

I think my article is a little on the confusing side because it has too many variations.

Yours hits the nail on the head.



Robert Vollman said...

Someone's been reading Cary Millsap's book. :)

Niall said...

not a nice article at all. now no-one will come to my session on setting trace and what to do with the output at UKOUG :(

I always recommend Pete Finnigan's article by the way.

at least Microsoft stick to 3 ways to do anything.

Tim... said...


Wow. I thought my article was overkill. The one by Pete F makes mine look brief :)

I'll put a link to it on the bottom of the article.



Jeff Hunter said...

Someone's been reading Cary Millsap's book.
Oh yeah, been there, done that.

Jeff Hunter said...

Niall said...
That reference was so good, I added it to the end of the post.

Anonymous said...

which provides as easy way to enable or disable tracng for your session or any other session; including enabling data collection for WAITs & BIND variable values.

Rahul said...


I just came across this post and I noticed this statement.

>>(I think Oracle uses tkprof as an acronym for Tom Kyte, Professor, but that's just speculation on my part.)

I think it is acronym for Transient Kernel PROFile. I could be wrong though.