Reading TKPROF formatted trace files

How to read a tkprof formatted trace file

View the summary at the bottom of the tkprof formatted trace file to assess what was taking up the most time. For example, the below shows that most of the overall elapsed time was spent on the execution of SQL. Therefore it would be worthwhile looking at a tkprof formatted trace file which was sorted by exeela (execute elapsed time). The most expensive queries will then be displayed from top down ordered by how long it took to execute each query.

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows

------- ------ -------- ---------- ---------- ---------- ---------- ----------

Parse 124 0.60 0.73 7 227 0 0

Execute 125 10.98 105.79 16113 578057 14414 7042

Fetch 2 0.00 0.00 0 5 0 1

------- ------ -------- ---------- ---------- ---------- ---------- ----------

total 251 11.58 106.53 16120 578289 14414 7043

Misses in library cache during parse: 62

Elapsed times include waiting on following events:

Event waited on Times Max. Wait Total Waited

---------------------------------------- Waited ---------- ------------

SQL*Net message to client 121 0.00 0.00

SQL*Net message from client 121 0.01 0.23

library cache lock 153 0.00 0.02

library cache pin 17 0.00 0.00

row cache lock 67 0.00 0.02

global cache cr request 12558 0.43 7.43

db file sequential read 15394 0.09 87.58

enqueue 22 0.00 0.00

global cache open x 6 0.00 0.00

log file sync 5 0.00 0.01

db file scattered read 23 0.08 0.56

global cache s to x 2557 0.07 0.82

SQL*Net more data from client 47 0.00 0.00

global cache open s 1 0.00 0.00

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows

------- ------ -------- ---------- ---------- ---------- ---------- ----------

Parse 296 0.09 0.07 0 39 0 0

Execute 14211 5.66 15.66 1569 946009 276 127

Fetch 953 0.09 0.49 95 2161 3 753

------- ------ -------- ---------- ---------- ---------- ---------- ----------

total 15460 5.84 16.24 1664 948209 279 880

Misses in library cache during parse: 20

Elapsed times include waiting on following events:

Event waited on Times Max. Wait Total Waited

---------------------------------------- Waited ---------- ------------

row cache lock 12 0.00 0.00

global cache cr request 2815 0.18 0.97

db file sequential read 981 0.10 9.34

enqueue 2 0.00 0.00

global cache open x 1 0.00 0.00

db file scattered read 2 0.03 0.04

global cache s to x 3 0.00 0.00

global cache open s 2 0.00 0.00

db file parallel read 9 0.07 0.32

If the overall timings are minimal then there would be very little scope for tuning the SQL within the trace thus it would not be worth wasting your time investigating the queries.

Investigating SQL inside a tkprof formatted trace file.

UPDATE c_inrd_ins_redemption inrd

SET (inrd.c_inrd_input_date,

inrd.c_inrd_rdm_early_value,

inrd.c_inrd_exsh_j1

) =

(SELECT ixj.i_xj_file_date,

DECODE(inrd.c_inrd_rdm_early_value,0,ixj.i_xj_j4_early_value,

DECODE(ixj.i_xj_j4_early_value,0,inrd.c_inrd_rdm_early_value,

ixj.i_xj_j4_early_value)),

ixj.i_xj_j1_redemption_type

FROM i_xj_exshare_section_j ixj,

c_in_instrument ins

WHERE ixj.i_xj_sedol_num = ins.c_in_sedol

AND inrd.c_inrd_in_id = ins.c_in_id)

WHERE EXISTS

(SELECT ins1.c_in_id

FROM c_in_instrument ins1,

i_xj_exshare_section_j ixj1

WHERE ins1.c_in_current_mkr = 'Y'

AND ixj1.i_xj_rdm_early_date IS NOT NULL

AND ixj1.i_xj_sedol_num = ins1.c_in_sedol

AND inrd.c_inrd_rdm_early_date = ixj1.i_xj_rdm_early_date

AND inrd.c_inrd_in_id = ins1.c_in_id)

call count cpu elapsed disk query current rows

------- ------ -------- ---------- ---------- ---------- ---------- ----------

Parse 1 0.01 0.00 0 0 0 0

Execute 1 7.55 93.15 13807 535656 0 0

Fetch 0 0.00 0.00 0 0 0 0

------- ------ -------- ---------- ---------- ---------- ---------- ----------

total 2 7.56 93.15 13807 535656 0 0

Column Value

Meaning

PARSE

Translates the SQL statement into an execution plan, including checks for proper security authorization and checks for the existence of tables, columns, and other referenced objects.

EXECUTE

Actual execution of the statement by Oracle. For INSERT, UPDATE, and DELETE statements, this modifies the data. For SELECT statements, this identifies the selected rows.

FETCH

Retrieves rows returned by a query. Fetches are only performed for SELECT statements.

COUNT

Number of times a statement was parsed, executed, or fetched.

CPU

Total CPU time in seconds for all parse, execute, or fetch calls for the statement. This value is zero (0) if TIMED_STATISTICS is not turned on.

ELAPSED

Total elapsed time in seconds for all parse, execute, or fetch calls for the statement. This value is zero (0) if TIMED_STATISTICS is not turned on.

DISK

Total number of data blocks physically read from the datafiles on disk for all parse, execute, or fetch calls.

QUERY

Total number of buffers retrieved in consistent mode for all parse, execute, or fetch calls. Usually, buffers are retrieved in consistent mode for queries.

CURRENT

Total number of buffers retrieved in current mode. Buffers are retrieved in current mode for statements such as INSERT, UPDATE, and DELETE.

ROWS

Total number of rows processed by the SQL statement. This total does not include rows processed by subqueries of the SQL statement.

Note: Query + Current = Logical Reads (total number of buffers accessed)

Looking at the above example we can see the SQL statement was executed once and took 93.15 seconds to complete. The query performed 535,656 logical reads of which 13,807 were from disk in order to update 0 rows. Therefore the query does not look very efficient.

The following part of the trace file shows the explain plan of the query and any wait events that occurred while running the SQL:

Misses in library cache during parse: 1

Optimizer goal: CHOOSE

Parsing user id: 6055 (INTERFACE)

Rows Row Source Operation

------- ---------------------------------------------------

0 UPDATE

0 FILTER

103779 TABLE ACCESS FULL C_INRD_INS_REDEMPTION

0 NESTED LOOPS

103395 TABLE ACCESS BY INDEX ROWID C_IN_INSTRUMENT

103480 INDEX UNIQUE SCAN C_IN_X_1 (object id 43932)

0 TABLE ACCESS BY INDEX ROWID I_XJ_EXSHARE_SECTION_J

0 INDEX UNIQUE SCAN I_XJ_X_1 (object id 1167486)

0 NESTED LOOPS

0 TABLE ACCESS BY INDEX ROWID C_IN_INSTRUMENT

0 INDEX UNIQUE SCAN C_IN_X_1 (object id 43932)

0 TABLE ACCESS BY INDEX ROWID I_XJ_EXSHARE_SECTION_J

0 INDEX UNIQUE SCAN I_XJ_X_1 (object id 1167486)

Rows Execution Plan

------- ---------------------------------------------------

0 UPDATE STATEMENT GOAL: CHOOSE

0 UPDATE OF 'C_INRD_INS_REDEMPTION'

0 FILTER

103779 TABLE ACCESS GOAL: ANALYZED (FULL) OF

'C_INRD_INS_REDEMPTION'

0 NESTED LOOPS

103395 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF

'C_IN_INSTRUMENT'

103480 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'C_IN_X_1'

(UNIQUE)

0 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF

'I_XJ_EXSHARE_SECTION_J'

0 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'I_XJ_X_1'

(UNIQUE)

0 NESTED LOOPS

0 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF

'C_IN_INSTRUMENT'

0 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'C_IN_X_1' (UNIQUE)

0 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF

'I_XJ_EXSHARE_SECTION_J'

0 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'I_XJ_X_1' (UNIQUE)

Elapsed times include waiting on following events:

Event waited on Times Max. Wait Total Waited

---------------------------------------- Waited ---------- ------------

global cache cr request 10959 0.43 6.86

db file scattered read 19 0.06 0.41

db file sequential read 13311 0.09 79.68

SQL*Net message to client 1 0.00 0.00

SQL*Net message from client 1 0.00 0.00

The above example shows that of the 93.15 seconds it took to execute the query 79.68 seconds were spent reading from disk (db file sequential read). The Rows column in the explain section gives you a clue where most of the work is being performed.

The above query was actually tuned by rewriting the UPDATE as a MERGE INTO statement. As the below shows this greatly reduced the amount of logical reads that were required:

MERGE into c_inrd_ins_redemption col1

USING (select inrd.rowid,

ixj.i_xj_file_date a,

DECODE(inrd.c_inrd_rdm_early_value,

ixj.i_xj_j4_early_value,

DECODE(ixj.i_xj_j4_early_value,

inrd.c_inrd_rdm_early_value,

ixj.i_xj_j4_early_value)) b,

ixj.i_xj_j1_redemption_type c

FROM c_inrd_ins_redemption inrd,

i_xj_exshare_section_j ixj,

c_in_instrument ins