Sunday, February 22, 2009

Basic SQL statement performance diagnosis - HOW TO, step by step instructions

On the OTN forum very often tuning requests about single SQL statements are posted, but the information provided is rather limited, and therefore it's not that simple to provide a meaningful advice. Instead of writing the same requests for additional information over and over again I thought I put together a post that describes how to gather the most important information and how to post it properly on OTN.

If you have identified a SQL statement that performs not as good as expected, you should follow the following step-by-step instructions to obtain as much information as possible that can be posted on the OTN forum. If you gather the information described here, in many cases it will be quite obvious what needs to be done to improve the performance of the SQL statement in question.

The following post on OTN should act as a template how a useful posting on OTN should ideally look like so that other people (or you yourself) are able to tell what might be wrong with the execution of the SQL statement.

So if you're posting a request about help on a particular SQL statement, make sure that your request includes all the information similar to the template post, and also make sure that you're using a proper formatting, otherwise the information posted can't be read properly, making it very hard for others to understand the meaning. I'll describe below how to apply this formatting on the OTN forum.

If you're facing a poor performing system but haven't identified yet what the issue this, these instructions here will not be very useful. There are other sources that provide helpful instructions in that case, e.g. Christian Antognini's book "Troubleshooting Oracle Performance" or Tanel Poder's "Advanced Oracle Troubleshooting".

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

Note that when using bind variables that the plans produced by EXPLAIN PLAN and AUTOTRACE - which does an EXPLAIN PLAN and unfortunately doesn't show the actual execution plan - are only of limited use, due to the bind variable peeking performed when actually executing the statement. Since the EXPLAIN PLAN doesn't execute the statement, the plans generated at runtime might be significantly different from the EXPLAIN PLAN output.

The SQL*Plus AUTOTRACE feature runs your statement, fetches all rows in case of a SELECT statement and shows afterwards basic performance related statistics about your statement. These statistics are already quite helpful and should be provided as part of your posting.

In case of a SELECT that returns a large number of rows it might be quite important what you set as bulk fetch size. You should try to find out which bulk fetch size your particular application uses (or if it fetches each row individually which is a bad idea in most cases) and set in SQL*Plus the ARRAYSIZE accordingly. Note that the default setting in SQL*Plus is to fetch 15 rows at a time, but usually a larger value offers better performance; a setting of at least 100 should be reasonable in most cases, which of course applies to your application as well.

For more information about this particular issue, look here.

It's usually a good idea to spool your SQL*Plus session to a file so that you can get the output from that file using a simple text editor.

You can gather above information in two steps. In the first step you'll run an EXPLAIN PLAN on your statement, generate a trace file and capture the AUTOTRACE output.

If you're on 10g or later you can capture the extended row source statistics using the DBMS_XPLAN.DISPLAY_CURSOR function in a second step.

The following sample scripts are only applicable to Oracle 9i or later.

For both steps I suggest to prepare a respective SQL script that is based on below code snippets, save it to a file and run it in SQL*Plus script mode using the following syntax:


SQLPLUS [user]/[password]@[database_alias] @[scriptfile_name]


Step 1

This is the code snippet for the first part covering relevant optimizer related settings, EXPLAIN PLAN output, extended SQL trace and the AUTOTRACE output.

Whenever you see "rem put your statement here" you should replace the demo SQL with your particular SQL statement that you want to diagnose.

If you're using bind variables, you need to define and initialize them accordingly. You need to remove the corresponding REMark keyword of that section below if you're using them.

If your SQL is sensitive and you don't want to it to show up in the SPOOLed log files, set the ECHO off in your version of the file.


rem Start of part 1 - save this to a file
rem This covers
rem relevant optimizer parameters
rem EXPLAIN PLAN
rem AUTOTRACE
rem extended trace with wait event information

rem whenever you see:
rem put your statement here
rem then replace the demo statement
rem with your SQL statement

-- if the SQL is sensitive
-- don't switch on the ECHO
-- set echo off
set echo on

set timing on trimspool on linesize 250 pagesize 999

-- this setting can influence your sorting
-- in particular if an index can satisfy your sort order
-- alter session set nls_language = 'AMERICAN';

-- enable timed_statistics (is enabled by default in 9i and later)
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

show parameter cursor_sharing

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);

rollback;

rem Set the ARRAYSIZE according to your application
set autotrace traceonly arraysize 100

alter session set tracefile_identifier = 'mytrace1';

rem if you're using bind variables
rem define them here

rem variable b_var1 number
rem variable b_var2 varchar2(20)

rem and initialize them

rem exec :b_var1 := 1
rem exec :b_var2 := 'DIAG'

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;

disconnect

spool off

exit

-- rem End of Part 1


The spool file "diag1.log" of this script should look similar to the following:


SQL> show parameter user_dump_dest

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
user_dump_dest string c:\oracle\diag\rdbms\orcl11\or
cl11\trace
SQL>
SQL> show parameter optimizer

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
optimizer_capture_sql_plan_baselines boolean FALSE
optimizer_dynamic_sampling integer 2
optimizer_features_enable string 11.1.0.7
optimizer_index_caching integer 0
optimizer_index_cost_adj integer 100
optimizer_mode string ALL_ROWS
optimizer_secure_view_merging boolean TRUE
optimizer_use_invisible_indexes boolean FALSE
optimizer_use_pending_statistics boolean FALSE
optimizer_use_sql_plan_baselines boolean TRUE
SQL>
SQL> show parameter db_file_multi

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
db_file_multiblock_read_count integer 8
SQL>
SQL> show parameter db_block_size

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
db_block_size integer 8192
SQL>
SQL> show parameter cursor_sharing

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
cursor_sharing string EXACT
SQL>
SQL> column sname format a20
SQL> column pname format a20
SQL> column pval2 format a20
SQL>
SQL> select
2 sname
3 , pname
4 , pval1
5 , pval2
6 from
7 sys.aux_stats$;

SNAME PNAME PVAL1 PVAL2
-------------------- -------------------- ---------- --------------------
SYSSTATS_INFO STATUS COMPLETED
SYSSTATS_INFO DSTART 01-30-2009 16:25
SYSSTATS_INFO DSTOP 01-30-2009 16:25
SYSSTATS_INFO FLAGS 0
SYSSTATS_MAIN CPUSPEEDNW 494,397
SYSSTATS_MAIN IOSEEKTIM 10
SYSSTATS_MAIN IOTFRSPEED 4096
SYSSTATS_MAIN SREADTIM
SYSSTATS_MAIN MREADTIM
SYSSTATS_MAIN CPUSPEED
SYSSTATS_MAIN MBRC
SYSSTATS_MAIN MAXTHR
SYSSTATS_MAIN SLAVETHR

13 rows selected.

Elapsed: 00:00:00.04
SQL>
SQL> explain plan for
2 -- put your statement here
3 select
4 *
5 from
6 t_demo
7 where
8 type = 'VIEW'
9 order by
10 id;

Explained.

Elapsed: 00:00:00.01
SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 1390505571

----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 60 | 0 (0)| 00:00:01 |
| 1 | TABLE ACCESS BY INDEX ROWID| T_DEMO | 1 | 60 | 0 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IDX_DEMO | 1 | | 0 (0)| 00:00:01 |
----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

2 - access("TYPE"='VIEW')

14 rows selected.

Elapsed: 00:00:00.08
SQL>
SQL> rollback;

Rollback complete.

Elapsed: 00:00:00.00
SQL>
SQL> rem Set the ARRAYSIZE according to your application
SQL> set autotrace traceonly arraysize 100
SQL>
SQL> alter session set tracefile_identifier = 'mytrace1';

Session altered.

Elapsed: 00:00:00.00
SQL>
SQL> rem if you're using bind variables
SQL> rem define them here
SQL>
SQL> rem variable b_var1 number
SQL> rem variable b_var2 varchar2(20)
SQL>
SQL> rem and initialize them
SQL>
SQL> rem exec :b_var1 := 1
SQL> rem exec :b_var2 := 'DIAG'
SQL>
SQL> alter session set events '10046 trace name context forever, level 8';

Session altered.

Elapsed: 00:00:00.01
SQL>
SQL> -- put your statement here
SQL> select
2 *
3 from
4 t_demo
5 where
6 type = 'VIEW'
7 order by
8 id;

149938 rows selected.

Elapsed: 00:00:02.21

Execution Plan
----------------------------------------------------------
Plan hash value: 1390505571

----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 60 | 0 (0)| 00:00:01 |
| 1 | TABLE ACCESS BY INDEX ROWID| T_DEMO | 1 | 60 | 0 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IDX_DEMO | 1 | | 0 (0)| 00:00:01 |
----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

2 - access("TYPE"='VIEW')


Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
149101 consistent gets
800 physical reads
196 redo size
1077830 bytes sent via SQL*Net to client
16905 bytes received via SQL*Net from client
1501 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
149938 rows processed

SQL>
SQL> disconnect
Disconnected from Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
SQL>
SQL> 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.

If some of these things are missing or you get error messages, sort any missing privileges or missing objects out and try again.

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.

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.

Once the trace file has been located, you need to run the trace file analyzer. I suggest to use the one provided by Oracle (TKPROF), but you should know that there are other freely available trace analyzers, e.g. OraSRP by Egor Starostin or TVD$XTAT by Christian Antognini. Oracle offers an extended version of TKPROF on MetaLink called TRCANLZR, see MetaLink note 224270.1.

I recommend to use the version of TKPROF that is part of the database installation, but you can use also one which is part of your client installation. Ideally it should have the same version and patch level as your database.

In order to run TKPROF to analyze your trace file, simply run the following:


TKPROF [input_trace_filename] trace_output.txt


This will generate a file called "trace_output.txt" that looks similar to the following:


TKPROF: Release 11.1.0.7.0 - Production on Mo Feb 23 10:23:08 2009

Copyright (c) 1982, 2007, Oracle. All rights reserved.

Trace file: orcl11_ora_3376_mytrace1.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
********************************************************************************

select
*
from
t_demo
where
type = 'VIEW'
order by
id

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

SQL ID: g72kdvcacxvtf
Plan Hash: 2637181423
DELETE FROM PLAN_TABLE
WHERE
STATEMENT_ID=:1
...


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.

E.g. if you don't disconnect your session, the "Row Source Operation" part could be missing. Since this is a crucial analysis information, you should make sure that it is part of the trace file and the TKPROF output. If you check the raw trace file, this information is represented by lines beginning with "STAT ...".

Step 2

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.

This is the code snippet for the second part covering the DBMS_XPLAN.DISPLAY_CURSOR output.

Whenever you see "rem put your statement here" you should replace the demo SQL with your particular SQL statement that you want to diagnose.

Note that this is going to execute your statement a second time. I've included a (commented) "flush buffer_cache" instruction, but e.g. on a production system this might not be recommended, so you should be cautious.

Again you should save this to a file and executed it in SQL*Plus as outlined above.

Again, if you're using bind variables, you need to define and initialize them accordingly. You need to remove the corresponding REMark keyword of that section below if you're using them.


rem Start of part 2 - save this to a file
rem This covers
rem DBMS_XPLAN.DISPLAY_CURSOR

-- if you're on 10g or later
-- get the row source statistics

-- if the SQL is sensitive
-- don't switch on the ECHO
-- set echo off
set echo on

set timing on trimspool on linesize 250 pagesize 999

-- this setting can influence your sorting
-- in particular if an index can satisfy your sort order
-- alter session set nls_language = 'AMERICAN';

rem Set the ARRAYSIZE according to your application
set arraysize 100 termout off

rem make sure that this doesn't harm
rem the environment you're running this script
rem e.g. don't do this to a production system
rem alter system flush buffer_cache;

rem if you're using bind variables
rem define them here

rem variable b_var1 number
rem variable b_var2 varchar2(20)

rem and initialize them

rem exec :b_var1 := 1
rem exec :b_var2 := 'DIAG'

spool off

-- put your statement here
-- use the GATHER_PLAN_STATISTICS hint
-- 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

exit

-- rem End of Part 2


The spool output "diag2.log" of this SQL script should look similar to the following:


SQL>
SQL> select * from table(dbms_xplan.display_cursor(null, null, 'ALLSTATS LAST'));

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
SQL_ID d4k5acu783vu8, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ * from t_demo
where type = 'VIEW' order by id

Plan hash value: 1390505571

-----------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads |
-----------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 149K|00:00:00.02 | 149K| 1183 |
| 1 | TABLE ACCESS BY INDEX ROWID| T_DEMO | 1 | 1 | 149K|00:00:00.02 | 149K| 1183 |
|* 2 | INDEX RANGE SCAN | IDX_DEMO | 1 | 1 | 149K|00:00:00.02 | 1880 | 383 |
-----------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

2 - access("TYPE"='VIEW')


20 rows selected.

Elapsed: 00:00:00.12
SQL>
SQL> spool off


Note that the DISPLAY_CURSOR function repeats the SQL analyzed so you need to remove it from the posted information if you are not allowed to disclose this information.

How to post the information on OTN

Now that you've collected the most important information about your SQL statement, here are the instructions how to post them properly on OTN.

Your post should start with a short description of what your SQL statement is about, e.g. if it covers some specific logic it might be good to mention this. Often things can be expressed differently in SQL and it's not unlikely that with the right information at hand someone might come with a different solution for the same problem which could be much more efficient making any further tuning efforts unnecessary.

Then you should of course post the SQL itself, if possible, this would be very helpful.

Note that a proper formatting of your SQL statement is very helpful, not only for others, but for yourself. If you want to get this done automatically, you can use some of the freely available online SQL formatting tools, e.g. SQLInform offers a quite powerful one.

You should also include an information about the expected runtime of your statement, simply saying that it takes "longer" is not really helpful. You could say e.g. that it is expected to return the whole result in 1 second, or 1 minute or similar.

In case you have the special requirement that you only need to fetch the first N rows of the result set this is also very important and should be mentioned explicitly, apart from the fact that your statement then usually should include an ORDER BY wrapped by a "ROWNUM < N" filter predicate.

After this general information you should post the information gathered, which is the following:

1. The version of your database with 4-digits (e.g. 10.2.0.4)
2. Parameters relevant to the optimizer
3. The TIMING and AUTOTRACE output
4. The EXPLAIN PLAN output
5. The TKPROF output snippet that corresponds to your statement
6. If you're on 10g or later, the DBMS_XPLAN.DISPLAY_CURSOR output as outlined above.

The most important point when posting spool/trace file output is the usage of the "code" tag. By using this "code" tag the information will be formatted in fixed font which preserves the formatting and makes it readable. Failure to do so will render the information more or less useless, since nobody can read your posted information, so make sure you use the "code" tag appropriately, which is not that complicated:

If you want to preserve the formatting and use fixed font formatting, enclose the information with the {code} tag before and after like that:


{code}
Here goes something
which is formatted in fixed font
and preserved formatting
{code}


So here is how a sample posting could look like:

Subject: SQL statement tuning request

-- Start of body --

The following SQL statement has been identified to perform poorly. It currently takes up to 10 seconds to execute, but it's supposed to take a second at most.

This is the statement:


{code}
select
*
from
t_demo
where
type = 'VIEW'
order by
id;
{code}


It should return data from a table in a specific order.

The version of the database is 11.1.0.7.

These are the parameters relevant to the optimizer:


{code}
SQL>
SQL> show parameter optimizer

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
optimizer_capture_sql_plan_baselines boolean FALSE
optimizer_dynamic_sampling integer 2
optimizer_features_enable string 11.1.0.7
optimizer_index_caching integer 0
optimizer_index_cost_adj integer 100
optimizer_mode string ALL_ROWS
optimizer_secure_view_merging boolean TRUE
optimizer_use_invisible_indexes boolean FALSE
optimizer_use_pending_statistics boolean FALSE
optimizer_use_sql_plan_baselines boolean TRUE
SQL>
SQL> show parameter db_file_multi

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
db_file_multiblock_read_count integer 8
SQL>
SQL> show parameter db_block_size

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
db_block_size integer 8192
{code}


Here is the output of EXPLAIN PLAN:


{code}
SQL> explain plan for
2 -- put your statement here
3 select
4 *
5 from
6 t_demo
7 where
8 type = 'VIEW'
9 order by
10 id;

Explained.

Elapsed: 00:00:00.01
SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 1390505571

----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 60 | 0 (0)| 00:00:01 |
| 1 | TABLE ACCESS BY INDEX ROWID| T_DEMO | 1 | 60 | 0 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IDX_DEMO | 1 | | 0 (0)| 00:00:01 |
----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

2 - access("TYPE"='VIEW')

14 rows selected.
{code}


Here is the output of SQL*Plus AUTOTRACE including the TIMING information:


{code}
SQL> select
2 *
3 from
4 t_demo
5 where
6 type = 'VIEW'
7 order by
8 id;

149938 rows selected.

Elapsed: 00:00:02.21

Execution Plan
----------------------------------------------------------
Plan hash value: 1390505571

----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 60 | 0 (0)| 00:00:01 |
| 1 | TABLE ACCESS BY INDEX ROWID| T_DEMO | 1 | 60 | 0 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IDX_DEMO | 1 | | 0 (0)| 00:00:01 |
----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

2 - access("TYPE"='VIEW')


Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
149101 consistent gets
800 physical reads
196 redo size
1077830 bytes sent via SQL*Net to client
16905 bytes received via SQL*Net from client
1501 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
149938 rows processed

SQL>
SQL> disconnect
Disconnected from Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
{code}


The TKPROF output for this statement looks like the following:


{code}
TKPROF: Release 11.1.0.7.0 - Production on Mo Feb 23 10:23:08 2009

Copyright (c) 1982, 2007, Oracle. All rights reserved.

Trace file: orcl11_ora_3376_mytrace1.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
********************************************************************************

select
*
from
t_demo
where
type = 'VIEW'
order by
id

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
********************************************************************************
{code}


The DBMS_XPLAN.DISPLAY_CURSOR output:


{code}
SQL>
SQL> select * from table(dbms_xplan.display_cursor(null, null, 'ALLSTATS LAST'));

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
SQL_ID d4k5acu783vu8, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ * from t_demo
where type = 'VIEW' order by id

Plan hash value: 1390505571

-----------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads |
-----------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 149K|00:00:00.02 | 149K| 1183 |
| 1 | TABLE ACCESS BY INDEX ROWID| T_DEMO | 1 | 1 | 149K|00:00:00.02 | 149K| 1183 |
|* 2 | INDEX RANGE SCAN | IDX_DEMO | 1 | 1 | 149K|00:00:00.02 | 1880 | 383 |
-----------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

2 - access("TYPE"='VIEW')


20 rows selected.
{code}


I'm looking forward for suggestions how to improve the performance of this statement.

-- End of body --

I'm sure that if you follow these instructions and obtain the information described, post them using a proper formatting (don't forget about the {code} tag) you'll receive meaningful advice very soon.

So, just to make sure you didn't miss this point:


{code}
Use proper formatting!
{code}


If you think I missed something important in this sample post let me know so that I can improve it.

10 comments:

Toni Lazarin said...

thanks, amazing post.
appriciate your efforts,
keep up the very good work on oracle performance,
cheers,
Toni

Randolf said...

Toni,

thanks for the feedback, always appreciated.

Regards,
Randolf

1 木匠 said...

Advice:

We also need to reproduce the test case. that is the SQL to create the table/index ...etc, SQL to insert the data.

Suggestions on how to improve the performance of this statement:

Based on your data use case, e.g. write or read intensive, there may be some solutions,

1) Reorganize the table data, order by column type,id.

2) create composite index on type and id

3) partition table by column type

4) Materialized View might help if it is read intensive.

select *
from t_demo
where type = 'VIEW'
order by id;

Thanks,
Charlie 木匠

Randolf said...

Charlie,

the test case used in this post is irrelevant, it was merely used for demonstration purposes since the topic of the post is to show how to gather the information.

If you're interested in the details: It has been taken from this post where I also provide all required information how to reproduce it.

By the way, the solution in that particular case it to gather proper statistics so that the optimizer is not mislead by wrong information.

Regards,
Randolf

Mark Freeman said...

Randolf,

This is really very helpful. I am curious though, why the part 1 script runs the explain plan twice. What is the benefit from that? There is nothing in the first output that is not also contained in the second, at least when I tried it.

Randolf said...

Mark,

the reason for showing this twice is very simple: AUTOTRACE in 9i versions didn't use DBMS_XPLAN.DISPLAY, therefore the AUTOTRACE output lacked a lot of information (e.g. the Predicates section below the plan).

From 10g on you get the same information twice, that is true.

Randolf

Suvv said...

The approach you have documented is very simple and superb ! for the DBAs who are new to the tuning world .Thanks for sharing the info !

Anonymous said...

Very helpful and detail post. Thank you Randolf.

You said and i quote
"If you have identified a SQL statement that performs not as good as expected, you should follow the following step-by-step instructions"
My question is: what should be the step-by-step instructions for pl/sql procedures. In my case i have pl/sql procedures that contains insert statements, select statements, delete statements and update statements (sequence varies with procedure to procedure and business logic).

Procedure is schedule to run every hour and when this procedure is scheduled to run no other SQL or PL/SQL statements run in the RAC database (2-node),that is the only procedure that will be running at that particular time in the database.

The behaviour of this procedure is strange at times it completes in 10 mts and other times it takes 1 hour.

Now i would like to understand why this behaviour ?

Appreciate if you could guide me to posts/papers/presentations/tools to help identify and tune the PL/SQL procedure.

Regards
Syed

Randolf said...

As usual the first step is that you need to understand where the time is spent.

For an ad-hoc analysis (the code is running slow NOW) you could simply use Tanel Poder's "snapper" script against your session to find out some details what it is doing at that moment.

For a PL/SQL procedure in general my first advice is that you need to have a proper instrumentation of your code in place. If you don't have anything at hand you could look at ILO (https://portal.hotsos.com/products/hotsos_ilo).

Then you could think about simply tracing your execution, or use the PL/SQL hierarchical profiler.

Once you have identified that one or more of the contained SQL statements cause problems you can follow again the advice shown here.

You might need to add more instrumentation code if you only get problems with certain bind variable values, so that you could see the actual inputs used to execute your statement.

If you have Enterprise Edition + Diagnostic + Tuning Pack license Real Time SQL Monitoring can provide the actual bind values used, too.

Randolf

Anonymous said...

wow posted on 2009, still it use full. thanks for the details, great step by step details.

Regards
Satyam K