In the previous post (Oracle TKProf Usage), we saw how to generate a SQL Trace and then how to format it using TKProf. In that post we create a trace for following SQL statement:-
select * from all_objects;
In this post we would interpret TKProf output of that SQL query. Following is the TKProf Output from previous post (Oracle TKProf Usage) that we are going to interpret:-
TKPROF: Release 12.2.0.1.0 - Development on Thu Dec 27 05:39:56 2018
Copyright (c) 1982, 2017, Oracle and/or its affiliates. All rights reserved.
Trace file: tracefile_10046.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
SQL ID: 4m94ckmu16f9k Plan Hash: 3910148636
select count(*)
from
dual
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.00 0 0 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 0 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=0 pr=0 pw=0 time=21 us starts=1)
1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=1 us starts=1 cost=2 size=0 card=1)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 1 0.00 0.00
SQLNet message to client 2 0.00 0.00 SQLNet message from client 2 10.63 10.63
TKProf output file mainly has following sections:-
1. Tabular Statistics
2. Row Source Operations
3. Wait Event Information
We’ll study each section individually.
Section 1: Tabular Statistics:-
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.00 0 0 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 0 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 1
To understand these statistics we should understand following CALLS.
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. ForINSERT,UPDATE, andDELETEstatements, this modifies the data. ForSELECTstatements, this identifies the selected rows.FETCH:Retrieves rows returned by a query. Fetches are only performed forSELECTstatements.
The other columns of the TKProf output are combined statistics for all parses, all executes, and all fetches of a statement. All column names are self explanatory but just to give a brief idea:-
count: It is the number of times a call (parse/execute/fetch) was performed.
cpu: Total CPU time in seconds
elapsed: Total elapsed time in seconds
disk: Total number of data blocks physically read from the data files on disk.
query: Total number of buffers retrieved in consistent mode.
current: Total number of buffers retrieved in current mode.
rows: Total number of rows processed by the SQL statement.
Sum of query & current columns is the total number of buffers accessed i.e. LIOs.
In this section, we should first look if any operation that is taking high number of cpu times. Or if we have high number of block reads i.e. query column, specially if the block read LIOs are very high compared to number of rows fetched. Another important thing is to see if there is lot of hard parsing which can be seen from count of parse call and the number of times it was hard parsed i.e. misses in library cache. All these things give a sense if there is something wrong with query or not and if there is a problem then where ? I would try to include some examples of Tabular Statistics in subsequent posts for scenarios where we have some problem with library cache or buffer cache etc.
Section 2: Row Source Operations
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=0 pr=0 pw=0 time=21 us starts=1)
1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=1 us starts=1 cost=2 size=0 card=1)
Where cr is consistent reads, pr is physical reads, pw is physical writes, time is time in microseconds.
From Tabular Statistics we can understand if there is any problem with the query and then we can refer to Row Source Operations to see what operations are costly.
Section 3: Wait Event Information
We know if there is problem with a hint about the problem area from tabular statistics and the most costly operation from row source operation, now we can get the details where this query is waiting from wait event information.
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 1 0.00 0.00
SQLNet message to client 2 0.00 0.00 SQLNet message from client 2 10.63 10.63
This is another important section of TKProf output file as it gives us the details on the wait events on which the query is waiting. We can use Wait Event Information and link it to the theory deduced from tabular statistics to confirm the bottleneck of the query. From this information we can either try to reduce the cause for the waits or from row source information see if any other alternate access method can be used.
Oracle Database Internal Mechanism 