How do we make trace file readable by using TKPROF?

TKPROF is Oracle utility to convert the Orace trace file into readable format. It is one of the most useful utility available to DBAs for diagnosing performance issues

TKPROF syntax is:

tkprof filename1 filename2 [waits=yesno] [sort=option] [print=n]
[aggregate=yesno] [insert=filename3] [sys=yesno] [table=schema.table]
[explain=user/password] [record=filename4] [width=n]

Here is the example to use the TKPROF utility.

tkprof dmdprod_ora_11154.trc traceoutput.txt sys=no

TKPROF command line options.

Print – This option will list number SQL statement in trace file. We can use this command when we want to list only specific number sql statement. This command is very useful when combining SORT option to list only top N statement by CPU, disk access etc.

Aggregate – When it is YES, then combine the statistics from multiple user execution for the same SQL statement.

Waits - It is used to record summary for any wait events found in the trace file

Insert – Create file to load the trace info into table for further processing. This will be useful for future analysis.

Sys – If it is NO, then it will exclude SQL statement which is executed by SYS schema. The default value is YES.

Table – It is used to load the explain plan info into table. We need to specify the schema name and table name to load the explain plan info. The table old data will be deleted when we use this option. If the table does not exist, then oracle will create the table to load the data.

Record – It is used to store all the non recursive SQL statement from the trace file. This statement can be used if we want to log the SQL statement in separate file.

Explain – It will be used if we want to generate the pre determined execution plan in trace file. When you use this option, you will see execution plan as well as Real plan in trace file. Execution plan is pre execution plan(like asking direction to home), Real Plan(like showing direction how you got home. In trace file, Real Plan will be displayed as Row source generation).

Sort – It will be useful if we want to see the top SQL which are consumed the most resources. Resource like CPU usage, disk usage etc.

The following are the data elements available for sorting:

. prscnt – The number of times the SQL was parsed.
· prscpu – The CPU time spent parsing.
· prsela – The elapsed time spent parsing the SQL.
· prsdsk – The number of physical reads required for the parse.
· prsmis – The number of consistent block reads required for the parse.
· prscu – The number of current block reads required for the parse.
· execnt – The number of times the SQL statement was executed.
· execpu – The CPU time spent executing the SQL.
· exeela – The elapsed time spent executing the SQL.
· exedsk – The number of physical reads during execution.
· exeqry – The number of consistent block reads during execution.
· execu – The number of current block reads during execution.
· exerow – The number of rows processed during execution.
· exemis – The number of library cache misses during execution.
· fchcnt – The number of fetches performed.
· fchcpu – The CPU time spent fetching rows.
· fchela – The elapsed time spent fetching rows.
· fchdsk – The number of physical disk reads during the fetch.
· fchqry – The number of consistent block reads during the fetch.
· fchcu – The number of current block reads during the fetch.
· fchrow – The number of rows fetched for the query.

TKPROF output

update COLLECTION set body=:1, control_no=:2, STATE=:3,
created_dt=:4, author=:5
where
id=:6
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- -------------------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 55.99 145.55 1057 9495719 8238 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- -------------------
total 2 55.99 145.56 1057 9495719 8238 1

Misses in library cache during parse: 1

Optimizer goal: FIRST_ROWS
Parsing user id: 67
Rows Row Source Operation
------- --------------------------------------------------------------------------------
1 UPDATE
1 TABLE ACCESS BY INDEX ROWID MWS_COLLECTION
1 INDEX UNIQUE SCAN PK_MWS_COLLECTION (object id 139890)
********************************************************************************

1. Parse – Parse does syntax checks, permissions, and all object dependencies.
2. Execute – The actual execution of the statement.
3. Fetch – The number of rows returned for a SELECT statement

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

V$SQLPLAN Versus EXPLAIN PLAN

EXPLAIN PLAN and v$sql_plan are providing same type of information. EXPLAIN PLAN command is used to display the execution plan of a SQL statement without actually executing it. But v$sql_plan dictionary view is used to show the execution plan of the SQL statement that has been compiled into a cursor in the cache.

What should DBA look in tkprof output file?
1. Compare the number of parses to number of executions. A Well defined system will have one parse per n executions.
2. Check any SQL do not use bind variables
3. Check if there is any Full table scan, Multiple disk reads, high CPU consumption.

Cursor Sharing in oracle

Before oracle8.1.6, When application sends a SQL, oracle first check the shared pool to see if there is an exact statement in the shared pool. If the exact statement is not found, then a hard parse is necessary to generate the executable form of the statement. Setting CURSOR_SHARING to EXACT allows SQL statements to share the SQL area only when their texts match exactly. This is the default behavior. Using this setting, similar statements cannot shared; only textually exact statements can be shared

Let me demonstrate CURSOR_SHARING=EXACT

SQL> select count(*),empno from emphist group by empno;

COUNT(*) EMPNO
---------- ----------
1 7369
1 7902
4194304 7934

SQL> create index idxemphist on emphist(empno);

Index created.

SQL> execute DBMS_STATS.GATHER_TABLE_STATS(OWNNAME => 'SCOTT', TABNAME => 'EMPHIST',ESTIMATE_PERCENT
=> 10, METHOD_OPT => 'FOR ALL COLUMNS SIZE 1',CASCADE => TRUE);

PL/SQL procedure successfully completed.

SQL> alter system flush shared_pool;

System altered.
SQL> set autotrace traceonly explain

SQL> alter session set cursor_sharing='EXACT';

Session altered.

SQL> select count(ename) from emphist where empno=7934;

COUNT(ENAME)
------------
4194304

Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=2297 Card=1 Bytes=11
)

1 0 SORT (AGGREGATE)
2 1 TABLE ACCESS (FULL) OF 'EMPHIST' (Cost=2297 Card=4193270
Bytes=46125970)

SQL> select count(ename) from emphist where empno=7902;

COUNT(ENAME)
------------
1
Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=4 Card=1 Bytes=11)
1 0 SORT (AGGREGATE)
2 1 TABLE ACCESS (BY INDEX ROWID) OF 'EMPHIST' (Cost=4 Card=
1 Bytes=11)

3 2 INDEX (RANGE SCAN) OF 'IDXEMPHIST' (NON-UNIQUE) (Cost=
3 Card=1)

SQL> select count(ename) from emphist where empno=7902;

COUNT(ENAME)
------------
1

Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=4 Card=1 Bytes=11)
1 0 SORT (AGGREGATE)
2 1 TABLE ACCESS (BY INDEX ROWID) OF 'EMPHIST' (Cost=4 Card=
1 Bytes=11)

3 2 INDEX (RANGE SCAN) OF 'IDXEMPHIST' (NON-UNIQUE) (Cost=
3 Card=1)

SQL> select count(ename) from emphist where empno=7369;

COUNT(ENAME)
------------
1

Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=4 Card=1 Bytes=11)
1 0 SORT (AGGREGATE)
2 1 TABLE ACCESS (BY INDEX ROWID) OF 'EMPHIST' (Cost=4 Card=
1 Bytes=11)

3 2 INDEX (RANGE SCAN) OF 'IDXEMPHIST' (NON-UNIQUE) (Cost=
3 Card=1)

SQL> select count(ename) from emphist where empno=7369;

COUNT(ENAME)
------------
1

Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=4 Card=1 Bytes=11)
1 0 SORT (AGGREGATE)
2 1 TABLE ACCESS (BY INDEX ROWID) OF 'EMPHIST' (Cost=4 Card=
1 Bytes=11)

3 2 INDEX (RANGE SCAN) OF 'IDXEMPHIST' (NON-UNIQUE) (Cost=
3 Card=1)

SQL> set autotrace off
SQL> select sql_text
2 from v$sql
3 where sql_text like 'select count(ename) from emphist where empno=%';

SQL_TEXT
--------------------------------------------------------------------------------
select count(ename) from emphist where empno=7369
select count(ename) from emphist where empno=7902
select count(ename) from emphist where empno=7934

Conclusion : Oracle does not use bind variable and every unique SQL statement, execution plan will be generated. It forced to hardparse every uniqe SQL statement and it leads to consume lot of CPU cycles. Oracle can not hardparse hundreds of SQL statement concurrently and it end up waiting for shared pool. To overcome this problem, oracle introduced FORCE paramter to use bind variable.

In oracle8.1.6, Oracle introduced new parameter FORCE. This is accomplished by transforming the statement into a new one by replacing the literals with system generated bind variables. The problem with bind variables is that the optimizer cannot predict precise selectivity.

Using cursor_sharing = force will parse the FIRST sql statement loaded into memory and will use this execution plan for the subsequent similar sql statements. This might be a problem if the FIRST statement's literals have good selectivity but those of the subsequent statements don't. In this case the statements with poor selectivity will also use the index whereas a full table scan would perform better. However, if the firstly run statement doesn't have good selectivity and a full table scan is used, the subequent similar statements will also use FTS.

Let me demonstrate CURSOR_SHARING=FORCE

SQL> select count(ename) from employee where empno=7934;

COUNT(ENAME)
------------
2097152
SQL>

The below plan is extracted from tkprof output file. Optimizer use the FTS which is right choice.

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE
2097152 TABLE ACCESS FULL OBJ#(30800)

Let us run the another query and see the execution plan.

SQL> select count(ename) from employee where empno=7902;

COUNT(ENAME)
------------
1

SQL>

The below plan is extracted from tkprof output file. Optimizer again use the FTS for this subsequent query which is bad choice.

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE
1 TABLE ACCESS FULL OBJ#(30800)

SQL> select sql_text from v$sql
2 where sql_text like 'select count(ename) from emphist where empno=%';

SQL_TEXT
--------------------------------------------------------------------------------
select count(ename) from emphist where empno=:"SYS_B_0"

SQL>

Conclusion : Oracle generate only one plan and use for all the SQL code. This would turn the hard parse into soft parse. It would require fewer resource. FORCE option is good when the query table is not skewed and all the queries require same execution plan. But in real world, this is not a good option.

To overcome this problem, In Oracle9i we can use CURSOR_SHARING=SIMILAR setting which makes the right plan based on the statistics.

Let me demonstrate CURSOR_SHARING=SIMILAR

SQL> ALTER SYSTEM FLUSH SHARED_POOL;
System altered.
SQL>

SQL> select count(ename) from employee where empno=7934;

COUNT(ENAME)
------------
2097152

Let us run the query and see the actual execution plan. Optimizer use the FTS which is right choice.

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE
2097152 TABLE ACCESS FULL OBJ#(30800)


Let us run the another query and see the actual execution plan.

SQL> select count(ename) from employee where empno=7902;

COUNT(ENAME)
------------
1

SQL>

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE
1 TABLE ACCESS BY INDEX ROWID OBJ#(30800)
1 INDEX RANGE SCAN OBJ#(30801) (object id 30801)


SQL> select sql_text
2 from v$sql
3 where sql_text like 'select count(ename)%';

SQL_TEXT
--------------------------------------------------------------------------------
select count(ename) from emphist where empno=:"SYS_B_0"
select count(ename) from emphist where empno=:"SYS_B_0"
SQL>

Optimizer use the Index range scan which is right choice. Optimizer makes the right choice based on the statistics.

Conclusion : Optimizer replace the literal with bind variable and check if it requires different plan for the query based on the current statistics. If so then, optimizer mark the bind variable as unsafe and store the value in the signature of the query. Next time, user submit the query with the same bind variable value, then oracle resuse the plan. Optimizer would use the same execution plan based on the statistics if user submit the same query with different literal .

SIMILAR option resolve the issues which we had in EXACT. Exact does not use bind variable. But here it is using bind variable. In FORCE option, optimizer use the same execution plan for same query with different literal. But SIMILAR option, it use the different plan for the same query with different literal values based on the current statistics.

Please read the below link if you need more info.

http://www.oracle.com/technology/oramag/oracle/06-jan/o16asktom.html

Index Monitoring in oracle

Before oracle9i, monitoring the index is difficult one. For monitoring index, we need to run the explain plan and find the estimated execution plan to see if the index is used for the query. For instances, if we have multiple queries running in the application, then we have to run the explain plan for each query to find out the index usage.

Oracle9i has overcome this problem and easily identify the unused index. This feature helps us to remove unused index and reduce the database overhead.

Enable index

ALTER INDEX indexname MONITORING USAGE;

Disable index

ALTER INDEX indexname NOMINTORING USAGE;

Note: v$object_usage is gathering index monitoring information.

Here is the table structure for v$object_usage.

SQL> desc v$object_usage;
Name Type
----------------------- -------- ------------------------------
INDEX_NAME VARCHAR2(30) /* Name of the index*/
TABLE_NAME VARCHAR2(30) /* Name of the table*/
MONITORING VARCHAR2(3) /* Monitoring Turned on(YES/NO)*/
USED VARCHAR2(3) /* Index used (YES/NO) */
START_MONITORING VARCHAR2(19) /* Index monitoring start date*/
END_MONITORING VARCHAR2(19) /* Index monitoring end date. It will be null if the index is currently monitoring. It will be populated when we stop monitoring index*/
SQL>

Example for Index Monitoring

Step 1

SQL> show user
USER is "SCOTT"
SQL> select index_name from user_indexes where table_name='EMPLOYEE';

INDEX_NAME
------------------------------
IDX

SQL> alter index idx monitoring usage;

Index altered.


Step 2

Check the inforamation in v$object_usage.
SQL> ;
1 select monitoring,used,start_monitoring,end_monitoring from v$object_usage
2* where table_name='EMPLOYEE'
SQL> /

MON USE START_MONITORING END_MONITORING
--- --- ------------------- -------------------
YES NO 06/20/2008 10:59:33

SQL>

Step 3

Make use of index and check the v$object_usage.

SQL> select count(ename) from employee where empno=7902;

COUNT(ENAME)
------------
1

SQL> select monitoring,used,start_monitoring,end_monitoring from v$object_usage
2 where table_name='EMPLOYEE';

MON USE START_MONITORING END_MONITORING
--- --- ------------------- -------------------
YES YES 06/20/2008 10:59:33

SQL>

Step 4

The index is used and USED column in v$object_usage is updated YES. Now we disable the index.

SQL> alter index idx nomonitoring usage;

Index altered.
SQL> select monitoring,used,start_monitoring,end_monitoring from v$object_usage
2 where table_name='EMPLOYEE';

MON USE START_MONITORING END_MONITORING
--- --- ------------------- -------------------
NO YES 06/20/2008 10:59:33 06/20/2008 11:20:08

SQL>


Important Note:

Before removing unused index, Index monitoring should run for few months, batch process, year beginning reports, year end reports and make sure the index is not used anywhere. Then we can come to conclusion that the index is not used.

LOB & IOT cannot be monitored.

How do we enable autotrace in oracle?

We can set the autotrace in Oracle and we can see the explain plan for SELECT statement.

This topic is tested in the below oracle version in Windows OS.

Oracle9i Enterprise Edition Release 9.2.0.1.0 - Production
PL/SQL Release 9.2.0.1.0 - Production
CORE 9.2.0.1.0 Production
TNS for 32-bit Windows: Version 9.2.0.1.0 - Production
NLSRTL Version 9.2.0.1.0 - Production

If we don't set the autotrace, then we get the below error.

SQL> connect scott/tiger@dba1
Connected.
SQL> set autotrace on
SP2-0613: Unable to verify PLAN_TABLE format or existence
SP2-0611: Error enabling EXPLAIN report
SP2-0618: Cannot find the Session Identifier. Check PLUSTRACE role is enabled
SP2-0611: Error enabling STATISTICS report
SQL>

Here are the steps to resolve the error.

Step 1

Run the plustrace.sql file on sys schema.

In windows, the plustrace file is residing at @$ORACLE_HOME\sqlplus\admin\plustrce.sql
In UNIX, the plustrace file is residing at @$ORACLE_HOME/sqlplus/admin/plustrce.sql

SQL> start d:/oracle/ora92/sqlplus/admin/plustrce.sql
SQL>
SQL> drop role plustrace;
drop role plustrace
*
ERROR at line 1:
ORA-01919: role 'PLUSTRACE' does not exist


SQL> create role plustrace;

Role created.

SQL>
SQL> grant select on v_$sesstat to plustrace;

Grant succeeded.

SQL> grant select on v_$statname to plustrace;

Grant succeeded.

SQL> grant select on v_$session to plustrace;

Grant succeeded.

SQL> grant plustrace to dba with admin option;

Grant succeeded.

SQL>
SQL> set echo off
SQL>

Step 2

Grant the plustrace role to Scott schema.

SQL> connect sys/password@dba1 as sysdba
Connected.
SQL> grant plustrace to scott;

Grant succeeded.

SQL>

Step 3

Create the plan_table on sys schema and grant select privileges to Scott schema.

SQL> connect sys/password@dba1 as sysdba
Connected.
SQL> CREATE TABLE PLAN_TABLE (
2 statement_id varchar2(30),
3 plan_id number,
4 timestamp date,
5 remarks varchar2(4000),
6 operation varchar2(30),
7 options varchar2(255),
8 object_node varchar2(128),
9 object_owner varchar2(30),
10 object_name varchar2(30),
11 object_alias varchar2(65),
12 object_instance numeric,
13 object_type varchar2(30),
14 optimizer varchar2(255),
15 search_columns number,
16 id numeric,
17 parent_id numeric,
18 depth numeric,
19 position numeric,
20 cost numeric,
21 cardinality numeric,
22 bytes numeric,
23 other_tag varchar2(255),
24 partition_start varchar2(255),
25 partition_stop varchar2(255),
26 partition_id numeric,
27 other long,
28 distribution varchar2(30),
29 cpu_cost numeric,
30 io_cost numeric,
31 temp_space numeric,
32 access_predicates varchar2(4000),
33 filter_predicates varchar2(4000),
34 projection varchar2(4000),
35 time numeric,
36 qblock_name varchar2(30),
37 other_xml clob
38 );

Table created.

SQL> grant all on plan_table to scott;

Grant succeeded.

SQL>
Step 4

Create the synonym on Scott schema for plan_table which is created in sys schema.

SQL> connect scott/tiger@dba1
Connected.
SQL>
SQL> create synonym plan_table for sys.plan_table;

Synonym created.


Step 5

Connect the scott schema and test the autotrace.

SQL> set autotrace on
SQL> select count(*) from emp;

COUNT(*)
----------
14


Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE
1 0 SORT (AGGREGATE)
2 1 TABLE ACCESS (FULL) OF 'EMP'

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

Here are the different autotrace settings...

SET AUTOTRACE OFF
No AUTOTRACE report is generated. This is the default.

SET AUTOTRACE ON EXPLAIN
The AUTOTRACE report shows only the optimizer execution path.

SET AUTOTRACE ON STATISTICS
The AUTOTRACE report shows only the SQL statement execution statistics.

SET AUTOTRACE ON
The AUTOTRACE report includes both the optimizer execution path and the SQL statement execution statistics.

SET AUTOTRACE TRACEONLY
Like SET AUTOTRACE ON, but suppresses the printing of the user's query output, if any.