Basic SQL Performance Diagnosis

Article is based on Randolf’s Post on Basic SQL statement performance diagnosis-HOW TO


The following steps should be taken to gather detailed information about the SQL statement:

1. Gather information about parameters relevant to the optimizer
2. Gather the output of the SQL*Plus AUTOTRACE and TIMING feature when executing your statement
3. Get the EXPLAIN PLAN output of DBMS_XPLAN.DISPLAY including the "Predicate Information" section
4. Run an extended SQL trace of your statement and analyze the generated trace file using a trace file analyzer like TKPROF
5. If you’re on Oracle 10g or later, gather the output of DBMS_XPLAN.DISPLAY_CURSOR after executing your statement


Step 1

Save in File Diag1.sql

set echo on
set timing on trimspool on linesize 130 pagesize 999

alter session set timed_statistics = true;
spool diag1.log
show parameter user_dump_dest
show parameter optimizer
show parameter db_file_multi
show parameter db_block_size
column sname format a20
column pname format a20
column pval2 format a20
select  sname , pname , pval1 , pval2
from sys.aux_stats$;

explain plan for
— put your statement here
select   *  from  t_demo
where type = ‘VIEW’ order by id;

select * from table(dbms_xplan.display);

set autotrace traceonly arraysize 100

alter session set tracefile_identifier = ‘mytrace1’;

alter session set events ‘10046 trace name context forever, level 8’;
— put your statement here
select  *
from t_demo where type = ‘VIEW’  order by id;
spool off


Make sure you see the optimizer settings (provided your user has access to V$PARAMETER), the EXPLAIN PLAN output and the AUTOTRACE statistics.

Please note that it’s crucial that the EXPLAIN PLAN output includes the "Predicate Information" section below the execution plan. If it’s missing and you get instead the message "PLAN_TABLE is old version" in the "Notes" section, you need to either re-create the PLAN_TABLE using the server-side script "$ORACLE_HOME/rdbms/admin/utlxplan.sql" or in 10g you can simply drop any PLAN_TABLE not owned by SYS since the SYS schema already provides a global temporary table PLAN_TABLE$ that is exposed via public synonym, so there is no need for a private PLAN_TABLE any longer.

Step 2

The next step that you need to perform is to analyze the trace file generated. The "USER_DUMP_DEST" setting in your script output tells you where your trace file has been generated on the server. It will have the "mytrace1" trace file identifier specified in its name, so it should be easy to identify, even if you have pass this request to a DBA.

TKPROF [input_trace_filename] trace_output.txt

You need to find the part in the trace file that corresponds to the statement that you’ve traced. It might contain other statements and cover even some statements recursively executed by Oracle.
Once you’ve located your statement in the trace file, the information below immediately following your statement is the crucial one:


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 1501 0.53 1.36 800 149101 0 149938
——- —— ——– ———- ———- ———- ———- ———-
total 1503 0.53 1.36 800 149101 0 149938
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 88
Rows Row Source Operation
——- —————————————————
149938 TABLE ACCESS BY INDEX ROWID T_DEMO (cr=149101 pr=800 pw=0 time=60042 us cost=0 size=60 card=1)
149938 INDEX RANGE SCAN IDX_DEMO (cr=1881 pr=1 pw=0 time=0 us cost=0 size=0 card=1)(object id 74895)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
—————————————- Waited ———- ————
SQL*Net message to client 1501 0.00 0.00
db file sequential read 800 0.05 0.80
SQL*Net message from client 1501 0.00 0.69

This covers the summary timing and blocks related information, the "Parse" related information (was it a hard parse or soft parse represented by the "Misses in library cache…" information), the "Row Source Operations" and the wait events. If one of these sections is missing, something went wrong.


Step 3

If you’re on 10g or later, you can run in a second step the "DBMS_XPLAN.DISPLAY_CURSOR" function to gather some additional information about the execution of your statement.


set echo on
set timing on trimspool on linesize 130 pagesize 999
set arraysize 100 termout off
spool off
— put your statement here
— if you’re not using STATISTICS_LEVEL = ALL
select /*+ gather_plan_statistics */
* from t_demo
where type = ‘VIEW’  order by id;
set termout on
spool diag2.log
select * from table(dbms_xplan.display_cursor(null, null, ‘ALLSTATS LAST’));
spool off


If result of

select * from table(dbms_xplan.display_cursor(null, null, ‘ALLSTATS LAST’));

is Last statement has a PREV_SQL_ID of ZERO then execute the following query and get sql_id and replace above sql with the following

select sql_id,sql_text,child_number from v$sql
where sql_text like ‘SELECT  a16.mkt_oid mkt_oid,%’

select * from table(dbms_xplan.display_cursor(‘aut6x3q9gska4’, 0, ‘ALLSTATS’));


For any clarification visit Randolf’s blog


Leave a Reply

Fill in your details below or click an icon to log in: Logo

You are commenting using your account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: