Analyzing TKPROF Files

 https://expertoracle.com/2017/11/24/performance-tuning-basics-7-trace-and-tkprof-part-3-analyzing-tkprof-files/

Overall the structure of the tkprof body output is:

• SQL Statement
• Parse/Execute/Fetch statistics and timings
• Library Cache information
• Row source plan
• Events waited for by the statement

Please note that this is Tkprof doesn’t contains the wait event information as the trace that was applied was not level 8 (with waits) trace.

Here SQL_ID is 6j28xhmyb12m7 and plan hash value assigned to this SQL_ID is 2622831843. Now go through below table to understand what each term means in the above tkprof portion

TERM	UNIT OF MEASURE	MEANING
Call	Not Applicable	Statistics for each cursor’s activity are divided in to 3 areas: Parse/Execute/Fetch. A total is also calculated.
Parse	Number of times	Statistics from parsing the cursor are shown. This step checks for proper security authorization and checks for the existence of tables, columns, and other referenced objects and translates the SQL statement into an execution plan.The parses might be HARD or SOFT
Execute	Number of times	statistics for the execution phase of a cursor. For INSERT, UPDATE, and DELETE statements, this modifies the data. For SELECT statements, this identifies the selected rows.
Fetch	Number of times	Statistics for actually fetching the rows. Fetches are only performed for SELECT statements.
count	Number of times	Number of times each individual activity like parsed, executed, or fetched has been performed on this particular cursor. You should investigate why the counts are high. Specially if you see high number of parses then it is very important to find the cause.
cpu	Seconds	The total CPU time in seconds for all parse, execute, or fetch calls. Remember that TIMED_STATISTICS database parameter must be enabled to populate this information or else it will show 0 here.
Elapsed	Seconds	Total elapsed time in seconds for all parse, execute, or fetch calls.It is the time taken to identify and modify rows during statement execution on the server. If this value is higher than CPU time, then you should review the wait events sections in the tkprof for the SQL to understand where the waits happened.
disk	Number of Data Blocks	Total number of data blocks physically read for all parse, execute, or fetch calls. Generally it would be preferable for blocks to be read from the buffer cache rather than disk.
query	Number of Data Blocks	This is Logical read. Total number of buffers retrieved in consistent mode for all parse, execute, or fetch calls.  A Consistent mode buffer is one that has been generated to give a consistent read snapshot for a long running transaction. Consistent read means “get the block as it appeared at the beginning of our statement, using rollback data if needed to undo changes”. Usually, this type of logical read is used by queries.
current	Number of Data Blocks	This is Logical read. Total number of buffers retrieved in current mode. Current mode means “get the as it exists RIGHT NOW. No need of applying any rollback data etc”. Buffers are retrieved in current mode for statements such as INSERT, UPDATE, and DELETE.
rows	Number of rows	Total number of rows processed by the SQL statement. This total does not include rows processed by subqueries of the SQL statement. For SELECT statements, the number of rows returned appears for the fetch step For UPDATE, DELETE, and INSERT statements, the number of rows processed appears for the execute step.
total	number of times	Sum of all operations
Misses in library cache during parse	number of times	Indicates that the the statement was found (soft parse) or not found (hard parse) in the library cache. If it is 0 then it means soft parse happened as there was no miss. If it is 1 then it means one hard parse happenedIf there are a high number of parses per execution, this could indicate the lack of use of bind variables in SQL statements or poor cursor reuse. So our goal is that misses should be minimum or zero.
Misses in library cache during execute	number of times	It means that the SQL text found but cursor not valid for reuse. Either object invalidation through DDL or different objects referenced/privileges meaning a new child cursor must be spawned. Misses while about to execute the plan and found it missing/invalid in library cache. If no hard parse occurred during execute calls, that specific line is missing.
Optimizer mode	Not Applicable	First_rows mode is a cost-based optimizer mode that will return rows as soon as possible, even if the overall query runs longer or consumes more resources.Such setting is good when user wants to see the result quicker. This optimizer mode favors index scans over full table scans. All_rows mode ensures that the overall query time is minimized, even if it takes longer to receive the first row. Default optimizer_mode is all_rows as can be seen in above example trace.
Parsing user id	Not Applicable	Database user id which was used to do parsing. If you specified the “explain” option also when generating TKPROF then username will also be mentioned along with userid.
Recursive Depth	Number	Recursive depth is provided only for recursive SQL statements. SQL statements directly executed by an application have a depth of 0. Recursive depth 1 here indicates that the UPDATE is a child of some other piece of code with depth n-1 (in this case 0). For PL/SQL block, which isn’t executed by the database recursively, the recursive depth will not be shown as it will be 0.
Number of plan statistics captured	Number	It tells you how many executions Oracle recorded information about the plan. It uses these to populate the “Rows (1st) Rows (avg) Rows (max)” columns in the row source operation
Row source plan	Not Applicable	This section displays the access path used at execution time for each statement along with timing and actual row counts returned by each step in the plan. This can be very useful for a number of reasons. Row source plans are generated from STAT lines in the raw trace. STAT lines are written to trace every now and then, but sometimes, if the cursor is not closed cleanly then STAT lines will not be recorded and then the row source plan will not be displayed. Setting SQL_TRACE to false DOES NOT close all cursors. Cursors are closed in SQL*Plus immediately after execution. The safest way to close all cursors is to cleanly exit the session in question.
Rows (1st)	Number of rows	While database version before 11.2.0.2 used to provide a single column (“Rows”) for reporting the number of rows returned by every row source operation, 11.2.0.2 provides three columns (“Rows (1st)”, “Rows (avg)” and “Rows (max)”). Number of rows returned on the first execution
Rows (avg)	Number of rows	Average number of rows returned for all execution
Rows (max)	Number of rows	Maximum number of rows returned for all executions
Row Source Operation	Not Applicable	“Row Source Operation” is the actual execution plan written in the trace file by the server process. Under “Row Source Operation” Heading first thing you will see is the operation type, example “Index range Scan” ” Nested Loops” “Select..” etc. After that in the brackets you will find the IO statistics like: cr = number of blocks read with logical reads in consistent mode. pr= number of blocks read with physical reads from the disk. pw= number of blocks written with physical writes to the disk. time = shows the cumulative elapsed time for the step and the steps that preceded it in microseconds (µs: 1/1000000 of a second).  This information is very useful when looking for the point in an access path that takes all the time. By looking for the point at where the majority of the time originates it is possible to narrow down a number of problems. cost =  estimated cost of the operation used by the optimizer for internal comparison size = estimated space usage of the operation in bytes card = estimated cardinality (number of rows returned) of that particular operation These statistics can be useful in identifying steps that read or write a particularly large proportion of the overall data. IMPORTANT: if the explain argument is specified during tkprof creation then you will also see the second Execution Plan which is generated by TKPROF. Since the second execution plan is generated by TKPORF WITHOUT EXECUTING THE SQL so that second execution plan may not be same as the first execution plan (“Row Source Operation”). Always refer “Row Source Operation” execution plan as that is the actual execution plan which was followed when the SQL was actually running.
Events waited for by the statement	Not Applicable	Although this section is not displayed in the above sample trace as we didn’t include the waits option while generating the trace file. This section displays all wait events that a statement has waited for during the tracing. This section can be very useful when used in conjunction with the statistics and row source information for tracking down the causes of problems associated with long wait times. High numbers of waits or waits with a long total duration may be candidates for investigation dependent on the wait itself.