Hungry DBA .com for DBAs who like food

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,

                     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)) b,

              ixj.i_xj_j1_redemption_type c

         FROM c_inrd_ins_redemption  inrd,

              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

          AND ins.c_in_current_mkr = 'Y'

          AND ixj.i_xj_rdm_early_date IS NOT NULL

          AND inrd.c_inrd_rdm_early_date = ixj.i_xj_rdm_early_date) t1

ON (col1.rowid = t1.rowid)

WHEN matched then

  update

     set col1.c_inrd_input_date      = t1.a,

         col1.c_inrd_rdm_early_value = t1.b,

         col1.c_inrd_exsh_j1         = t1.c

WHEN not matched then

  insert (c_inrd_exsh_j1) values (null)

call     count       cpu    elapsed       disk      query    current        rows

------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse        1      0.01       0.01          0          0          0           0 Execute      1      0.00       0.00          0          3          0           0 Fetch        0      0.00       0.00          0          0          0           0

------- ------  -------- ---------- ---------- ---------- ----------  ---------- total        2      0.01       0.01          0          3          0           0

Misses in library cache during parse: 1

Optimizer goal: CHOOSE

Parsing user id: 6055  (INTERFACE)

Rows     Row Source Operation

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

      2  MERGE 

      0   VIEW 

      0    NESTED LOOPS OUTER

      0     NESTED LOOPS 

      0      NESTED LOOPS 

      0       TABLE ACCESS FULL I_XJ_EXSHARE_SECTION_J

      0       TABLE ACCESS BY INDEX ROWID C_IN_INSTRUMENT

      0        INDEX RANGE SCAN C_IN_X_2 (object id 43935)

      0      TABLE ACCESS BY INDEX ROWID C_INRD_INS_REDEMPTION

      0       INDEX UNIQUE SCAN C_INRD_X_1 (object id 42684)

      0     TABLE ACCESS BY USER ROWID C_INRD_INS_REDEMPTION

Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total Waited

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

  SQL*Net message to client                       1        0.00          0.00

  SQL*Net message from client                     1        0.00          0.00

Note: The WHEN NOT MATCHED condition would never be met so just contains a dummy insert.

Row Source Operations in tkprof formatted trace files

Row source operations provide the number of rows processed for each operation executed on the rows and additional row source information, such as physical reads and writes. The following is a sample:

Rows     Row Source Operation

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

      0  DELETE  (cr=43141 r=266947 w=25854 time=60235565 us)

  28144   HASH JOIN ANTI (cr=43057 r=262332 w=25854 time=48830056 us)

  51427    TABLE ACCESS FULL STATS$SQLTEXT (cr=3465 r=3463 w=0 time=865083 us)

 647529    INDEX FAST FULL SCAN STATS$SQL_SUMMARY_PK

                      (cr=39592 r=39325 w=0 time=10522877 us) (object id 7409)

In this sample TKPROF output, note the following under the Row Source Operation column:

cr specifies consistent reads performed by the row source

r specifies physical reads performed by the row source

w specifies physical writes performed by the row source time specifies time in microseconds

Row source operations only appear in trace files if the relevant cursor was closed before the tracing ended.  Therefore if you want to capture Row Source Operations make sure the relevant session being traced is closed cleanly before ending tracing and formatting the file using tkprof.