Using TKPROF and Explain Plan with Oracle -- Contents

• Oracle TRACE Utility
• Simple Steps for TRACE with a Simple Query
• The Sections of a TRACE Output
• The SQL Statement
• The Statistics Section
• Information Section
• The EXPLAIN PLAN
• A More Complex TKPROF Output
• Using EXPLAIN PLAN Alone
• An Additional EXPLAIN PLAN Example for a Simple Query
• EXPLAIN PLAN--Read It Top to Bottom or Bottom to Top?
• Reading the EXPLAIN PLAN
• Setting AUTOTRACE On

Oracle TRACE Utility

• TRACE runs the query and generates statistics about an Oracle query that is executed.
• TRACE helps developers analyze every section of a query.

1. Set the following init.ora parameters:

     TIMED.STATISTICS = TRUE
     MAX_DUMP_FILE_SIZE = 2000000 (Not 2M)
     USER_DUMP_DEST = /oracle8/rich_trc
     

   In Oracle7, the database must be shut down and restarted for these parameters to take effect. In Oracle8, the TIMED_STATISTICS parameter may be set via an ALTER SESSION (for an individual session) or ALTER SYSTEM (for the entire system) command. The USER_DUMP_DEST specifies the location to put the files and the MAX_DUMP_FILE_SIZE specifies the maximum file size.
2. Enable TRACE for a SQL*Plus session (this starts TRACing for an individual session):

     alter session set SQL_TRACE true;
     

3. Run the query to be TRACEd:

     select    table_name,
               owner, 
               initial_extent,
               uniqueness
     from	    ind2
     where	    owner || '' = 'SCOTT';
     --    (Note: An index on "OWNER" is suppressed)
     

4. Disable TRACE for the SQL*Plus session:

     alter session set SQL_TRACE false;
     

5. You can also enable TRACE for all sessions by setting the SQLTRACE parameter in the init.ora. You must shut down and restart the database for this to take effect. This is not suggested!

     SQL_TRACE = TRUE
     

   After running TRACE, your output file will look something like the following:

     5_19554.trc
     

   TIP Setting TIMED_STATISTICS=TRUE in the init.ora will begin TRACing upon the user's command. But, be careful; setting SQLTRACE=TRUE in the init.ora will cause the entire system and all queries to be TRACEd and could cause performance degradations.
6. Run TKPROF to put the TRACE file into readable format:

     tkprof 5_19554.trc rich2.prf explain=system/manager
     

   The TKPROF utility translates the TRACE file generated by the SQLTRACE facility to a readable format. You can run TKPROF against a TRACE file that you have previously created, or you can run it while the program that is creating the TRACE file is still running. Options for TKPROF are listed next.

     tkprof tracefile output_file [sort = parameters]
     [print =number] [explain=username/password@sid]
     

   Command-Line Options:

   TRACEfile

   The name of the TRACE file containing the statistics by SQL_TRACE.

   output_file

   The name of the file where TKPROF writes its output.

   SORT= parameters

   The order in which to display the statements in the output. There are about 20 different options for sorting the output-you can even combine these options.

   PRINT=number

   The number of statements to include in the output. included, TKPROF will list all statements in the output.

   EXPLAIN=username/password@sid

   Run the EXPLAIN PLAN on the user's SQL statements in the TRACE file. This option will create a PLAN_TABLE of its own, so the user will need to have privileges to create the table and space in which to create it. When TKPROF is finished, this table is dropped.

   New options in 7.3+:

   INSERT= filename

   This option creates a script to create a table and store the TRACE file statistics for each SQL statement TRACEd.

   RECORD= filename

   This option will produce a file of all the user's SQL statements.

   SYS= YES/NO

   This option allows the user to request the recursive SQL statements not be displayed in the output. The default is set to YES.

   SORT= parameters

   There is a tremendous number of sorting options that are available. My favorites are FCHCPU (CPU time of fetch), FCHDSK (disk reads for fetch), FCHCU and FCHQRY (memory reads for fetch), FCH ROW (number of rows fetched), EXEDSK (disk reads during execute), EXECU and EXEQRY (memory reads during execute), EXEROW (rows processed during execute), EXECPU (execute CPU time), and PRSCNT (times parsed).

   TIP

   The TKPROF utility puts a TRACEd output into a readable format. Without running TKPROF, it would be difficult to read the output of a TRACE. By specifying "explain=username/password" (noted earlier), we are able to get the EXPLAIN PLAN execution path in addition to the execution statistics of the query.

7. The output of the file rich2.prf (query with the index suppressed):

  select    table_name,
            owner,
            initial_extent,
            uniqueness
  from      ind2
  where     owner = 'SCOTT';

	count	cpu	elap	disk	query	current	  rows

Parse:	    1     1        2       0        0         0
Execute:    1     0        0       0        0         2      0
Fetch:	    2    69      113     142      430         0     36
  

Execution Plan (no index used):

TABLE ACCESS (FULL) OF 'IND2'
  

The output shows 142 disk reads and 430 memory reads (query + current). Having such a high number of disk reads compared to physical reads is certainly a potential problem. The execution path shows a full table scan confirming that we may have a potential problem.

TIP A TRACEd query with a large number of physical reads usually indicates a missing index. The disk column indicates the physical reads (usually where an index is not used) and the query added to the current columns indicates the memory reads (usually reads where an index is being used).

8. Here's what happens when I rerun the query (after restarting the system) to be TRACEd, now using an index on the owner table:

     select    table_name,
               owner,
               initial_extent,
               uniqueness
     from      ind2
     where     owner = 'SCOTT';
     (The index on "OWNER" is not suppressed)
   
   	count	cpu	elap	disk	query	current	  rows
   
   Parse:	    2     0        0       0        0         0
   Execute:    2     0        0       0        0         0      0
   Fetch:	    4     6        6       0      148         0     72 
     

   Execution Plan (index used):

   TABLE ACCESS (BY ROWID) OF 'IND2'
     INDEX (RANGE SCAN) OF 'IND2_1' (NON-UNIQUE)
     

   TIP

   A TRACEd query output with only memory reads (query-consistent reads) indicates that an index is being used.

count

The number of times this type of call was made.

cpu

The total CPU time for all of the calls of this type for this statement. If the TIMED_STATISTICS parameter in the init.ora is not set to TRUE, this statistic and the elapsed statistic will be 0.

elapsed

The total elapsed time for this call.

disk

The total number of data blocks retrieved from disk to satisfy this call.

query

The total number of data buffers retrieved from memory for this type SELECT statements usually retrieve buffers in this mode.

current

The total number of data buffers retrieved from memory for this type of call. UPDATE, INSERT, or DELETE the usual access buffers in this mode.

rows

The total number of rows processed by this statement. The rows statements will appear in the row of Fetch statistics. INSERTS, UPDATES, and DELETES will appear in the execute row.

It is also possible that there is only one line of the execution plan that is processing a large number of rows compared to the rest of the statement. This can be caused by full table scans or the use of a bad index.

A More Complex TKPROF Output

select    Item_Item_Id, InitCap( Item_Description )
from      Item
where     Item_Classification = 1
and       Item_Item_Id Between 1000000 And 2700000
and       Item_Item_Id Not In ( Select Invitem_Item_Id
          from  Inventory_Item
          where Invitem_Location_Id = '405')

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      27   20.87     21.24       0      4408         0   399
Totals     29   20.87     21.24       0      4408         0   399

Misses in library cache during parse: 0
Optimizer hint: CHOOSE
Parsing user id: 106  (C12462)

Rows	  Execution Plan
0	     SELECT STATEMENT	OPTIMIZER HINT: CHOOSE
572	 	 FILTER
598		     TABLE ACCESS (BY ROWID) OF 'ITEM'
599			INDEX (RANGE SCAN) OF 'ITEM_PK' (UNIQUE)
278790			INDEX (RANGE SCAN) OF 'INVITEM_PK' (UNIQUE)

Problems	Solutions
High numbers for the parsing	The SHARED_POOL_SIZE may need to be increased.
The disk reads are very high	Indexes are not used or may not exist.
The "query" and/or "current" (memory reads) are very high	Indexes may be on columns with high cardinality (columns where an individual value generally makes up a large percentage of the table). Removing or suppressing the index may increase performance.
The parse elapse time is high	There may be a problem with the number of open cursors.
The number of rows processed by a row in the EXPLAIN PLAN is high compared to the other rows	This could be a sign of an index with a poor distribution distinct keys (unique values for a column). Or this could also be a sign of a poorly written statement.
If the number of misses in the library cache during parse is greater than 1	This is an indication that the statement had to be reloaded. You may need to increase the SHARED_POOL_SIZE in the init.ora.

Using EXPLAIN PLAN Alone

Q.	Why use EXPLAIN PLAN without TRACE?
A.	The statement is not executed; it only shows what will happen if the statement is executed.
Q.	When do you use EXPLAIN PLAN without TRACE?
A.	When the query will take exceptionally long to run.

The following diagram demonstrates the procedures for running TRACE versus EXPLAIN PLAN:

TRACE It takes four hours to TRACE a query that takes four hours to run. Set up Init.ora Parameters Create PLAN_TABLE table Run Query Statement is executed PLAN_TABLE is populated Run TKPROF Output shows disk and memory reads in addition to EXPLAIN PLAN output

EXPLAIN PLAN It takes less than a minute to EXPLAIN PLAN a query that takes four hours to run. Create PLAN_TABLE table Explain Query PLAN_TABLE is populated Query PLAN_TABLE Output shows EXPLAIN PLAN

Q.

How do I use EXPLAIN PLAN by itself

A.

1. Find the script; it is usually in the ORACLE_HOME/rdbms/admin:

   "utlxplan.sql"

2. Execute the script XPLAINPL.sql in SQL*Plus:

           @utlxplan
           

   This creates the PLAN_TABLE for the user executing the script. You may create your own PLAN_TABLE, but use Oracle"s syntax or else!!!
3. Run EXPLAIN PLAN for the query to be optimized:

           explain plan for 
           select CUSTOMER_NUMBER 
           from   CUSTOMER
           where  CUSTOMER_NUMBER = 111;
   
           Explained.
           

4. EXPLAIN PLAN for the query to be optimized (using a tag for the statement):

   	explain plan 
   	set statement_id = 'CUSTOMER' for 
   	select 	CUSTOMER_NUMBER
   	from	CUSTOMER
   	where	CUSTOMER_NUMBER = 111;
   	

   TIP Use the SET STATEMENT_ID = "your identifier" when the PLAN_TABLE will be populated by many different developers. I rarely use the SET STATEMENT_ID statement. Instead, I EXPLAIN PLAN a query, look at the output, and then delete from the PLAN_TABLE table. I continue to do this (making changes to the query), until I see an execution plan that I think will be favorable. I then run the query to see if the performance has been improved. If multiple developers/DBAs are using the same PLAN_TABLE, then the SET STATEMENT_ID will be essential to identifying a statement.

5. Select the output from the PLAN_TABLE table:

   	select	operation,
   		options, 
   		object_name, 
   		id, 
   		parent_id
   	from	plan_table
   	where 	statement_id = 'CUSTOMER';
   
   	Operation	  Options	Object Name	ID	Parent
   	select statement 				 0
   	Table Access	  By ROWID	Customer	 1
   	Index	  	  Range Scan	CUST_IDX	 2	     1
           

   TIP Use EXPLAIN PLAN instead of TRACE so that you don't have to wait for the query to run. EXPLAIN PLAN will show the path of a query without actually running the query. Use TRACE only for multi-query batch jobs to find out which of the many queries in the batch job are slow.

1. Run the query with the EXPLAIN syntax embedded prior to the query:

     explain plan
     set statement_id ='query 1' for
     select  customer_number,
     	  name
   	  customer
     from 	  customer
     where	  customer_number = '111';
     

2. Retrieve the output of EXPLAIN PLAN by querying the PLAN_TABLE:

   To retrieve the information for viewing, a SQL statement must be executed. Two scripts provided in the Oracle documentation are displayed in this step and in step 3, along with the results of each based on the previous EXPLAIN PLAN command. Note that this example varies from the last example. The customer_number column is an indexed number field, which in the second example is suppressed (by forcing a to_char) because of a data type mismatch ('111' is in quotes). In the first example, I treated the customer_number column correctly as a number field (111 is not in quotes).

     select  operation, 
   	  options,
   	  object_name, 
   	  id, 
   	  parent_id, 
   	  position
     from	  plan_table
     where	  statement_id = 'query 1'
     order by id; 
   
   Operation	  Options	Object Name		ID	Parent
   select statement 				 	 0
   Table Access	  Full		Customer_Information	 1
     

3. Retrieving a more intuitive and easy to read output of EXPLAIN PLAN:

   select 	lpad(' ', 2*(level-1)) || operation || ' ' || options || ' ' ||
   	object_name || ' ' || decode(id, 0, 'Cost = ' || position) 'Query Plan'	
   from	plan_table
   start	with id = 0
   and	statement_id = 'query 1'
   connect by prior id = parent_id
   and	statement_id = 'query 1';
     

   Output:

   Query Plan
   
   select statement	Cost=220
       Table Access Full Customer
     

The SQL statement should be placed after the FOR clause of the EXPLAIN PLAN:

delete	from plan_table;
explain plan
set 	statement_id = 'SQL1' for
select	to_char(sysdate, 'MM/DD/YY HH:MM AM'), 
	to_char((trunc((sysdate -4, -1), 'day') +1), 'DD-MON-YY'),
from	bk, ee
where	bk_shift_date >= to_char((trunc(( sysdate - 4 - 1), 'day' + 1),
                         'DD-MON-YY')
and	bk_shift_date <= to_char((sysdate - 4), 'DD-MON-YY')
and	bk_empno = ee_empno (+)
and	substr( ee_hierarchy_code, 1, 3) in ('PNA', 'PNB', 'PNC',
                                             'PND', 'PNE', 'PNF')
order by ee_job_group, 
	 bk_empno,
	 bk_shift_date
/
select	LPad(' ', 2*(Level-1)) || Level || '.' || nvl(Position,0) ||
        ' ' || Operation || ' ' || Options || ' ' || Object_Name ||
        ' ' || Object_Type || ' ' || Decode(id, 0, Statement_id ||  
        'Cost = ' || Position) || Other || ' ' || 
	Object_Node "Query Plan"
from	plan_table
start	with id = 0
and 	statement_id = 'SQL1'
connect by prior id = parent_id
and	statement_id = 'SQL1'
/

Query Plan
1.0 SELECT STATEMENT	SQL1	Cost =
    2.1 SORT ORDER BY
        3.1 FILTER
            4.1 NESTED LOOPS OUTER
                5.1 TABLE ACCESS BY ROWID BK
                    6.1 INDEX RANGE SCAN I_BK_06 NON-UNIQUE
                5.2 TABLE ACCESS BY ROWID EE
                    6.1 INDEX UNIQUE SCAN I_EE_01 UNIQUE

Step	Action
6.1	This is the index range scan of I_BK_06. This is the first step. This index is on the bk_shift_dt column. This step performs a scan of this index to produce a list of ROWIDs that fall between the two dates.
5.1	Retrieve the rows from the BK table.
6.1	Scan of the I_EE_01 index. This index is on the ee_empno column. Using the bk_empno retrieved from the previous step, this index is scanned to retrieve the ROWIDs to produce a list of the ee_empnos that match the bk_empnos.
5.2	Retrieve the rows from the EE table.
4.1	NESTED LOOP. The two lists are joined, producing one list.
3.1	FILTER. The rest of the conditions of the WHERE clause are applied.
2.1	SORT ORDER BY. The remaining rows are sorted according to the ORDER BY clause.
1.0	This tells what type of statement it is.

TIP Whether the EXPLAIN PLAN is read from top to bottom or from the bottom to the top is dependent entirely on the query used to select information from the PLAN_TABLE table. Both methods of reading the query may be correct, given the query selecting the information is correctly structured.

Setting AUTOTRACE On

SET AUTOTRACE ON
select	count(name)
from	emp7
where 	name = 'branches';

COUNT(NAME)
100

Query Plan
   0	  SELECT STATEMENT Optimizer=CHOOSE
   1    0   SORT (AGGREDATE)
   2    1     INDEX (RANGE SCAN) OF 'EMP7_I1' (NON-UNIQUE)

Statistics
	0  recursive calls
	0  db block gets
	1  consistent gets
	1  physical reads
	0  redo size
      223  bytes sent via SQL*Net to client
      274  bytes recd via SQL*Net from client
	2  SQL*Net roundtrips to/from client
	1  sorts (memory)
	0  sorts (disk)
	1  rows processed