Application Tuning Using Extended SQL Trace And TKPROF

Introduction

Sometimes it’s useful to be able to trace an Oracle session. This could be because you’ve written a batch process, it’s taking a long time to run, and you want to find out what’s causing it to run slow. It could also be because you’ve written a web or desktop application, and users complain that certain parts of the application run too slow. By tracing an Oracle session, which contains one or more SQL statements executed in order, you want find out precisely what statements your session executed, how they were executed by Oracle, and what delays occurred as the statements were executed.

This is particularly useful when you’ve written a batch job or program that, when run in isolation, runs very quickly, but when you try and run multiple copies of it concurrently the response time increases exponentially. This is usually because each concurrent program is fighting over the same database blocks and Oracle resources at the same time, or because an underlying inefficiency in your program becomes more apparent when multiple copies are run at the same time.

One of the features that Oracle has got that you don’t find in databases like Access, SQL Server and DB2 is that the database kernel is ‘instrumented’ and, more importantly, you can easily ask Oracle to provide you with a detailed breakdown of exactly what happens when you execute a set of queries. By tracing your Oracle session or batch job, you can list out the statements that you’ve executed, the cost of each statement, and, using the Oracle kernel diagnostics, list out in detail what events happened in the background that caused your statements to run slower than you expected.

This document sets out how to enable SQL tracing for any Oracle database (8i, 9i, 10g), how to format and interpret the trace files, and where to look next to resolve your performance issues.

Scenario 1 : PL/SQL Simulate Workload, single process.

To help explain how tracing in Oracle works, I have provided some PL/SQL code that simulates two typical workloads, with code at the start of the procedure that turns on extended SQL tracing for the rest of the session. The code works off of the sample data within the SCOTT/TIGER schema found within every Oracle database.

The first bit of PL/SQL code simulates a typical workload. Note – no comments about the code, this is just a rough and ready set of inserts, updates, selects and deletes put together to simulate a workload. (download PL/SQL code)

CREATE OR REPLACE procedure simulate_workload_with_binds
as
var1 varchar2(100);
begin

-- turn on extended SQL tracing

execute immediate 'alter session set timed_statistics = true';
execute immediate 'alter session set max_dump_file_size = unlimited';
execute immediate 'alter session set tracefile_identifier = ''test1_binds_single_process''';
execute immediate 'alter session set events ''10046 trace name context forever, level 8''';

-- main body of code

for c in 1 .. 500 loop
insert into test (col1) values (c);
commit;
end loop;

commit;

for c in 1 .. 50 loop
update test
set col1 = col1;
commit;
end loop;

for c in 1 .. 500 loop
begin
select col1
into var1
from test
where col1 = c;
exception
when others then null;
end;
end loop;

for c in 1 .. 500 loop
insert into test(col1) values (c);
commit;
end loop;

commit;

for c in 1 .. 500 loop
delete from test where col1=c;
commit;
end loop;

commit;

execute immediate 'alter session set events ''10046 trace name context off''';

end;
/

points to note :

The following code turns on what’s termed ‘extended SQL tracing’ for this session:

-- turn on extended SQL tracing

execute immediate 'alter session set timed_statistics = true';
execute immediate 'alter session set max_dump_file_size = unlimited';
execute immediate 'alter session set tracefile_identifier = ''test_1 _binds_single_process''';
execute immediate 'alter session set events ''10046 trace name context forever, level 8''';

“alter session set timed_statistics=true” ensures that the trace data contains timings for the various events and statements contained within it.

“alter session set max_dump_file_size = unlimited” ensures that your trace doesn’t prematurely end because you’ve reached the default max dump file size.

“alter session set tracefile_identifier = ‘’test1_binds_single_process’’” puts the specified text into the trace file name, making it easier to identify later

“alter session set events ‘’10046 trace name context forever, level 8’’’” is the important line, and tells Oracle to emit trace data, including information on ‘wait events’ (this is what the level 8 bit refers to) to the trace file.

Note the bit about ‘extended SQL tracing’. It’s called ‘extended’ because it’s like regular SQL tracing (which you can turn on by issuing the command Alter session set sql_trace=true ) but it additionally captures diagnostic information on what’s called ‘wait events’ – behind the scenes events that delay your SQL statement – events such as locks on tables, contention for disk blocks and so on. Also, with later versions of Oracle, you can active extended SQL trace using new built in Oracle packages - however, the method detailed above works for all Oracle versions, doesn’t require you to install any additional packages, and captures all the information we need for tracing. Note also that it’s possible to interactively turn on tracing for a session using the SQL*Plus prompt, and you can also turn it on for sessions other than your own – however for simplicity’s sake I’m embedding the relevant code directly into the PL/SQL procedure. For more details on the various ways to invoke extended SQL tracing see this presentation by David Kurtz.

The PL/SQL code is the compiled, and then executed with the commands :

SQL> exec simulate_workload;

PL/SQL procedure successfully completed.

The trace file is then located (within my c:\oracle\admin\markr9i\udump directory) and you can download the raw trace file here. Interpreting this raw trace file is outside the scope of this document, but if you’re interested more details can be found in the book “Optimising Oracle Performance” by Cary Millsap and Jeff Holt, a copy of which can be found in the office.

The next step is to use TKPROF (provided by default with all recent Oracle installations) to process and report on this raw trace file. From the DOS command line, find the raw trace file, and issue the command:

TKPROF raw_trace_file_name formatted_trace_file_name

e.g.

C:\oracle\admin\markr9i\udump>tkprof markr9i_ora_5820_test1_binds_single_process
.trc markr9i_ora_5820_test1_binds_single_process.txt

TKPROF: Release 9.2.0.5.0 - Production on Mon Oct 4 11:03:48 2004

Copyright (c) 1982, 2002, Oracle Corporation. All rights reserved.


C:\oracle\admin\markr9i\udump>

Then, open up the formatted trace file (download here) with notepad, textpad or similar.

The formatted trace file has the following sections:

1. The preamble that tells you about TKPROF formatted trace files, and the SQL statement that enabled extended SQL trace.
TKPROF: Release 9.2.0.5.0 - Production on Mon Oct 4 14:19:34 2004

Copyright (c) 1982, 2002, Oracle Corporation. All rights reserved.

Trace file: markr9i_ora_5820_test1_binds_single_process.trc
Sort options: default

********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************

alter session set events '10046 trace name context forever, level 8'


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.00 0 0 0 0

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 59 (recursive depth: 1)
********************************************************************************

2. The statements that were executed as part of the PL/SQL packages.
INSERT INTO TEST (COL1)
VALUES
(:B1)


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 500 0.09 0.08 0 1 1007 500
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 501 0.09 0.08 0 1 1007 500

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 59 (recursive depth: 1)
********************************************************************************

COMMIT


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 7 0.00 0.00 0 0 0 0
Execute 1553 0.08 0.07 0 0 1550 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1560 0.08 0.07 0 0 1550 0

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 59 (recursive depth: 1)
********************************************************************************

UPDATE TEST SET COL1 = COL1


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 50 6.12 6.19 0 452 27078 25000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 51 6.12 6.19 0 452 27078 25000

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 59 (recursive depth: 1)

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
undo segment extension 293 0.00 0.00
********************************************************************************

select file#
from
file$ where ts#=:1


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.01 2 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.01 2 3 0 1

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 2)

Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID FILE$
1 INDEX RANGE SCAN I_FILE2 (object id 42)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 2 0.00 0.01
********************************************************************************

SELECT COL1
FROM
TEST WHERE COL1 = :B1


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 500 0.01 0.00 0 0 0 0
Fetch 500 0.09 0.08 0 4500 0 500
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1001 0.10 0.09 0 4500 0 500

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 59 (recursive depth: 1)
********************************************************************************

INSERT INTO TEST(COL1)
VALUES
(:B1)


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 500 0.09 0.09 0 2 1026 500
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 501 0.09 0.09 0 2 1026 500

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 59 (recursive depth: 1)
********************************************************************************

DELETE FROM TEST
WHERE
COL1=:B1


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 500 0.25 0.25 0 4500 1516 1000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 501 0.25 0.25 0 4500 1516 1000

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 59 (recursive depth: 1)
********************************************************************************

alter session set events '10046 trace name context off'


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 59 (recursive depth: 1)

Taking the first PL/SQL commands and looking at them more detail

for c in 1 .. 500 loop
insert into test (col1) values (c);
commit;
end loop;

This results in the following formatted trace output:

INSERT INTO TEST (COL1)
VALUES
(:B1)


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 500 0.09 0.08 0 1 1007 500
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 501 0.09 0.08 0 1 1007 500

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 59 (recursive depth: 1)
********************************************************************************

The PL/SQL commands set up a loop that executes 500 times, with the value of the loop counter being inserted into the ‘test’ table each time the loop executes.

What the trace file tells us is that a single command was parsed once, then executed 500 times. This is because PL/SQL uses bind variables by default, and Oracle would therefore only need to hard parse the statement once, with subsequent executions being able to use the stored parsed value of the statement each time a new value was inserted. For more details on bind variables, see http://www.rittman.net/archives/000832.html. Therefore, this section of the trace file refers to 500 separate SQL code executions, and the trace file has wrapped these up into a single section of the trace file.

It’s also useful to look at the ‘totals’ at the bottom of the statement breakdown, that show you the cpu time taken up by the statements and the total elapsed time. Note that the elapsed time is shorter than the CPU time – this is a rounding error and infact the elapsed time in this case should be considered to be the CPU time or a few microseconds more.

Once you have reviewed the rest of the SQL statements in the trace file, move on to the final part of the trace file.

3. The trace file summary
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0

Misses in library cache during parse: 0


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 14 0.00 0.00 0 0 0 0
Execute 3606 6.64 6.70 0 4955 32177 27000
Fetch 502 0.09 0.09 2 4503 0 501
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4122 6.73 6.80 2 9458 32177 27501

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
undo segment extension 293 0.00 0.00
db file sequential read 2 0.00 0.01

14 user SQL statements in session.
1 internal SQL statements in session.
15 SQL statements in session.
********************************************************************************
Trace file: markr9i_ora_5820_test1_binds_single_process.trc
Trace file compatibility: 9.02.00
Sort options: default

1 session in tracefile.
14 user SQL statements in trace file.
1 internal SQL statements in trace file.
15 SQL statements in trace file.
9 unique SQL statements in trace file.
6053 lines in trace file. 5728 lines in trace file.

The main Area of interest in this section is the ‘Overall Totals For All Recursive Statements’ section. This is the SQL statements contained within your PL/SQL package and comprises the totals for all parses, executes and fetches incurred by your statements. In this particular bit of PL/SQL, bind variables are used and statements are executed many times, which leads to a much smaller amount of parses than executes – which is generally a good thing.

If your parses were more or less the same as your executes, you should check your code to make sure bind variables are being used – in PL/SQL, it is difficult to not use bind variables, but with Java, VB etc you have to consciously use them, and therefore it’s not unusual to find excessive amounts of parsing in their traced code, which is generally a bad thing as parsing ties up the CPU and prevents the application scaling if many users are using the program concurrently.

Note also the totals, where the elapsed time is only slightly higher than the CPU time – this shows that the program only took slightly longer to execute than the CPU time it required, meaning that it wasn’t unduly delayed by waiting for contended resources, network traffic and so on. If you were tuning this application, you wouldn’t really worry about this sort of profile.

Lastly, although it’s not really an issue for this simulated workload, note also the columns headed ‘query’ ‘current’ and ‘rows’ – these detail the amount of rows, blocks and so on that the query requested and worked on – if your program appears to be requesting and processing an excessive number of rows, look to reduce these (by altering the SQL statements) to bring down the total amount of data the query is looking to process.

Scenario 2 : PL/SQL Simulated Workload, 5 concurrent processes.

This scenario looks at a more common situation, where a program that previously performed without too much of an issue now is exponentially slower when a larger number of copies are run concurrently.

To test this, a line in the PL/SQL program was changed to alter the trace file identifier:

-- turn on extended SQL tracing

execute immediate 'alter session set timed_statistics = true';
execute immediate 'alter session set max_dump_file_size = unlimited';
execute immediate 'alter session set tracefile_identifier = ''test2_binds_concurrent_processes''';
execute immediate 'alter session set events ''10046 trace name context forever, level 8''';

(download the altered PL/SQL package here) and then five copies of the program were executed simultaneously, by opening up five DOS command windows and then executing the PL/SQL program within each session at the same time.

The first thing that you will notice is that each copy of the program takes considerably longer to run when run concurrently with the others. In short, this is because each copy is trying to insert, update, select from and delete from the same table, leading to contention for resources.

You will notice that five separate trace files have been output into the /udump directory, with a different process ID embedded within each filename. Assuming that all processes were started at the same time, take one trace file (download here) and process it using TKPROF:

C:\oracle\admin\markr9i\udump>tkprof markr9i_ora_2652_test2_binds_concurrent_pro
cesses.trc markr9i_ora_2652_test2_binds_concurrent_processes.txt

TKPROF: Release 9.2.0.5.0 - Production on Mon Oct 4 12:50:46 2004

Copyright (c) 1982, 2002, Oracle Corporation. All rights reserved.


C:\oracle\admin\markr9i\udump>

Then, open up the formatted trace file (download here) and view using Notepad.exe. You will find the same structure within the trace file, the same order of statements and so on. However, looking at for example the set of SQL statements analyzed before, note this time that the elapsed time is twice as much as the CPU time.

INSERT INTO TEST (COL1)
VALUES
(:B1)


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 500 0.14 0.31 0 2 1021 500
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 501 0.14 0.31 0 2 1021 500

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 59 (recursive depth: 1)
********************************************************************************

Also, look at the part of the trace file that analyzes the SQL statement

UPDATE TEST SET COL1 = COL1

In our original trace file (where the command was run in isolation) the trace file shows the following analysis:

UPDATE TEST SET COL1 = COL1

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 50 6.13 6.27 0 451 25600 25000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 51 6.13 6.27 0 451 25600 25000

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 59 (recursive depth: 1)
********************************************************************************

whilst in our current trace file, where the command was run concurrently, the trace file analysis shows:

UPDATE TEST SET COL1 = COL1


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 50 114.77 781.11 6 277901 128304 124500
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 51 114.77 781.11 6 277901 128304 124500

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 59 (recursive depth: 1)

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
enqueue 305 3.12 605.91
buffer busy waits 146 0.08 1.38
undo segment extension 162 0.00 0.00
db file sequential read 6 0.06 0.12
********************************************************************************

Our original trace file shows a total elapsed time of 6.27 seconds and a CPU time of 6.13 seconds, which is acceptable. However our current trace file shows a total elapsed time of 781.11 seconds and a CPU time of 114.77 seconds – our CPU time has risen dramatically, and our elapsed time is several times longer again.

However, note the section that follows the statement breakdown, headed by ‘Elapsed Times Include Waiting On The Following Events’. This is called the wait event analysis, and it tells us exactly what kept our statement waiting.

The key column is the ‘total waited’ column, and you can see in this instance that our statement was kept waiting for 605.91 seconds by the ‘enqueue’ wait event – which means ‘locks’. Looking back at our PL/SQL code, this problem is happening because each of the five copies of the program are trying to update the same columns in the same table, and more often than not the row is locked when a copy of the application needs to write to it.
Also, note the ‘buffer busy waits’ event. Buffer busy waits (http://www.dba-oracle.com/art_builder_bbw.htm) occur when an Oracle session needs to access a block in the buffer cache, but cannot because the buffer copy of the data block is locked. This buffer busy wait condition can happen for either of the following reasons:
• The block is being read into the buffer by another session, so the waiting session must wait for the block read to complete.

• Another session has the buffer block locked in a mode that is incompatible with the waiting session's request.
Buffer busy waits are happening in our system because each session is trying to access the same blocks in the database buffer, meaning that most of them have to wait until the other one has finished reading the buffer block. However, note that whilst the number of buffer busy waits is 50% of the enqueue waits, the total waited time is only a fraction of the wait time caused by enqueue events – therefore, if you were tuning this application, you would focus the vast majority of your time on solving the enqueue problem, as this will have the greatest impact on your application (i.e. it will potentially remove 605.91 seconds from the time your session takes to run, rather than the 1.38 seconds that would be removed by dealing with the buffer busy waits issue)
The rest of our statements in the formatted trace file also suffer from the buffer busy waits problem, but the total delay is very small compared to our enqueue problem detailed before.
SELECT COL1
FROM
TEST WHERE COL1 = :B1


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 500 0.00 0.00 0 0 0 0
Execute 500 0.00 0.00 0 0 0 0
Fetch 500 0.17 1.08 0 2499 0 500
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1500 0.17 1.09 0 2499 0 500

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 59 (recursive depth: 1)

Rows Row Source Operation
------- ---------------------------------------------------
2 TABLE ACCESS FULL TEST


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
buffer busy waits 27 0.05 0.23
latch free 2 0.01 0.01
********************************************************************************
INSERT INTO TEST(COL1)
VALUES
(:B1)


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 500 0.09 0.56 0 149 1010 500
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 501 0.09 0.56 0 149 1010 500

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 59 (recursive depth: 1)

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
buffer busy waits 4 0.05 0.13
********************************************************************************

DELETE FROM TEST
WHERE
COL1=:B1


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 500 0.71 3.91 0 8466 845 566
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 501 0.71 3.91 0 8466 845 566

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 59 (recursive depth: 1)

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
buffer busy waits 81 0.06 1.11
latch free 11 0.03 0.06
enqueue 3 0.09 0.16
********************************************************************************
Note that the last statement that deletes from the test table also has issues with locking and latches, but the total contribution to total session time is very small.
Next, look at the summary section of the formatted trace file.
********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0

Misses in library cache during parse: 0


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 512 0.00 0.00 0 0 0 0
Execute 3605 115.77 787.28 6 286518 132493 126066
Fetch 500 0.17 1.08 0 2499 0 500
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4617 115.94 788.37 6 289017 132493 126566

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
enqueue 308 3.12 606.08
buffer busy waits 258 0.08 2.85
undo segment extension 162 0.00 0.00
db file sequential read 6 0.06 0.12
latch free 15 0.03 0.10

513 user SQL statements in session.
0 internal SQL statements in session.
513 SQL statements in session.
********************************************************************************
Trace file: markr9i_ora_2652_test2_binds_concurrent_processes.trc
Trace file compatibility: 9.02.00
Sort options: default

1 session in tracefile.
513 user SQL statements in trace file.
0 internal SQL statements in trace file.
513 SQL statements in trace file.
8 unique SQL statements in trace file.
9491 lines in trace file.

Looking at the ‘Overall Totals For All Recursive Statements’ section, it shows that the total CPU time was 115.94 and the total elapsed time was 788.37, with the difference between the two being the amount of time Oracle was having to wait around for resources or other wait events.

The ‘Elapsed times include waiting on following events’ section then summarises all of the wait events, with ‘enqueue’ again being by far the largest contributor to the total time taken up by the session.

The outcome of tracing this session would be that you would concentrate your efforts on resolving the locking problems being experienced by the UPDATE statement in your code, and this would have a major effect on the total running time of your application.
(Footnote : We did in fact also have a wait event section in the previous formatted trace file markr9i_ora_5820_test1_binds_single_process.txt:
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
undo segment extension 293 0.00 0.00
db file sequential read 2 0.00 0.01

However, the total waiting time was virtually nil – 0.01 seconds - and would not be something you would need to concern yourself with when tuning a particular session.)

Conclusions

Tuning your batches, statements and applications using extended SQL trace and TKPROF allows you to examine exactly what statements your code is executing, whether they used bind variables, how many rows they processes and what wait events occurred whilst they were trying to execute. By tuning your applications using this approach, you can determine exactly what is slowing your code down, allowing you to concentrate your efforts on eliminating those waits that add the most to your total execution time.

Tuning applications in this way takes much of the ‘guess work’ out of tuning Oracle applications and makes it a process based on logical steps and documented approaches rather than picking solutions out of the air and hoping they’l have an effect.

Further Reading

For more details on extended SQL tracing and TKPROF, take a look at the following

• Optimising Oracle Performance, Cary Millsap & Jeff Holt (considered to be the canonical text on tuning using wait event analysis)
• Effective Oracle By Design, Tom Kyte (pages 120-135)
• Oracle Performance Tuning 101, Gaja Krishna Vaidyanatha (chapter 4)
Also, take a look at these articles

• Diagnosing Oracle Performance Problems by Cary Millsap
• Oracle Performance Tuning Using Event 10046
• Watching Your users' every move: All about SQL Tracing by Thiru Vadivelu
• "Oracle System Performance Analysis Using Oracle Event 10046" by Cary Millsap & Jeff Holt
• "Diagnosing Performance Problems Using Extended Trace" by Cary Millsap
• Why a 99%+ Database Buffer Cache Hit Ratio is Not Ok by Cary Millsap, (free reg. Required)
• How to Manage an Oracle Optimization Project by Gary Goodman (free reg. required)
• Performance Management Myths and Facts by Cary Millsap
• Introduction to Method R and Hotsos Profiler by Cary Millsap (free reg. required)
• How to Activate Extended SQL Trace by Cary Millsap (free reg. required)
• Performance Problems from the Field, Part 1 by Cary Millsap (free reg. required)
Note : Extended SQL Tracing When Using Connection Pooling

One problem that comes up with extended SQL tracing is when your application is an application (typically Java, or .NET) that uses connection pooling. In this sort of situation, the statements for a typical user session can end up spread over several separate trace files, each one relating to a separate pooled connection. In addition (and this is the worst bit) each trace file can contain SQL statements for other users who are using the same pooled connection, mixing up their statements with yours.
Connection pooling is dealt with in the above books and articles, but in summary the problem is usually dealt with in one of the following ways.
• Oracle 10g has specific features (detailed in Tracing SQL in Oracle Database 10g by Kimberly Floss) which allow you to identify just those SQL statements that pertain to a particular user/application.
• Force all users to log off the system then run the application, and cut and paste the separate trace files into one before analyzing using TKPROF
• Run a separate copy of the application on a different port number (for example, port 81) and have this version connect using a dedicated connection, and then TKPROF the resultant trace file as normal.