Introduction

This paper is about performance tuning, and in particular about getting information on not just which SQL statements are using the most resource within an application mix, but which steps within those SQL statements are amenable to improvement. In addition to considering the available data sources, and how easy they are both to enable and to interrogate, tuners are usually acutely aware of the need not to place additional loads on any production application that is under study. For this reason this paper presents a number of sets of measurements performed on the author's development work station, which also doubles as his laptop.

All of the measurements reported in this paper were made on a Compaq Armada M700 with 448Mb of memory and a single 20Gb hard disk running Oracle9i Release 2 Enterprise Edition under Microsoft Windows/2000 Professional with Service Pack 1 installed. The processor was an 833MHz Pentium III, and the database was a slightly customized configuration of the "general purpose" starter database optionally created by the Oracle Installer.

When running performance tests care was taken to avoid any extraneous load and also to ensure that the memory charge did not exceed the physical memory available. However, to avoid the need to take network considerations into account the client "application" was, in every case, also running on the same platform as the database.

The SQL_TRACE Mechanism

The Basics

Since the early days of Oracle Version 6 the dataserver has had a facility that allows each session to write to a dedicated serial file details of each Parse, Execute or Fetch call that it has processed. A little care is required here as the "calls" reported by sql_trace do not map in any consistent manner to the number of calls passed between the client application and the database server program. Because of the mechanisms used under Oracle to minimize the number of network round-trips it is important not to try to reconcile the number of calls reported in a trace file with the number of network calls observed from the client. It may also be worth noting that older versions of Oracle's client libraries may use any number of additional network calls in order, for example, to bind data values to a SQL statement before execution.

File Contents

There are a large number of undocumented optional data items that can be written to trace files under specific circumstances but the basic facility simply records each SQL statement that has been assigned to a "cursor" and then records the resources used by each Parse, Execute and Fetch operation against that cursor. The resources are not reported in great detail, and the key attributes are the elapsed and CPU time of the call (in microseconds), the number of database blocks requested from the buffer pool, the number of physical disk reads and the total number of rows processed. A short extract from a trace file is presented below so that you can get the general idea of the structure.

PARSING IN CURSOR #2 len=89 dep=0 uid=64 oct=6 lid=64 tim=210428125008 hv=2185651036 ad='667b3e98'
         update RUNS
            set CONNECTS = nvl(CONNECTS, 0) + 1
          where RUN_ID = :p1
END OF STMT
PARSE #2:c=0,e=218,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,Tim=210428124993
EXEC #2:c=0,e=487,p=0,cr=1,cu=2,mis=0,r=1,dep=0,og=4,Tim=210428127311
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='UPDATE '
STAT #2 id=2 cnt=1 pid=1 POs=1 obj=31186 op='INDEX UNIQUE SCAN RUNS_PK          '
XCTEND rlbk=0, rd_only=0

This extract is a relatively simple case in that no fetch was required (the cursor is an update rather than a query) and the execute call immediately followed the parse call. In the real world an application may have several hundred "cursors" parsed (ready for use) and calls to these cursors are interleaved.

The lines starting STAT give details on each step in the execution plan for the statement, and cnt gives the number of rows processed by that step.

Lastly, the entry XCTEND signals transaction end, in this case a commit. Although both commit and rollback are SQL statements in Oracle, they are also supported as direct calls and almost all applications issue them by direct call rather than through SQL statements.

Fortunately Oracle provide a command line utility, tkprof, to report the contents of these files.

Enabling SQL_TRACE

The facility can be enabled at the instance level by setting SQL_trace = true in an init.ora file (though these are obsolete in Oracle9i) or through the SQL statement

alter system set SQL_trace = true scope = [memory | spfile | both];

However, doing this means that every session will have to write to a serial file on every call until the feature is switched off.

It is generally preferred to set tracing on and off at session level using either the SQL statement

alter session set SQL_trace = true;

or, inside PL/SQL, the packaged procedure call

dbms_session.set_SQL_trace(true);

Unfortunately, very few applications give users the option of switching trace on and off programmatically and indeed some package suppliers are very much against their customers' using tracing, regarding it as a form of reverse engineering. Thus at first sight there is no convenient way of getting a trace file from a problem session without enabling trace at the instance level. However, this was a supported feature of Oracle Version 7.3 and the syntax documented with that release still works if issued by SYS. So provided that you can connect with enough privilege, and can locate in V$SESSION the session that you need to trace, the solution is to call

DBMS_system.set_SQL_trace_in_session(sid, serial#, true);

Now if a user tells you that performance is a problem, you can produce a trace file from their session from that point onwards in the hope that that performance problem will repeat itself and that you will be able to diagnose the cause from the diagnostic data.

Relevant System Parameters

A number of system parameters have a potential effect on trace file writing. Three are especially important, and are discussed in turn below.

max_dump_file_size

A session that is working hard issuing efficient queries can generate 1 Mb of trace per second; even though this is far from typical, it shows the need for a parameter to limit the size of each individual file.

timed_statistics

At various times Oracle has found that requesting values from a high-precision clock has caused an undue CPU overhead on a particular platform, and in these environments this parameter had the default value of false. As far as the author is aware these problems are not present in current operating system versions and this parameter should always be true although on many platforms timing will be performed whatever the setting.

user_dump_dest

Specifies the directory or folder to which all session-level trace files will be written. If you ever expect to have multiple trace files being written in parallel, it is well worth making sure that this directory is on a heavily buffered logical device spread over multiple physical drives. If you are confident that your instance will only ever be tracing a single session, then the directory can be on any relatively lightly loaded device. As an aside, if you enable tracing, then trace files will be written. If the specified destination is on a non-existent device, then (under MS-Windows) Oracle will simply create a default directory under %ORACLE_HOME%\admin\%ORACLE_SID%\udump. You have been warned!

Reporting

Oracle provides the command line utility tkprof to generate plain text reports from the files produced by SQL_trace, and although the output is plain text the program does an entirely adequate job for most purposes. Its greatest weaknesses are encountered when processing trace files from transaction processing applications that do not use bind variables and which have been run under instances in which cursor_sharing = exact. Under these circumstances a trace file can contain many thousand statements that although lexically different are in fact the same statement, and tkprof will not aggregate them. With some justification the program regards

select ENAME from EMP where EMPNO = 22

as a different statement from

select ENAME from EMP where EMPNO = 23
RUNNING tkprof

The command format is

tkprof inputfile outputfile options

The program aggregates the statistics from all of the executions of each SQL statement and produces a simple summary report for each statement. The default order is the sequence in which the statements were first parsed., and each is presented in the form shown below.

********************************************************************************
select STOPPED_AT 
from
RUNS where RUN_ID =   :R

call    count  cpu      elapsed    disk       query      current    rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse   73     0.01     0.00       0          0          0          0
Execute 73     0.00     0.00       0          0          0          0
Fetch   73     0.00     0.00       0          146        0          73
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total   219    0.01     0.02       0          146        0          73
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 64     (recursive depth: 1)
Rows    Row Source Operation
------- ---------------------------------------------------
      1 TABLE ACCESS BY INDEX ROWID RUNS 
      1 INDEX UNIQUE SCAN RUNS (object id 31084)
********************************************************************************

In tkprof's original incarnation the command line option explain=connectstring was an important feature, allowing the user to see the output from an explain plan of each SQL statement. Unfortunately there are a large number of possible reasons why explain plan output may differ from the plan actually used; a full analysis is outside the scope of this paper, but one known cause is that the session that issued the SQL and session started by tkprof had different settings for an optimizer parameter such as optimizer_index_caching. As the real execution plan is now available in the trace file, there now seems little reason for using the explain option.

As an aside, if you are interested in exploring further why apparently identical SQL statements may generate different execution plans the column names in the Oracle9i view V$SQL_SHARED_CURSOR may be of some interest.

The option sys=no is generally recommended as it suppresses all the SQL statements that Oracle has decided to issue to itself, typically for space allocation and to load object definitions into the row cache in order to support statement parsing. In an advanced tuning paper we might discuss the ways in which a tuner could try to reduce the amount of recursive SQL, but we would also have to cover the many reasons why it may be benign (because, for example, the trace file was generated from an instance that had only recently been restarted).

A feature-rich application may issue well over 1,000 distinct SQL statements in a single run, and we can use tkprof's sort and print options to limit the output to those SQL statements using the greatest amount of resource. My current favorite is sort=(exeela, fchela) print=10 or "the top SQL ten statements by elapsed time for execute and fetch."

Resource Implications

DBA's have traditionally been unwilling to enable SQL_trace for a number of reasons, the most important of which was its resource overhead.

It is without doubt true that earlier versions have suffered from efficiency problems stemming from the way in which the file writes were performed, especially under MS-Windows. These issues seem to have been resolved in Oracle9i R2. It is, however, clear that tracing must have both a CPU overhead and an I/O overhead, because at the start of any call a number of statistics (such as the current time) have to be noted, and at the end of the call these statistics have to be reexamined, the deltas calculated, and one or more lines written to the trace file. However, it is vital to realize that these overheads are per call so the more work each call performs the lower the percentage overhead of having SQL_trace enabled.

I created a million-row table that was too large to fit into my buffer pool. Running a full table scan on this table always took 6.06 elapsed seconds as measured by the set timing on option in SQL*Plus. It did not matter whether or not SQL_trace was enabled, the operation was reported as taking exactly the same amount of time. We know that with tracing on it must surely be taking longer, but it is not taking very much longer.

At the other end of this spectrum, I used a PL/SQL loop to query each of the first 100,000 rows of the table by primary key; e.g.,

for I in 1 .. 100000  loop
  select CUST_NAME
    into C_NAME
    from CUSTS
    where CUST_ID = I;
end loop;

Even after running this a couple of times to ensure that all the required blocks were in the buffer pool the elapsed time continued to vary slightly, though it always ran at 100% CPU. The loop took about 11 seconds with tracing disabled and about 19 seconds with tracing enabled. It also generated a 14.2 Mb trace file.

The trace penalty may seem high, but the query is particularly efficient. One compelling deduction was that tracing a single SQL statement from within PL/SQL takes Oracle around 80 microseconds on a 833 Mhz Intel chip (the select itself and the loop control overhead taking only some 110 microseconds in this atypical case).

Of course, most SQL statements executed under Oracle come not from PL/SQL loops but from client applications and the same test was repeated using both a Perl script connecting through DBD::Oracle (tracing raised the elapsed time from 79 seconds to 89 seconds) and a Pro*C loop (up from 43 seconds to 56 seconds). In each case the trace file was around 14Mb and the CPU remained at 100% utilization for the duration of the loop.

The highest overhead observed for tracing this particular SQL statement was therefore 130 microseconds including the serial file output overhead. Buffered serial output is clearly good news.

The tests were deliberately severe and normal applications issue SQL statements that take much longer to run and therefore the tracing overhead is much smaller as a percentage of the total.

Other Issues

Managing trace files can quickly become a nightmare if more than a handful of them are generated. Sections of directory listings of the form

…
17/10/02   14:28     14,791,249    dae92_ora_1860.trc
17/10/02   14:28     14,882,780    dae92_ora_1940.trc
17/10/02   14:28     14,505,832    dae92_ora_1960.trc
17/10/02   14:28     14,870,413    dae92_ora_1984.trc
17/10/02   14:03     3,730         dae92_ora_1988.trc
16/10/02   13:28     3,648         dae92_ora_2004.trc
17/10/02   05:14     15,326        dae92_ora_2024.trc
…

do not convey very much information about the applications that created the files other than that the instance was called dae92 and that the sessions were running in threads 1860, 1940, and so forth. It is clearly a good plan to keep the number of trace files to an absolute minimum, and to rename them to something informative immediately after they have been produced.

As we saw above even my humble laptop can process more than 2,000 SQL statements from a C program, and around 9,000 statements per second if they are coming from within the server engine. Oracle9i records timings in trace files in microseconds though the utility tkprof still reports in hundredths of a second. It is important to note that on some platforms (including MS-Windows/2000) Oracle uses a CPU-time clock that reads only to a precision of one hundredth of a second, and so the smallest number of microseconds that will appear in the trace file for the CPU time of a call is 10000. The elapsed time, however, is recorded to genuine microsecond precision.

Row Source Trees

A major attraction of SQL_trace output is that it gives totally accurate information on both execution plans and the number of rows processed at each stage of a row source tree. This information provides a highly effective agenda for query tuning.

Having executed the SQL statement

select count(*)
  from custs c, ordrs r, lines l
where c.cust_type = 'T'
  and r.cust_id = c.cust_id
  and l.cust_id = r.cust_id
  and l.ordr_no = r.ordr_no
  and l.prod_id = 77

with SQL_trace enabled, I ran tkprof and the output file showed the row source tree as

Rows    Row Source Operation
------- ------------------------------------------
       1 SORT AGGREGATE
      31  HASH JOIN
     260   HASH JOIN
     260    TABLE ACCESS BY INDEX ROWID LINES 
     260     INDEX RANGE SCAN LINES_PROD_ID
  550115    TABLE ACCESS FULL ORDRS
    9991   TABLE ACCESS FULL CUSTS

The elapsed time was 6.0 seconds.

It is immediately obvious that the problem is the optimizer's use of two hash joins that in turn require two full table scans to visit an excessive number of rows. This example also highlights a problem with the traditional method of displaying Oracle's execution plans, as the predicate filters are not shown although they are now available from both explain plan and V$SQL_PLAN (discussed below).

The solution adopted in this case was to use index hints to avoid the hash joins, and therefore the full table scans.

The amended statement:

select /*+ INDEX (C)          INDEX (R ORDRS_PK) */ count(*)
  from custs c, ordrs r, lines l
 where c.cust_type = 'T'
  and r.cust_id = c.cust_id
  and l.cust_id = r.cust_id
  and l.ordr_no = r.ordr_no
  and l.prod_id = 77
gave a row source tree of
Rows    Row Source Operation
------- ------------------------------------------
       1 SORT AGGREGATE
      31  NESTED LOOPS
     260   NESTED LOOPS
     260    TABLE ACCESS BY INDEX ROWID LINES
     260     INDEX RANGE SCAN LINES_PROD_ID
     260    INDEX UNIQUE SCAN ORDRS_PK
      31   TABLE ACCESS BY INDEX ROWID CUSTS
     260    INDEX UNIQUE SCAN CUSTS_ID

ran in an elapsed time of 0.13 seconds.

Attacking each row source count that is much higher than the number of rows returned by its parent is a highly effective statement tuning technique, though a word of warning may be appropriate. In this case there were 100,000 rows in CUSTS but only 9,991 were of type T. In other words, the full number of rows coming from the full table scan is not shown, only the number emerging from the scan into the rest of the query processing. Thus, without resource usage figures for each stage of the execution plan, it is still possible for resource consumptive steps not to be apparent from the row source tree.

New Sources in Oracle9i R2

Hopefully, you are convinced of the benefit of accurate information on the SQL statements are being issued, how often they are issued, and how much resource they are using per execution. We have also seen that if we have accurate information on the execution plans and row source counts of these statements, then it will be easier to determine which phase of a statement's execution is generating the major part of the load, and this in turn will point us towards possible solutions.

Unfortunately prior to Oracle9i R2 the files produced by the SQL_trace facility were the only reliable sources of execution plans and row source counts. There were statistics available from V$SQL, most notably buffer_gets, that helped us to identify the problem SQL statements but in order to see an execution plan we needed to issue an explain plan, and as we have already discussed this was (and still is) liable to give a misleading result. Even if the execution plan is accurate, the row source counts within it are estimates that were used to pick the execution plan, and if the plan seems to be "less than optimal" then it may be only sensible to suspect that these estimates may be wrong.

In Oracle9i R2 a number of additional V$ views have been provided to give access to statistics, and the two of greatest interest in this discussion are V$SQL_PLAN and V$SQL_PLAN_STATISTICS. Both can be joined to V$SQL by the columns ADDRESS and HASH_VALUE and the new views give respectively the actual execution plan assigned to the statement and the resources used to date by each stage of the plan. It appears to the author that V$SQL_PLAN_STATISTICS reports only the resources used by completed executions.

It is also worth noting that both CPU time used and elapsed time have finally been added to V$SQL so it is no longer necessary to use BUFFER_GETS and PHYSICAL_READS as surrogates for CPU and elapsed time respectively.

Cautions

When composing joins against V$ views, it is vital to remember that Oracle's query consistency model is not used for such queries. For this reason, even though the ADDRESS column of V$SQL is a unique key, the join should include HASH_VALUE just in case the slot is reused for a different statement while your query is executing.

Secondly, these new views are always visible, but V$SQL_PLAN_STATISTICS is only populated when the new parameter statistics_level is set to ALL, and this is not its default setting. It also appears to contain data only from statement plans produced by the cost based optimizer.

Thirdly, use of V$SQLAREA is deprecated because it contains a group by clause that can cause aggregation across different instances of the same statement, possibly with different execution plans. As discussed above, there are many reasons why Oracle may need to track different instances of the same statement; one is that the statements may have been parsed with different optimizer modes in effect.

Reporting

Oracle do not ship any scripts for reporting from V$SQL_PLAN_STATISTICS, and my first cut script is not yet sufficiently well developed to be included with this paper, but I hope to put a more refined version onto http://www.dbazine.com in the near future.

Initial experimentation has shown that the views can give the same level of reporting of execution plans and row source trees as tkprof. An unexpected bonus of having to write my own script was that I could report the row source counts as an average per execution rather than as a total across all executions; e.g.,
select count(MEMBNAME) from MEMBERS

Rows    Row Source Operation
------- ---------------------------------------------------
2       SORT AGGREGATE (cr=9324 r=9309 w=0 time=14559236 us)
2000000  TABLE ACCESS FULL MEMBERS (cr=9324 r=9309 w=0 time=9827664 us)    

became

select count(MEMBNAME) from MEMBERS
 Avg Rows   Operation
---------   ---------
         1  SORT AGGREGATE (resource detail not yet implemented)
1,000,000     TABLE ACCESS FULL DAVE.MEMBERS (resource detail not yet implemented)
Calls: Parse = 1, Execute = 2

Note: the trace file was produced with statistics_level = ALL

Resource Implications

The Pro*C loop discussed earlier was run with each possible setting of the new parameter and the results are summarized below:

statistics_level     timed_statistics     Elapsed seconds at 100% CPU
BASIC                false                43
TYPICAL              true                 43
ALL                  true                 48

These results should be of considerable reassurance to those who retain residual concerns about the overhead of timed_statistics, and the cost of gathering the additional statistics seems quite modest in view of the benefits. However, a simple test of two rather less efficient operations returned less encouraging results.

                                    Elapsed seconds at 100%          CPU
statistics_level  timed_statistics  Index fast full scan      Full table scan
BASIC             false             0.02                      2.03
TYPICAL           true              0.02                      2.03
ALL               true              4.03                      7.01

It would appear that the new facility has an uncomfortable overhead for more resource consumptive operations where presumably the cost can less readily be afforded. Although the new views are excellent from a functional point of view, the performance penalties observed may mitigate against their use in any production environment where long scans are taking place with any frequency.

Additional Features in SQL Trace

Wait Data

One of the major changes in Oracle tuning practice over the past few years has been the increasing attention given to investigating the wait states encountered by the Oracle server, observed through views including V$SYSTEM_EVENT, V$SESSION_EVENT and V$SESSION_WAIT.

Tying the incidence of particular wait states (for example I/O waits) to a particular statement generally requires either a data collector that directly accesses Oracle's shared memory region or high-frequency polling using the V$ views. Suitable data collectors are available from a number of sources, but not from Oracle itself, and have been widely installed because use of the V$ views can cause a significant CPU overhead.

When SQL_trace first appeared somewhere around Oracle Version 6.0.23 it was enabled and disabled through Oracle's general tracing facility, the events mechanism. The syntax then used to switch on what we now call SQL_trace was
alter session set events '10046 trace name context forever, level nn';

This syntax remains available, albeit barely documented, and is used by Oracle Support to extract many different types of diagnostic data from the server engine. Several hundred different trace events can be enabled, and the level number is a means of specifying options to the event; for event 10046 setting level 8 (or 12) will result in an entry being made in the trace file for each wait encountered. As an aside, level 4 records all bind variable values, which can also be useful in some tuning situations.

Although this ability to trace wait states is not documented (except in the comments in the supplied file dbmssupp.sql), tkprof's command line help does admit the existence of the option waits=yes which reports the total number and type of waits (if any) encountered by each SQL statement in the trace file; e.g.,

********************************************************************************
SELECT count(MEMBNAME) from MEMBERS

call     count      CPU    elapsed       disk      query    current       rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse        1     0.03       0.03          0          0          0          0
Execute      2     0.00       0.00          0          0          0          0
Fetch        2     9.89       14.55      9309       9324          0          2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total        5     9.92       14.59      9309       9324          0          2
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 61     (recursive depth: 1)
Rows    Row Source Operation
------- ---------------------------------------------------
      2 SORT AGGREGATE (cr=9324 r=9309 w=0 time=14559236 us)
2000000  TABLE ACCESS FULL MEMBERS (cr=9324 r=9309 w=0 time=9827664 us)
Elapsed times include waiting on following events:
 Event waited on                            Times   Max. Wait   Total Waited
----------------------------------------    Waited  ----------  ------------
db file scattered read                         304        0.03          2.32
********************************************************************************

Enabling level 8 in these tests added only about 40 milliseconds to the observed elapsed time of the scan.

Application Flow

The vendor side of the software industry tends to regard any form of reverse engineering with a great deal of suspicion, and normally little mention is made in the literature of features that support such activity. However, it is clear that the SQL_trace facility allows a determined user to find out exactly what SQL is being executed and in what order. Some software products even issue a protective

alter session set SQL_trace false;

at the start of each run to prevent customers from acquiring details of the execution flow. As we have seen this will not necessarily stop a investigator from generating a trace file, though the first few seconds of the run may escape tracing.
The tkprof command line option record=filename causes each non-recursive SQL statement that appears in the trace file to be written to the nominated file though this is not as useful as it at first sounds for a couple of reasons. Firstly, the file written will contain no information whatever about SQL issued from stored procedures or triggers because recursive SQL is not reported.

Secondly, and more importantly, although the statements appear in the resulting file in the order in which they were parsed this does not give a good picture of the application flow as well written applications parse each statement only once, even if they then execute each statement several thousand times.

The full application flow, including all recursive SQL, is freely available from a trace file but its capture requires either that the investigator read the raw trace file or that they write or acquire a suitable utility. Each line in a trace file that gives the statistics for an individual call also gives the cursor number; e.g.,

EXEC #2:c=0,e=487,p=0,cr=1,cu=2,mis=0,r=1,dep=0,og=4,Tim=210428127311

and at some earlier point in the file there will be a parse call to this cursor that will report the SQL submitted; e.g.,

PARSING IN CURSOR #2 Len=89 dep=0 uid=64 oct=6 lid=64 Tim=210428125008 hv=2185651036         
ad='667b3e98'
      update RUNS
         set CONNECTS = nvl(CONNECTS, 0) + 1
       where RUN_ID = :p1
END OF STMT

The principal danger of trying to track this down by hand is that cursors are routinely re-used and it is all too easy to look back too far through the file and locate an earlier SQL statement than the one actually being executed. The really determined reverse engineer writes some string processing code (a Perl script perhaps) to keep track of the usage of each cursor and can establish the application flow with complete accuracy, at least as far as its use of Oracle is concerned. This can often by highly illuminating about both program structure and end user behavior, and is an important potential benefit of trace file production.

Conclusions

The new V$ objects that are populated when statistics_level = all give all of the data necessary both to pick the SQL statements that merit tuning effort and to diagnose the likely cause of any performance problems. However, in their present implementation the high CPU overhead during scans may critically limit their use. It is also worth noting that although the feature can be enabled at session level, there does not seem to be any mechanism for doing this from outside the session, and therefore limiting the overhead to a nominated session is available only with application awareness of the feature.

On the other hand, a reasonably well tuned Oracle application is more likely to be I/O-bound than CPU-bound, and this alone may make the CPU overhead of the approach acceptable in order to take advantage of a data collection mechanism with no I/O overhead. It should also be noted that if Oracle Parallel Query is not active then on a server with multiple CPUs, each scan operation will consume a maximum of 1 CPU worth of CPU load. The less CPUs that are available, the more dramatic the likely impact of multiple simultaneous scans (especially if they are running against cached objects).

The production of SQL_trace files will inevitably increase the total I/O load on an instance, but the mechanism retains several major advantages, including the fact that its percentage overhead is lower when the SQL statements being traced are inefficient. Put another way, if the overhead of running SQL_trace on selected sessions is significant, then you probably have a well-tuned application and do not need tracing anymore!

If you want to investigate application flow, or to discover which of the SQL statements in an application are causing waits, then the SQL_trace mechanism is the only feasible option that does not require installation of a third-party tool to monitor Oracle's shared memory region. The reporting tool supplied by Oracle, tkprof, is very fast and meets all of the reporting needs discussed other than reporting the application flow.

SQL_trace remains an important feature for diagnosing Oracle performance problems that are related to SQL statement execution, and almost all Oracle performance problems are closely related to SQL statement execution.

--

Dave Ensor is a Senior Technical Advisor with BMC Software where his mission is to produce software solutions that automate Oracle performance tuning. He has been tuning Oracle for 15 years, and in total he has more than 30 years' active programming and design experience.

As an Oracle design and tuning specialist Dave built a global reputation both for finding cost-effective solutions to Oracle performance problems and for his ability to explain performance issues to technical audiences. He is co-author of the O'Reilly & Associates books Oracle Design and Oracle8 Design Tips.