A collection of tutorials, code and tools to help you get better using Oracle
23 June 2011
SQL Trace is an incredibly powerful tool, and allows you to get all sorts of information about a single query, or set of queries. When it is enabled, it is like turning on SQL debug mode. In fact, over many years of development, the engineers at Oracle have carefully instrumented large parts of the Oracle code base with debug statements, and when SQL Trace is enabled, this debug information is made available to you via a trace file.
Each time Oracle does anything related to your query, it is logged in this trace file. Pretty much everything is logged there such as:
First you need to ensure that Timed Statistics are enabled in your session, or the trace file will be missing vital information:
SQL11G> ALTER SESSION SET timed_statistics=TRUE;
Next, for a very large SQL statement, there is a chance the default size limit of the trace file will be exceeded, and vital information about the query will be lost, so set the maximum size to unlimited:
SQL11G> ALTER SESSION SET max_dump_file_size=UNLIMITED;
Next, if you are on a busy system, it can be useful to add a unique identifier to your trace file to help find it later:
SQL11G> ALTER SESSION SET tracefile_identifier='unique_identifier';
Finally, turn on SQL Trace:
SQL11G> ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';
At this point, tracing is enabled for your session, so any SQL statements that you run will be traced. Try running any SQL query:
SQL11G> select * from test1
order by object_id;
When running this query, you may notice that there is no change, the query runs just the same as it always did and there is no indication tracing is enabled. However, be assured that the trace information is being recorded and written to a file - you just need to know where to look.
After tracing some relevant SQL, you should turn tracing off again, either by exiting SQLPLUS (or closing your session) or use the command:
SQL11G> ALTER SESSION SET EVENTS '10046 trace name context forever, level 1';
Sometimes you want to trace a session that is not your own, or that you cannot easily add the code above to enable trace. If you have sysdba access to the database, the easiest way to enable trace in another session is to use the oradebug command. First you need to identify the SPID of the process you want to trace:
select p.spid,s.sid,s.serial#,s.username,s.status,p.program
from V$process p,V$session s
where s.paddr = p.addr
Identifying the session you want may take some work, which is more than I want to talk about here. Once you have the SPID you want to trace, run the following three commands:
oradebug setospid <SPID found above>
oradebug unlimit
oradebug event 10046 trace name context forever, level 12
To turn tracing off again, simply run:
oradebug event 10046 trace name context forever, level 1
OK, so we have traced the SQL statement above, but where is the trace file? Well, it goes into userdumpdest of course. Obvious right? Well not really actually.
Upon start up, there are literally tons of parameters that control all sorts of settings about how Oracle works. For a developer, most of these settings are not important, but one such parameter is known as userdumpdest, and is the location trace files are written to. Finding this location is pretty easy (if you have the correct privileges on the database):
SQL11G> select name, value
from v$parameter
where name = 'user_dump_dest';
The value returned will be the location on the database server where trace files are written. If you get an error trying to access the v$parameter table, you probably don't have the required privileges, and will need to have a chat with your DBA.
If you look inside this directory, you should find a file that contains the unique identifier you specified above, which will be the file you are after.
Believe it or not, the contents of the trace file actually do make some sense, and it is possible decipher them. I have written Perl programs that extra information, but luckily that is rarely necessary. Below is an extract from the trace file generated earlier:
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /dboracle/product/11.2.0/dbhome_1
System name: Linux
Node name: home.appsintheopen.com
Release: 2.6.18-238.9.1.el5xen
Version: #1 SMP Tue Apr 12 18:53:56 EDT 2011
Machine: x86_64
Instance name: ora11gr2
Redo thread mounted by this instance: 1
Oracle process number: 25
Unix process pid: 30727, image: oracle@home.appsintheopen.com
*** 2011-06-23 20:32:54.940
*** SESSION ID:(50.2) 2011-06-23 20:32:54.940
*** CLIENT ID:() 2011-06-23 20:32:54.940
*** SERVICE NAME:(ora11gr2) 2011-06-23 20:32:54.940
*** MODULE NAME:(SQL*Plus) 2011-06-23 20:32:54.940
*** ACTION NAME:() 2011-06-23 20:32:54.940
WAIT #8: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857574939930
*** 2011-06-23 20:33:11.904
WAIT #8: nam='SQL*Net message from client' ela= 16964278 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857591904507
CLOSE #8:c=0,e=19,dep=0,type=1,tim=1308857591904604
*** 2011-06-23 20:33:11.947
=====================
PARSING IN CURSOR #12 len=51 dep=0 uid=32 oct=3 lid=32 tim=1308857591947353 hv=130287142 ad='65e0ca48' sqlid='dysy9ps3w81j6'
select * from test1
order by object_id
END OF STMT
PARSE #12:c=0,e=42705,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3586745170,tim=1308857591947350
EXEC #12:c=0,e=5473,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3586745170,tim=1308857591952914
WAIT #12: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857591952949
FETCH #12:c=0,e=119,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=3586745170,tim=1308857591953183
WAIT #12: nam='SQL*Net message from client' ela= 3763 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857591956989
WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857591957040
FETCH #12:c=0,e=42,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=3586745170,tim=1308857591957069
WAIT #12: nam='SQL*Net message from client' ela= 6744 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857591963836
WAIT #12: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857591963869
FETCH #12:c=0,e=35,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=3586745170,tim=1308857591963894
WAIT #12: nam='SQL*Net message from client' ela= 8821 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857591972738
WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857591972775
FETCH #12:c=0,e=35,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=3586745170,tim=1308857591972800
WAIT #12: nam='SQL*Net message from client' ela= 14300 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857591987123
WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857591987160
FETCH #12:c=0,e=36,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=3586745170,tim=1308857591987186
WAIT #12: nam='SQL*Net message from client' ela= 7150 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857591994359
WAIT #12: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857591994396
FETCH #12:c=0,e=36,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=3586745170,tim=1308857591994422
WAIT #12: nam='SQL*Net message from client' ela= 5636 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857592000081
WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857592000113
FETCH #12:c=0,e=38,p=0,cr=3,cu=0,mis=0,r=15,dep=0,og=1,plh=3586745170,tim=1308857592000142
WAIT #12: nam='SQL*Net message from client' ela= 5647 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857592005812
WAIT #12: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857592005850
FETCH #12:c=0,e=35,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=3586745170,tim=1308857592005875
WAIT #12: nam='SQL*Net message from client' ela= 5508 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857592011423
WAIT #12: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857592011456
FETCH #12:c=0,e=34,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=3586745170,tim=1308857592011480
WAIT #12: nam='SQL*Net message from client' ela= 12100 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857592023603
WAIT #12: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857592023640
FETCH #12:c=0,e=39,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=3586745170,tim=1308857592023669
WAIT #12: nam='SQL*Net message from client' ela= 6351 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857592030043
WAIT #12: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=13050 tim=1308857592030081
FETCH #12:c=0,e=35,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=3586745170,tim=1308857592030106
As you can see, it contains a lot of information, but making any sense of that information looks difficult to say the least.
Luckily, Oracle provides a tool that comes bundled with Oracle that can take a trace file, and produce a useful report with a single command.
From the UNIX command line enter the command (replacing the path names with the values relevant for your system):
$ tkprof /path/to/trace/file.trc /path/to/output/file.prf
The tkprof program will read the trace file and produce a nicely formatted report in the output file. If you have a look at the output, you will find the query you executed, along with some information about it, eg:
select * from test1
order by object_id
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.04 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 513 0.00 0.01 0 1135 0 7679
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 515 0.00 0.06 0 1135 0 7679
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 32
Rows Row Source Operation
------- ---------------------------------------------------
7679 TABLE ACCESS BY INDEX ROWID TEST1 (cr=1135 pr=0 pw=0 time=26157 us cost=117 size=660394 card=7679)
7679 INDEX FULL SCAN TEST1_UK1 (cr=529 pr=0 pw=0 time=9213 us cost=18 size=0 card=7679)(object id 13050)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 513 0.00 0.00
SQL*Net message from client 513 12.41 16.03
********************************************************************************
Often there will be many more SQL statements in the tkprof output which you did not run in your session. These are known as recursive SQL statements, and are statements which Oracle has to run behind the scenes to answer your query. Often these are due to parsing and dynamic stats gathering, which are not topics I want to explore here.
In the tkprof extract above, there are three main sections.
Useful stats on the query are listed first, and are very similar to those obtained through autotrace, with the useful addition of CPU consumed running the query.
In the tkprof output, the DISK column indicates how many blocks were read from disk, and is equivalent to PHYSICAL READS in the autotrace output.
The QUERY column is the number of logical I/O operations required to answer the query, which may have come from the buffer cache or disk. This is equivalent to the CONSISTENT GETS stat in autotrace.
The CURRENT column indicates the number of blocks gotten in current mode, and are usually required for updates.
The next section looks remarkably like an Explain Plan, and it basically is. The difference is that an Explain Plan is an educated guess of how Oracle will process a query, while the row source output is what actually happened. Almost always the two plans will be the same. The notable difference is that the row source operation contains the actual number of rows obtained at each stage of the query processing (as the "card" statistic) and the time spend processing each section, which can be useful.
The final section details the wait events which Oracle encountered when processing the query. In this example, there isn't much of interest, only some time spent waiting on "SQL*Net message from client", but on more complex queries all sorts of events will be logged here, such as time spend waiting on locks and reading from disk. This is generally the section to look at when attempting to troubleshoot a long running query, as it will give an indication of what it is spending time doing.
At the bottom of the trace file, some useful summary information is reported, such as cumulative wait events for all queries and the number of SQL queries included in the trace file.
The best way to learn about tracing and tkprof is to experiment with it on your development box. Try setting the tracing level to 12 instead of 8 to capture bind variables (at the expense of a much bigger trace file) and figure out the various command line options to tkprof that control sorting the SQL statements.
Once again for reference (and mainly easy cut and paste) the commands to enable tracing are:
ALTER SESSION SET timed_statistics=TRUE;
ALTER SESSION SET max_dump_file_size=UNLIMITED;
ALTER SESSION SET tracefile_identifier='unique_identifier';
ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';
<SQL STATEMENT HERE>
ALTER SESSION SET EVENTS '10046 trace name context forever, level 1';