How to read Tkprof oracle Database performance tuning

 

 

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. 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. 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.