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.

Wednesday, February 18, 2009

EXPLAIN PLAN on DDLs

Update May 2009: Inspired by Jonathan Lewis' post about index sizes I've revisited this and added some more cases that covers Jonathan's points and some more experiments regarding 11g's virtual columns and bitmap indexes.

Although it's mentioned in the official documentation of the EXPLAIN PLAN command, I believe it's a not so well known fact that you can EXPLAIN the following DDL commands:

CREATE TABLE
CREATE INDEX
ALTER INDEX REBUILD

What is the benefit of doing so? First of all in case of a complex CREATE TABLE AS SELECT (CTAS) statement you'll get the execution plan, and when using the Cost Based Optimizer this information will include the number of estimated rows that are going to be generated and the estimated time it takes (from 10g on, prior to 10g you need to turn the reported cost yourself into time if you like).

Of course usually this plan is supposed to correspond to the plan of the SELECT statement alone, provided that you're using the default ALL_ROWS optimizer mode, but I have already encountered situations where the plans were different although this usually was due to some buggy behaviour.

In case of a CREATE INDEX DDL you'll get again a cost and time indication, along with a row estimate. Unfortunately it doesn't show an estimation of the required TEMP space for sorting. Additionally it doesn't work very well for function-based indexes where the number of rows actually indexed might be far less than the number of rows of the underlying table. The same applies to NULLABLE columns, it would be nice if this information would be used to come up with the correct number of rows that the index will cover.

As you will see in the sample script provided below, the optimizer's cardinality estimates are not used at full extent when generating indexes, in particular function-based indexes. The cardinality estimates of a query are significantly different from that of a corresponding index expression.

Starting with Oracle 10.2 you'll get an indication of the size of the index based on the dictionary statistics in the "Notes" section, so the estimate is only as good as your statistics allow for, in addition above points apply regarding the accuracy of the estimate in case of null values or function-based indexes. The size estimate is obviously based on the average column length recorded in the statistics.

Interestingly the CREATE TABLE AS SELECT estimation doesn't provide such a size estimation which could be quite handy, too.

Explaining an ALTER INDEX REBUILD shows similar information to that of a CREATE INDEX, but it doesn't show the size estimate, which is a pity because it might provide an indication of the size reduction that might be the result of a rebuild. Of course you can help yourself by explaining the corresponding CREATE INDEX statement.

One potentially interesting information is what is going to be used to perform the create or rebuild index, e.g. the database might be capable of using another index to read the information from rather than performing a full table scan (although you should check in this case if the index isn't redundant).

Other DDLs like ALTER INDEX COALESCE obviously are not supported and a simple CREATE TABLE doesn't add any value, so it's supported but useless.

The following script shows some test results of a EXPLAIN PLAN on DDLs in 11.1.0.7:


SQL> create table explain_ddl_test
2 as
3 select * from all_objects
4 where rownum <= 1000;

Table created.

SQL>
SQL> exec dbms_stats.gather_table_stats(null, 'explain_ddl_test')

PL/SQL procedure successfully completed.

SQL>
SQL> -- create table DDL explain
SQL> explain plan for
2 create table explain_ddl_test2
3 as
4 select * from explain_ddl_test;

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 3524376278

--------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------------------------
| 0 | CREATE TABLE STATEMENT | | 1000 | 84000 | 9 (0)| 00:00:01 |
| 1 | LOAD AS SELECT | EXPLAIN_DDL_TEST2 | | | | |
| 2 | TABLE ACCESS FULL | EXPLAIN_DDL_TEST | 1000 | 84000 | 5 (0)| 00:00:01 |
--------------------------------------------------------------------------------------------

9 rows selected.

SQL>
SQL> -- create index explain
SQL> -- includes used and estimated index bytes
SQL> explain plan for
2 create index explain_ddl_test_idx
3 on explain_ddl_test (object_id);

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 932678384

-----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------
| 0 | CREATE INDEX STATEMENT | | 1000 | 4000 | 7 (0)| 00:00:01 |
| 1 | INDEX BUILD NON UNIQUE| EXPLAIN_DDL_TEST_IDX | | | | |
| 2 | SORT CREATE INDEX | | 1000 | 4000 | | |
| 3 | TABLE ACCESS FULL | EXPLAIN_DDL_TEST | 1000 | 4000 | 5 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------

Note
-----
- estimated index size: 65536 bytes

14 rows selected.

SQL>
SQL> -- but the estimated index size
SQL> -- doesn't use the correct tablespace
SQL> -- since the user has a default tablespace
SQL> -- with 1MB uniform extent allocation
SQL> create index explain_ddl_test_idx
2 on explain_ddl_test (object_id);

Index created.

SQL>
SQL> select
2 bytes/1024 as KB
3 from
4 user_segments
5 where
6 segment_name = 'EXPLAIN_DDL_TEST_IDX'
7 and segment_type = 'INDEX';

KB
----------
1024

1 row selected.

SQL>
SQL> drop index explain_ddl_test_idx;

Index dropped.

SQL>
SQL> -- Now the estimated index size information
SQL> -- is correct when explicitly
SQL> -- stating the tablespace
SQL> explain plan for
2 create index explain_ddl_test_idx
3 on explain_ddl_test (object_id)
4 tablespace test_8k;

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 932678384

-----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------
| 0 | CREATE INDEX STATEMENT | | 1000 | 4000 | 7 (0)| 00:00:01 |
| 1 | INDEX BUILD NON UNIQUE| EXPLAIN_DDL_TEST_IDX | | | | |
| 2 | SORT CREATE INDEX | | 1000 | 4000 | | |
| 3 | TABLE ACCESS FULL | EXPLAIN_DDL_TEST | 1000 | 4000 | 5 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------

Note
-----
- estimated index size: 1048K bytes

14 rows selected.

SQL>
SQL> -- what about compression?
SQL> explain plan for
2 create index explain_ddl_test_idx
3 on explain_ddl_test (object_type, object_id);

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 932678384

-----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------
| 0 | CREATE INDEX STATEMENT | | 1000 | 11000 | 7 (0)| 00:00:01 |
| 1 | INDEX BUILD NON UNIQUE| EXPLAIN_DDL_TEST_IDX | | | | |
| 2 | SORT CREATE INDEX | | 1000 | 11000 | | |
| 3 | TABLE ACCESS FULL | EXPLAIN_DDL_TEST | 1000 | 11000 | 5 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------

Note
-----
- estimated index size: 65536 bytes

14 rows selected.

SQL>
SQL> -- not considered in the estimate
SQL> explain plan for
2 create index explain_ddl_test_idx
3 on explain_ddl_test (object_type, object_id)
4 compress;

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 932678384

-----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------
| 0 | CREATE INDEX STATEMENT | | 1000 | 11000 | 7 (0)| 00:00:01 |
| 1 | INDEX BUILD NON UNIQUE| EXPLAIN_DDL_TEST_IDX | | | | |
| 2 | SORT CREATE INDEX | | 1000 | 11000 | | |
| 3 | TABLE ACCESS FULL | EXPLAIN_DDL_TEST | 1000 | 11000 | 5 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------

Note
-----
- estimated index size: 65536 bytes

14 rows selected.

SQL>
SQL> -- The size estimate
SQL> -- seems to be based
SQL> -- on num_rows * sum(avg_col_len)
SQL> exec dbms_stats.set_table_stats(null, 'explain_ddl_test', numblks=>10000000, numrows=>100000000)

PL/SQL procedure successfully completed.

SQL>
SQL> explain plan for
2 create index explain_ddl_test_idx
3 on explain_ddl_test (object_id);

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 932678384

-----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------
| 0 | CREATE INDEX STATEMENT | | 100M| 381M| 2809K (1)| 09:21:58 |
| 1 | INDEX BUILD NON UNIQUE| EXPLAIN_DDL_TEST_IDX | | | | |
| 2 | SORT CREATE INDEX | | 100M| 381M| | |
| 3 | TABLE ACCESS FULL | EXPLAIN_DDL_TEST | 100M| 381M| 2730K (1)| 09:06:07 |
-----------------------------------------------------------------------------------------------

Note
-----
- estimated index size: 2415M bytes

14 rows selected.

SQL>
SQL> exec dbms_stats.gather_table_stats(null, 'explain_ddl_test')

PL/SQL procedure successfully completed.

SQL>
SQL> exec dbms_stats.set_column_stats(null, 'explain_ddl_test', 'object_id', avgclen=>50)

PL/SQL procedure successfully completed.

SQL>
SQL> -- it looks like that a certain overhead
SQL> -- is included in the estimated index size
SQL> -- otherwise this should fit into a
SQL> -- single 64kb extent
SQL> explain plan for
2 create index explain_ddl_test_idx
3 on explain_ddl_test (object_id);

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 932678384

-----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------
| 0 | CREATE INDEX STATEMENT | | 1000 | 50000 | 8 (0)| 00:00:01 |
| 1 | INDEX BUILD NON UNIQUE| EXPLAIN_DDL_TEST_IDX | | | | |
| 2 | SORT CREATE INDEX | | 1000 | 50000 | | |
| 3 | TABLE ACCESS FULL | EXPLAIN_DDL_TEST | 1000 | 50000 | 5 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------

Note
-----
- estimated index size: 131K bytes

14 rows selected.

SQL>
SQL> exec dbms_stats.gather_table_stats(null, 'explain_ddl_test')

PL/SQL procedure successfully completed.

SQL>
SQL> -- what about function-based indexes?
SQL> -- this is the default 5% hard-coded
SQL> -- selectivity for functions
SQL> -- by the optimizer
SQL> explain plan for
2 select
3 *
4 from
5 explain_ddl_test
6 where
7 case when object_id = 1 then 1 else null end is not null;

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 119225828

--------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 50 | 4200 | 5 (0)| 00:00:01 |
|* 1 | TABLE ACCESS FULL| EXPLAIN_DDL_TEST | 50 | 4200 | 5 (0)| 00:00:01 |
--------------------------------------------------------------------------------------

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

1 - filter(CASE "OBJECT_ID" WHEN 1 THEN 1 ELSE NULL END IS NOT NULL)

13 rows selected.

SQL>
SQL> -- but it's not reflected
SQL> -- in the create index
SQL> explain plan for
2 create index explain_ddl_test_idx
3 on explain_ddl_test (case when object_id = 1 then 1 else null end);

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 932678384

-----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------
| 0 | CREATE INDEX STATEMENT | | 1000 | 4000 | 7 (0)| 00:00:01 |
| 1 | INDEX BUILD NON UNIQUE| EXPLAIN_DDL_TEST_IDX | | | | |
| 2 | SORT CREATE INDEX | | 1000 | 4000 | | |
| 3 | TABLE ACCESS FULL | EXPLAIN_DDL_TEST | 1000 | 4000 | 5 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------

Note
-----
- estimated index size: 65536 bytes

14 rows selected.

SQL>
SQL> -- same here
SQL> explain plan for
2 select
3 *
4 from
5 explain_ddl_test
6 where
7 decode(object_id, 1, 1, null) is not null;

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 119225828

--------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 50 | 4200 | 5 (0)| 00:00:01 |
|* 1 | TABLE ACCESS FULL| EXPLAIN_DDL_TEST | 50 | 4200 | 5 (0)| 00:00:01 |
--------------------------------------------------------------------------------------

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

1 - filter(DECODE("OBJECT_ID",1,1,NULL) IS NOT NULL)

13 rows selected.

SQL>
SQL> explain plan for
2 create index explain_ddl_test_idx
3 on explain_ddl_test (decode(object_id, 1, 1, null));

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 932678384

-----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------
| 0 | CREATE INDEX STATEMENT | | 1000 | 4000 | 7 (0)| 00:00:01 |
| 1 | INDEX BUILD NON UNIQUE| EXPLAIN_DDL_TEST_IDX | | | | |
| 2 | SORT CREATE INDEX | | 1000 | 4000 | | |
| 3 | TABLE ACCESS FULL | EXPLAIN_DDL_TEST | 1000 | 4000 | 5 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------

Note
-----
- estimated index size: 65536 bytes

14 rows selected.

SQL>
SQL> -- virtual columns
SQL> -- in 11g should help
SQL> alter table explain_ddl_test
2 add expr1 as (decode(object_id, 1, 1, null));

Table altered.

SQL>
SQL> -- let's create statistics
SQL> -- for the virtual column
SQL> begin
2 dbms_stats.gather_table_stats(
3 null,
4 'explain_ddl_test',
5 method_opt => 'for columns expr1 size auto'
6 );
7 end;
8 /

PL/SQL procedure successfully completed.

SQL>
SQL> -- now the optimizer estimate
SQL> -- should use the extended statistics
SQL> explain plan for
2 select
3 *
4 from
5 explain_ddl_test
6 where
7 decode(object_id, 1, 1, null) is not null;

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 119225828

--------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 84 | 5 (0)| 00:00:01 |
|* 1 | TABLE ACCESS FULL| EXPLAIN_DDL_TEST | 1 | 84 | 5 (0)| 00:00:01 |
--------------------------------------------------------------------------------------

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

1 - filter("EXPLAIN_DDL_TEST"."EXPR1" IS NOT NULL)

13 rows selected.

SQL>
SQL> -- now the optimizer estimate
SQL> -- should use the extended statistics
SQL> explain plan for
2 select
3 *
4 from
5 explain_ddl_test
6 where
7 expr1 is not null;

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 119225828

--------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 84 | 5 (0)| 00:00:01 |
|* 1 | TABLE ACCESS FULL| EXPLAIN_DDL_TEST | 1 | 84 | 5 (0)| 00:00:01 |
--------------------------------------------------------------------------------------

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

1 - filter("EXPR1" IS NOT NULL)

13 rows selected.

SQL>
SQL> -- what about a CREATE INDEX?
SQL> -- still not used
SQL> explain plan for
2 create index explain_ddl_test_idx
3 on explain_ddl_test (expr1);

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 932678384

-----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------
| 0 | CREATE INDEX STATEMENT | | 1000 | 7000 | 7 (0)| 00:00:01 |
| 1 | INDEX BUILD NON UNIQUE| EXPLAIN_DDL_TEST_IDX | | | | |
| 2 | SORT CREATE INDEX | | 1000 | 7000 | | |
| 3 | TABLE ACCESS FULL | EXPLAIN_DDL_TEST | 1000 | 7000 | 5 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------

Note
-----
- estimated index size: 65536 bytes

14 rows selected.

SQL>
SQL> -- What about NULL values in the statistics?
SQL> alter table explain_ddl_test modify object_id null;

Table altered.

SQL>
SQL> update
2 explain_ddl_test
3 set
4 object_id = NULL
5 where
6 rownum <= 500;

500 rows updated.

SQL>
SQL> commit;

Commit complete.

SQL>
SQL> exec dbms_stats.gather_table_stats(null, 'explain_ddl_test')

PL/SQL procedure successfully completed.

SQL>
SQL> explain plan for
2 select count(*)
3 from explain_ddl_test
4 where object_id is not null;

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 2446556867

---------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 3 | 5 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | 3 | | |
|* 2 | TABLE ACCESS FULL| EXPLAIN_DDL_TEST | 500 | 1500 | 5 (0)| 00:00:01 |
---------------------------------------------------------------------------------------

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

2 - filter("OBJECT_ID" IS NOT NULL)

14 rows selected.

SQL> -- not used in ROWS estimated in the CREATE INDEX
SQL> -- but the AVG_COL_LEN reflects the nulls
SQL> explain plan for
2 create index explain_ddl_test_idx
3 on explain_ddl_test (object_id);

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 932678384

-----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------
| 0 | CREATE INDEX STATEMENT | | 1000 | 3000 | 7 (0)| 00:00:01 |
| 1 | INDEX BUILD NON UNIQUE| EXPLAIN_DDL_TEST_IDX | | | | |
| 2 | SORT CREATE INDEX | | 1000 | 3000 | | |
| 3 | TABLE ACCESS FULL | EXPLAIN_DDL_TEST | 1000 | 3000 | 5 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------

Note
-----
- estimated index size: 65536 bytes

14 rows selected.

SQL>
SQL> create index explain_ddl_test_idx on explain_ddl_test (object_id);

Index created.

SQL>
SQL> explain plan for alter index explain_ddl_test_idx rebuild;

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 346799211

-----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------
| 0 | ALTER INDEX STATEMENT | | 1000 | 3000 | 5 (0)| 00:00:01 |
| 1 | INDEX BUILD NON UNIQUE| EXPLAIN_DDL_TEST_IDX | | | | |
| 2 | SORT CREATE INDEX | | 1000 | 3000 | | |
| 3 | INDEX FAST FULL SCAN| EXPLAIN_DDL_TEST_IDX | | | | |
-----------------------------------------------------------------------------------------------

10 rows selected.

SQL>
SQL> explain plan for alter index explain_ddl_test_idx rebuild online;

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 932678384

-----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------
| 0 | ALTER INDEX STATEMENT | | 1000 | 3000 | 5 (0)| 00:00:01 |
| 1 | INDEX BUILD NON UNIQUE| EXPLAIN_DDL_TEST_IDX | | | | |
| 2 | SORT CREATE INDEX | | 1000 | 3000 | | |
| 3 | TABLE ACCESS FULL | EXPLAIN_DDL_TEST | 1000 | 3000 | 5 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------

10 rows selected.

SQL>
SQL> explain plan for create table test (col1 number);

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------

----------------------------------------------------
| Id | Operation | Name | Cost (%CPU)|
----------------------------------------------------
| 0 | CREATE TABLE STATEMENT | | 0 (0)|
----------------------------------------------------

6 rows selected.

SQL>
SQL> explain plan for alter index explain_ddl_test_idx coalesce;
explain plan for alter index explain_ddl_test_idx coalesce
*
ERROR at line 1:
ORA-00900: invalid SQL statement


SQL>
SQL> -- what about bitmap indexes vs. b-tree indexes
SQL> exec dbms_stats.set_table_stats(null, 'explain_ddl_test', numblks=>10000000, numrows=>100000000)

PL/SQL procedure successfully completed.

SQL>
SQL> explain plan for
2 create index explain_ddl_test_idx
3 on explain_ddl_test (object_type);

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 932678384

-----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------
| 0 | CREATE INDEX STATEMENT | | 100M| 953M| 2810K (1)| 09:22:10 |
| 1 | INDEX BUILD NON UNIQUE| EXPLAIN_DDL_TEST_IDX | | | | |
| 2 | SORT CREATE INDEX | | 100M| 953M| | |
| 3 | TABLE ACCESS FULL | EXPLAIN_DDL_TEST | 100M| 953M| 2731K (1)| 09:06:18 |
-----------------------------------------------------------------------------------------------

Note
-----
- estimated index size: 2415M bytes

14 rows selected.

SQL>
SQL> -- no difference
SQL> explain plan for
2 create bitmap index explain_ddl_test_idx
3 on explain_ddl_test (object_type);

Explained.

SQL>
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 3686177077

------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
------------------------------------------------------------------------------------------------
| 0 | CREATE INDEX STATEMENT | | 100M| 953M| 2810K (1)| 09:22:10 |
| 1 | INDEX BUILD NON UNIQUE | EXPLAIN_DDL_TEST_IDX | | | | |
| 2 | BITMAP COMPACTION | | | | | |
| 3 | SORT CREATE INDEX | | 100M| 953M| | |
| 4 | BITMAP CONSTRUCTION | | | | | |
| 5 | TABLE ACCESS FULL | EXPLAIN_DDL_TEST | 100M| 953M| 2731K (1)| 09:06:18 |
------------------------------------------------------------------------------------------------

Note
-----
- estimated index size: 2415M bytes

16 rows selected.

SQL>


In summary the added value and functionality of explaining the supported DDLs is rather limited, given the limitations mentioned above, although the information provided can be helpful in some cases.

Sunday, February 8, 2009

Cost-Based Oracle - Fundamentals: Test cases applied against 10.2.0.4 and 11.1.0.6 (Part 2)

Back to part 1

This part of this series covers chapter 2 of the book, the "Tablescan".

Running the test cases of chapter 2 against 10.2.0.4 and 11.1.0.6 revealed that apart from a few oddities all of the results were consistent with those reported by Jonathan for the previous releases.

In the following I'll attempt to cover the most important findings.

Effects of Block Sizes

One particular issue that the book already covered in detail is the effect of using non-standard block sizes on the optimizer's estimates.

Let's start with re-iterating what has already been written by Jonathan. Using traditional I/O only costing (CPU costing disabled), 8KB default blocksize and a db_file_multiblock_read_count = 8 the following costs were reported for a full table scan of an 80MB table segment:


Block Size Cost Adjusted dbf_mbrc Number of blocks
---------- ---------- ----------------- ----------------
2KB 2,439 16.39 40,000
4KB 1,925 10.40 20,000
8KB 1,519 6.59 10,000
16KB 1,199 4.17 5,000


What can be deduced from these findings? The optimizer is consistent with the runtime engine in that it adjusts the db_file_multiblock_read_count (dbf_mbrc) according to the block size, e.g. the 2KB block size segment is scanned using an dbf_mbrc of 32, because the default block size of 8KB times the dbf_mbrc of 8 results in a multi-block read request of 64KB.

A dbf_mbrc of 32 results in an adjusted dbf_mbrc used for cost calculation of 16.39, as can be seen in the previous examples of the book, presumably because the optimizer assumes that multi-block reads requesting more blocks have a higher probability of getting reduced due to blocks already in the buffer cache. It's this assumption that tempts to deduce that there is a element of truth that using a larger block size might be able to reduce the number of I/O requests.

Consider that in the case of smaller blocks (e.g. 2KB) some of them are already in the buffer cache due to single row/block access. This could actually require to split a 32 block multi-block read request into multiple smaller ones, increasing the number of I/O requests required to read the data.

On the other hand, in the same scenario using a larger block size (e.g. 16KB) the single rows accessed might possibly be located in less blocks, leading to less fragmentation of the 4 block multi-block read requests.

But the usage of the larger block size in this scenario might also lead to much greater portion of the segment competing for the buffer cache with other concurrent requests due to the fact that a single row request requires the whole (larger) block to be read possibly lowering the overall effectiveness of the buffer cache, so it probably depends largely on the actual usage pattern and it's likely that both effects outweigh each other in most cases.

Let's move on to CPU costing and the effects of non-standard block sizes. Again the same 80MB table segment is read. The dbf_mbrc is set to 8, and in case of the WORKLOAD system statistics ("Normal" column below) the values have been set deliberately to mimic the NOWORKLOAD statistics, which means a MBRC of 8, sreadtim = 12 and mreadtim = 26. The results shown can be reproduced using the script "tablescan_04.sql".


Block size Noworkload Normal Number of Blocks
---------- ---------- ------ ----------------
2KB 7,729 10,854 40,000
4KB 4,387 5,429 20,000
8KB 2,717 2,717 10,000
16KB 1,881 1,361 5,000


Let's recall the formula to calculate the I/O cost with CPU costing enabled, reduced to the multi-block read requests part that matter in this particular case:

Cost = (number of multi-block read requests)*mreadtim/sreadtim

And here is the formula that is used to calculate mreadtim and sreadtim in the case of NOWORKLOAD statistics, which records only ioseektim (disk random seek time in milliseconds) and iotrfspeed (disk transfer speed in bytes per millisecond) for the I/O calculation:

MBRC = dbf_mbrc
sreadtim = ioseektim + db_block_size / iotfrspeed
mreadtim = ioseektim + dbf_mbrc * db_block_size / iotfrspeed

NOWORKLOAD system statistics

Slotting in the values we have, considering that we have non-standard block sizes and an adjusted dbf_mbrc at runtime:

2KB, NOWORKLOAD:

MBRC = 32 (adjusted for 2KB block size)
sreadtim = 10 + 2,048 / 4,096 = 10 + 0.5 = 10.5
mreadtim = 10 + 32 * 2,048 / 4,096 = 26

Cost = (40,000 / 32) * 26 / 10.5 = 3,095 (rounded), actually => 7,729 !

Clearly, something is going wrong here, the difference can't be explained by some kind of "rounding" issues.

After fiddling a bit around, it becomes obvious that the optimizer uses a different set of values for the formula:

2KB, NOWORKLOAD (actual):

MBRC = 32 (adjusted for 2KB block size)
sreadtim = 10 + 8192 / 4,096 = 10 + 2 = 12
mreadtim = 10 + 32 * 8,192 / 4,096 = 74 (!)

Cost = (40,000 / 32) * 74 / 12 = 7,708 (rounded), actually => 7,729

That's close enough to explain the remaining part with the CPU cost. So the optimizer uses an odd mixture of adjusted and unadjusted values which might be deliberate, but seem to be questionable at least, in particular a multi-block read request calculated to take 74ms.

The MBRC is adjusted, but obviously the default block size is used instead of the non-standard block size.

Let's check the results for the 16KB block size, first by looking at what we expect to get when slotting in the obvious values:

16KB, NOWORKLOAD:

MBRC = 4 (adjusted for 16KB block size)
sreadtim = 10 + 16,384 / 4,096 = 10 + 4 = 14
mreadtim = 10 + 4 * 16,384 / 4,096 = 26

Cost = (5,000 / 4) * 26 / 14 = 2,321 (rounded), actually => 1,881 !

Again the difference is significant, let's try the modified formula:

16KB, NOWORKLOAD (actual):

MBRC = 4 (adjusted for 16KB block size)
sreadtim = 10 + 8,192 / 4,096 = 10 + 2 = 12
mreadtim = 10 + 4 * 8,192 / 4,096 = 18

Cost = (5,000 / 4) * 18 / 12 = 1,875 (rounded), actually => 1,881

So it looks like my theory applies and the obvious question remains why the optimizer uses a quite unintuitive and odd set of values for the cost calculation of the NOWORKLOAD statistics.

Looking at the results when using the correct non-standard block size in the formula it's obvious that the variation in cost calculation for the non-standard block sizes would be much smaller than the actual variation observed. The actual smallest cost encountered was 1,881 for 16KB block size and 7,729 for 2KB. Using the correct block size this would be 2,321 (+6 CPU cost) for 16KB block size and 3,095 (+21 CPU cost) for the 2KB block size, which is much closer to the default block size cost of 2,717.

I've added another test case "tablescan_04a.sql" to the code depot which is not part of the official distribution. Its purpose is to check how the optimizer deals with the formula when dealing with a query based on multiple objects residing in multiple block sizes. The results show that for each individual object above formula is still used to estimate the cost, which makes the behaviour even more questionable why the optimizer is then not using the correct block sizes for each individual calculation.

WORKLOAD system statistics

What about the results of the WORKLOAD system statistics? How is it going to deal with the non-standard block sizes?

Let's check the formula:

MBRC = 8
mreadtim = 26
sreadtim = 12

as set in "tablescan_04.sql"

2KB, WORKLOAD:

Assuming an adjusted MRBC of 32 for the 2KB block size:

Cost = (40,000/32)*26/12 = 2,708 (rounded), actually 10,854 !

So again, something is clearly not following the assumptions. Let's try with the MBRC left unchanged (unadjusted):

2KB, WORKLOAD (actual):

Cost = (40,000/8)*26/12 = 10,833 (rounded), actually 10,854

Checking the same for the 16KB block size:

16KB, WORKLOAD:

Assuming an adjusted MRBC of 4 for the 16KB block size:

Cost = (5,000/4)*26/12 = 2,708 (rounded), actually 1,361 !

16KB, WORKLOAD (actual):

Cost = (5,000/8)*26/12 = 1,354 (rounded), actually 1,361

So the obvious problem of the WORKLOAD system statistics with non-standard block sizes is that the MBRC is not adjusted, but the number of blocks decrease/increase according to the block size used, resulting in a even larger variation in cost than the NOWORKLOAD statistics.

So I can only repeat what Jonathan has already written in his book: Be very cautious with using different block sizes for different objects. In particular with CPU costing enabled the cost based optimizer uses some questionable values to calculate the I/O cost leading to large variations in costs that very likely don't reflect the actual cost difference encountered at runtime. The result is that objects that reside in larger block sizes obviously are going to favor full table scans due to the lower cost, and the opposite applies to objects in smaller non-standard block sizes.

CPU costing and predicate re-ordering

One of the unique features of CPU costing is the ability to cost the predicate evaluation order and possibly perform a re-ordering to lower the cost (which can be prevented by using the ORDERED_PREDICATES hint). Running the test case provided by Jonathan against 11.1.0.6 and 11.1.0.7 shows a oddity regarding the costing of the TO_NUMBER function. Obviously the cost of 100 for a single call to TO_NUMBER doesn't apply in 11.1. This might be deliberate but seems to be questionable; other conversion functions like TO_CHAR or TO_DATE were still showing the same cost as in the other versions.

Here is the output from 10.2.0.4 of the "cpu_costing.sql" script:


Predicted cost (9.2.0.6): 1070604

Filter Predicate CPU cost
------------------------------------------------------------ ------------
TO_NUMBER("V1")=1 AND "N2"=18 AND "N1"=998 1,070,604

Predicted cost (9.2.0.6): 762787

Filter Predicate CPU cost
------------------------------------------------------------ ------------
"N1"=998 AND "N2"=18 AND TO_NUMBER("V1")=1 762,786

Predicted cost (9.2.0.6): 1070232

Filter Predicate CPU cost
------------------------------------------------------------ ------------
TO_NUMBER("V1")=1 AND "N1"=998 AND "N2"=18 1,070,231

Predicted cost (9.2.0.6): 762882

Filter Predicate CPU cost
------------------------------------------------------------ ------------
"N1"=998 AND TO_NUMBER("V1")=1 AND "N2"=18 762,881

Predicted cost (9.2.0.6): 770237

Filter Predicate CPU cost
------------------------------------------------------------ ------------
"N2"=18 AND "N1"=998 AND TO_NUMBER("V1")=1 770,236

Predicted cost (9.2.0.6): 785604

Filter Predicate CPU cost
------------------------------------------------------------ ------------
"N2"=18 AND TO_NUMBER("V1")=1 AND "N1"=998 785,604

Left to its own choice of predicate order

Filter Predicate CPU cost
------------------------------------------------------------ ------------
"N1"=998 AND "N2"=18 AND TO_NUMBER("V1")=1 762,786

And one last option where the coercion on v1 is not needed
Predicted cost (9.2.0.6): 770604

Filter Predicate CPU cost
------------------------------------------------------------ ------------
"V1"='1' AND "N2"=18 AND "N1"=998 770,604


Apart from some minor rounding issues the results correspond to those from 9.2 and 10.1.

Here's the output running the same against 11.1.0.7:


Predicted cost (9.2.0.6): 1070604

Filter Predicate CPU cost
------------------------------------------------------------ ------------
TO_NUMBER("V1")=1 AND "N2"=18 AND "N1"=998 770,604

Predicted cost (9.2.0.6): 762787

Filter Predicate CPU cost
------------------------------------------------------------ ------------
"N1"=998 AND "N2"=18 AND TO_NUMBER("V1")=1 762,781

Predicted cost (9.2.0.6): 1070232

Filter Predicate CPU cost
------------------------------------------------------------ ------------
TO_NUMBER("V1")=1 AND "N1"=998 AND "N2"=18 770,231

Predicted cost (9.2.0.6): 762882

Filter Predicate CPU cost
------------------------------------------------------------ ------------
"N1"=998 AND TO_NUMBER("V1")=1 AND "N2"=18 762,781

Predicted cost (9.2.0.6): 770237

Filter Predicate CPU cost
------------------------------------------------------------ ------------
"N2"=18 AND "N1"=998 AND TO_NUMBER("V1")=1 770,231

Predicted cost (9.2.0.6): 785604

Filter Predicate CPU cost
------------------------------------------------------------ ------------
"N2"=18 AND TO_NUMBER("V1")=1 AND "N1"=998 770,604

Left to its own choice of predicate order

Filter Predicate CPU cost
------------------------------------------------------------ ------------
"N1"=998 AND TO_NUMBER("V1")=1 AND "N2"=18 762,781

And one last option where the coercion on v1 is not needed
Predicted cost (9.2.0.6): 770604

Filter Predicate CPU cost
------------------------------------------------------------ ------------
"V1"='1' AND "N2"=18 AND "N1"=998 770,604


It's rather obvious that the TO_NUMBER function is not costed in the same way as previously, up to the point where 11g comes to a different conclusion when left on its own choice, and I doubt that the change is for the better, because the TO_NUMBER function is more often evaluated than necessary.

I've added some more test cases ("cpu_costing_2.sql" to "cpu_costing_5.sql") that show that other functions don't show this different treatment, so it seems to be particular issue of the TO_NUMBER function costing.

Single table selectivity, unknown bind variables and range comparisons

This difference showed up as a side effect of the "partition.sql" script. The recent releases (9.2.0.8, 10.2.0.4 and 11.1.0.6/7) seem to have been extended by an additional sanity check when applying the default 5% based selectivity of bind variables when performing range comparisons.

As pointed out by Jonathan it's quite unrealistic that a range comparison to an unknown bind variable results in a estimated cardinality lower than the cardinality estimated for an individual value. Consider e.g. a table consisting of 1,200 rows, 12 distinct values and a uniform distribution. A single value corresponds to 100 rows, but a range comparison to an unknown bind variables resulted previously in a reported cardinality of 60 (1/20 resp. 5% hard coded).

This is no longer the case with 9.2.0.8, 10.2.0.4 and 11.1.0.6/7: Obviously a lower limit of 1/NUM_DISTINCT applies, in this particular case this would be 100 instead of 60.

The rule seems to be more complex, and is again different in 11.1.0.6/7 than in previous versions, in particular when dealing with multiple predicates, but that's something to be left for Chapter 3 which deals with the "Single Table selectivity".

Updated code depot

You can download the updated code depot containing all scripts and the spool results from here: My homepage (SQLTools++, an open source lightweight SQL Oracle GUI for Windows)

The original code depot (still maintained by Jonathan) can be found here.

Friday, February 6, 2009

How to force a hard parse

It's not uncommon to be confronted with a bad behaving application that doesn't share its SQLs by using bind variables but uses literals instead. This leads to well known issues like increased CPU usage, library cache contention etc. due to the hard parse activities required.

On a recent OTN thread the question was raised, what to do if you are confronted with the opposite, a bad behaving application that shares SQL using bind variables that should not be shared? Although this might sound a bit odd at first, in pre-11g databases this "over-use" of bind variables can lead to severe issues, in particular if you have long running queries, possibly together with skewed data. Sharing SQL in such scenarios can lead to poor performance if the optimizer re-uses unsuitable execution plans that otherwise would not be used if a hard parse was forced using literals.

Obviously fixing the application and using literals where appropriate is the correct approach, but what can be done if you can't change the code, e.g. in case it's a third party application?

One possible solution is to "mis-use" the row level security feature of Oracle (RLS, often also called Virtual Private Database, VPD, also known as FGAC, Fine Grained Access Control) to modify the queries on the fly and therefore forcing a hard parse every time a query is using one of the objects the RLS policy is applied to.

The following code snippet demonstrates three slightly different approaches that were mentioned in the thread, all using the same basic principle: Add a non-filtering predicate to the query that makes the query unsharable resp. unique, e.g. like "1 = 1". The third one was contributed by Jonathan Lewis, by the way.


-- Global context approach
create table hard_parse_test
as
select * from all_objects
where rownum <= 1000;

exec dbms_stats.gather_table_stats(null, 'hard_parse_test')

create or replace context ctx_force_hard_parse
using pkg_rls_force_hard_parse
accessed globally;

create or replace package pkg_rls_force_hard_parse is
function force_hard_parse (in_schema varchar2, in_object varchar2) return varchar2;
procedure clear_context;
end pkg_rls_force_hard_parse;
/

create or replace package body pkg_rls_force_hard_parse is
g_counter pls_integer;

procedure clear_context
is
begin
dbms_session.clear_context('CTX_FORCE_HARD_PARSE', NULL, 'G_COUNTER');
end clear_context;

procedure set_context
is
begin
dbms_session.set_context('ctx_force_hard_parse', 'G_COUNTER', to_char(g_counter, 'TM'));
end set_context;

procedure get_context
is
begin
g_counter := to_number(SYS_CONTEXT('ctx_force_hard_parse', 'G_COUNTER'));
end get_context;

function force_hard_parse (in_schema varchar2, in_object varchar2) return varchar2
is
s_predicate varchar2(100);
begin
get_context;
if g_counter is null then
g_counter := 0;
end if;
g_counter := g_counter + 1;
if g_counter > 1000000 then
g_counter := 1;
end if;
set_context;
-- s_predicate := '1 = 1';
s_predicate := to_char(g_counter, 'TM') || ' = ' || to_char(g_counter, 'TM');
-- s_predicate := 'object_type = ''TABLE''';
return s_predicate;
end force_hard_parse;
begin
get_context;
if g_counter is null then
g_counter := 0;
set_context;
end if;
end pkg_rls_force_hard_parse;
/

exec DBMS_RLS.ADD_POLICY (USER, 'hard_parse_test', 'hard_parse_policy', USER, 'pkg_rls_force_hard_parse.force_hard_parse', 'select');

-- random approach
create table hard_parse_test_rand
as
select * from all_objects
where rownum <= 1000;

exec dbms_stats.gather_table_stats(null, 'hard_parse_test_rand')

create or replace package pkg_rls_force_hard_parse_rand is
function force_hard_parse (in_schema varchar2, in_object varchar2) return varchar2;
end pkg_rls_force_hard_parse_rand;
/

create or replace package body pkg_rls_force_hard_parse_rand is
function force_hard_parse (in_schema varchar2, in_object varchar2) return varchar2
is
s_predicate varchar2(100);
n_random pls_integer;
begin
n_random := round(dbms_random.value(1, 1000000));
-- s_predicate := '1 = 1';
s_predicate := to_char(n_random, 'TM') || ' = ' || to_char(n_random, 'TM');
-- s_predicate := 'object_type = ''TABLE''';
return s_predicate;
end force_hard_parse;
end pkg_rls_force_hard_parse_rand;
/

exec DBMS_RLS.ADD_POLICY (USER, 'hard_parse_test_rand', 'hard_parse_policy', USER, 'pkg_rls_force_hard_parse_rand.force_hard_parse', 'select');

-- sequence approach
create sequence hard_parse_test_seq maxvalue 1000000 cycle;

create table hard_parse_test_sequence
as
select * from all_objects
where rownum <= 1000;

exec dbms_stats.gather_table_stats(null, 'hard_parse_test_sequence')

create or replace package pkg_rls_force_hard_parse_seq is
function force_hard_parse (in_schema varchar2, in_object varchar2) return varchar2;
end pkg_rls_force_hard_parse_seq;
/

create or replace package body pkg_rls_force_hard_parse_seq is
function force_hard_parse (in_schema varchar2, in_object varchar2) return varchar2
is
s_predicate varchar2(100);
n_seq pls_integer;
begin
select hard_parse_test_seq.nextval
into n_seq
from dual;
-- s_predicate := '1 = 1';
s_predicate := to_char(n_seq, 'TM') || ' = ' || to_char(n_seq, 'TM');
-- s_predicate := 'object_type = ''TABLE''';
return s_predicate;
end force_hard_parse;
end pkg_rls_force_hard_parse_seq;
/

exec DBMS_RLS.ADD_POLICY (USER, 'hard_parse_test_sequence', 'hard_parse_policy', USER, 'pkg_rls_force_hard_parse_seq.force_hard_parse', 'select');

-- trace
alter session set tracefile_identifier = 'hard_parse_test_session_loop1';

exec dbms_monitor.session_trace_enable

declare
begin
for i in 1..1000 loop
for rec in (select * from hard_parse_test_sequence) loop
exit;
end loop;
end loop;
end;
/

exec dbms_monitor.session_trace_disable


If you check the trace files you'll see that the query in the PL/SQL loop got hard parsed for each execution, so this looks promising. Stress testing the implementation by running the loop from multiple sessions simultaneously showed that it seems to work well, and effectively prevents the sharing of the SQLs.

Using Tom Kyte's RUNSTATS package shows that there are not too many differences in resource consumption of the different approaches:


-- statistics
set timing on echo on serveroutput on trimspool on

spool hard_parse_force_rls_testcase.log

alter session set nls_language = 'AMERICAN';

alter system flush shared_pool;

exec runstats_pkg.rs_start

declare
begin
for i in 1..1000 loop
for rec in (select * from hard_parse_test) loop
exit;
end loop;
end loop;
end;
/

exec runstats_pkg.rs_middle

declare
begin
for i in 1..1000 loop
for rec in (select * from hard_parse_test_rand) loop
exit;
end loop;
end loop;
end;
/

exec runstats_pkg.rs_stop

spool off

-- statistics
set timing on echo on serveroutput on trimspool on

spool hard_parse_force_rls_testcase2.log

alter session set nls_language = 'AMERICAN';

alter system flush shared_pool;

exec runstats_pkg.rs_start

declare
begin
for i in 1..1000 loop
for rec in (select * from hard_parse_test_sequence) loop
exit;
end loop;
end loop;
end;
/

exec runstats_pkg.rs_middle

declare
begin
for i in 1..1000 loop
for rec in (select * from hard_parse_test_rand) loop
exit;
end loop;
end loop;
end;
/

exec runstats_pkg.rs_stop

spool off


Results for Global Context vs Random:


Run1 ran in 1941 hsecs
Run2 ran in 1869 hsecs
run 1 ran in 103,85% of the time

Name Run1 Run2 Diff
LATCH.list of block allocation 0 1 1
LATCH.transaction branch alloc 7 6 -1
STAT...session cursor cache co 1 0 -1
STAT...table scan blocks gotte 2,002 2,001 -1
STAT...redo entries 9 10 1
STAT...calls to kcmgcs 4 5 1
LATCH.user lock 0 1 1
LATCH.transaction allocation 0 1 1
LATCH.longop free list parent 7 6 -1
STAT...opened cursors current 1 2 1
LATCH.session timer 7 6 -1
LATCH.mostly latch-free SCN 7 6 -1
LATCH.threshold alerts latch 1 0 -1
LATCH.lgwr LWN SCN 7 6 -1
LATCH.ASM db client latch 14 12 -2
STAT...cursor authentications 3 5 2
LATCH.job_queue_processes para 0 2 2
LATCH.session idle bit 16 14 -2
LATCH.cache buffers lru chain 7 5 -2
LATCH.shared pool sim alloc 2 0 -2
LATCH.dml lock allocation 0 2 2
LATCH.undo global data 3 6 3
LATCH.parameter list 5 2 -3
STAT...table fetch continued r 3 0 -3
STAT...bytes received via SQL* 1,224 1,227 3
LATCH.redo allocation 16 19 3
LATCH.object queue header oper 50 46 -4
LATCH.In memory undo latch 8 12 4
LATCH.library cache lock alloc 12 16 4
LATCH.parallel query alloc buf 4 0 -4
STAT...consistent changes 37 32 -5
STAT...db block changes 47 42 -5
LATCH.session state list latch 6 0 -6
LATCH.active service list 40 33 -7
STAT...undo change vector size 2,132 2,140 8
STAT...parse time cpu 13 5 -8
LATCH.messages 124 116 -8
STAT...parse count (hard) 1,013 1,004 -9
STAT...parse time elapsed 15 5 -10
STAT...db block gets 39 28 -11
STAT...db block gets from cach 39 28 -11
LATCH.channel operations paren 98 84 -14
STAT...enqueue releases 1,020 1,005 -15
STAT...enqueue requests 1,021 1,005 -16
LATCH.checkpoint queue latch 184 168 -16
LATCH.library cache load lock 60 41 -19
STAT...redo size 2,884 2,904 20
STAT...workarea executions - o 38 14 -24
STAT...table scan rows gotten 178,060 178,030 -30
STAT...cluster key scans 47 8 -39
LATCH.kks stats 1,056 1,015 -41
STAT...rows fetched via callba 58 15 -43
STAT...cluster key scan block 51 8 -43
STAT...hot buffers moved to he 45 0 -45
STAT...workarea memory allocat 34 -12 -46
STAT...sorts (memory) 63 15 -48
STAT...free buffer inspected 49 0 -49
STAT...CPU used by this sessio 1,915 1,856 -59
STAT...parse count (total) 2,137 2,074 -63
STAT...CPU used when call star 1,921 1,857 -64
STAT...recursive cpu usage 1,918 1,853 -65
STAT...index scans kdiixs1 137 67 -70
STAT...Elapsed Time 1,944 1,873 -71
LATCH.SQL memory manager worka 489 416 -73
STAT...DB time 1,945 1,867 -78
STAT...index fetch by key 116 25 -91
STAT...session cursor cache hi 2,157 2,059 -98
STAT...opened cursors cumulati 2,172 2,071 -101
LATCH.enqueues 2,365 2,252 -113
STAT...execute count 3,208 3,094 -114
LATCH.enqueue hash chains 2,368 2,253 -115
STAT...calls to get snapshot s 3,210 3,091 -119
STAT...consistent gets - exami 377 131 -246
STAT...no work - consistent re 2,456 2,183 -273
STAT...buffer is not pinned co 617 230 -387
STAT...table fetch by rowid 555 103 -452
STAT...consistent gets 4,841 4,323 -518
STAT...consistent gets from ca 4,841 4,323 -518
STAT...session logical reads 4,880 4,351 -529
STAT...sorts (rows) 3,173 2,561 -612
STAT...buffer is pinned count 653 9 -644
LATCH.cache buffers chains 9,799 8,728 -1,071
LATCH.simulator hash latch 50 2,023 1,973
STAT...recursive calls 8,243 6,256 -1,987
LATCH.session allocation 7,735 2,065 -5,670
LATCH.global ctx hash table la 6,004 0 -6,004
LATCH.library cache lock 1,011,473 1,003,687 -7,786
LATCH.shared pool simulator 509,871 517,895 8,024
LATCH.library cache pin 34,233 22,204 -12,029
LATCH.library cache 1,061,947 1,040,025 -21,922
STAT...session pga memory max 310,652 196,608 -114,044
STAT...session uga memory 130,928 0 -130,928
LATCH.row cache objects 37,688,620 37,550,193 -138,427
STAT...session uga memory max 299,884 123,440 -176,444
STAT...session pga memory 310,652 0 -310,652
LATCH.shared pool 896,770 283,900 -612,870

Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
41,235,708 40,439,510 -796,198 101.97%


Results for Sequence vs. Random:


Run1 ran in 1912 hsecs
Run2 ran in 1863 hsecs
run 1 ran in 102,63% of the time

Name Run1 Run2 Diff
LATCH.compile environment latc 1 0 -1
LATCH.job_queue_processes para 1 0 -1
LATCH.threshold alerts latch 0 1 1
LATCH.parameter list 3 2 -1
LATCH.resmgr:actses change gro 1 0 -1
LATCH.KMG MMAN ready and start 7 6 -1
LATCH.FOB s.o list latch 1 0 -1
LATCH.parameter table allocati 1 0 -1
STAT...cursor authentications 4 3 -1
STAT...session cursor cache co 1 0 -1
STAT...index crx upgrade (posi 2 1 -1
STAT...calls to kcmgcs 4 5 1
STAT...shared hash latch upgra 2 1 -1
LATCH.resmgr:active threads 2 0 -2
LATCH.resmgr:free threads list 2 0 -2
STAT...table fetch continued r 2 0 -2
LATCH.post/wait queue 2 0 -2
LATCH.user lock 2 0 -2
LATCH.dummy allocation 2 0 -2
LATCH.mostly latch-free SCN 9 6 -3
LATCH.lgwr LWN SCN 9 6 -3
LATCH.list of block allocation 3 0 -3
LATCH.transaction allocation 3 0 -3
STAT...change write time 3 0 -3
STAT...parse time elapsed 10 13 3
LATCH.active service list 44 41 -3
STAT...workarea memory allocat -18 -21 -3
LATCH.parallel query alloc buf 4 0 -4
LATCH.PL/SQL warning settings 2,010 2,006 -4
STAT...free buffer requested 8 12 4
STAT...parse time cpu 10 6 -4
STAT...consistent changes 37 32 -5
STAT...bytes received via SQL* 1,233 1,227 -6
LATCH.resmgr group change latc 6 0 -6
LATCH.channel operations paren 98 92 -6
STAT...physical read total IO 0 6 6
STAT...physical read IO reques 0 6 6
STAT...physical reads cache 0 6 6
STAT...physical reads 0 6 6
STAT...user I/O wait time 0 7 7
LATCH.library cache pin alloca 15 7 -8
LATCH.session state list latch 8 0 -8
LATCH.Consistent RBA 9 1 -8
LATCH.active checkpoint queue 15 6 -9
LATCH.simulator lru latch 10 0 -10
STAT...parse count (hard) 1,016 1,006 -10
LATCH.In memory undo latch 25 8 -17
LATCH.cache buffers lru chain 30 12 -18
LATCH.redo allocation 34 15 -19
LATCH.client/application info 24 0 -24
LATCH.shared pool sim alloc 0 24 24
STAT...workarea executions - o 38 13 -25
LATCH.messages 158 126 -32
LATCH.redo writing 54 22 -32
LATCH.library cache lock alloc 43 8 -35
STAT...rows fetched via callba 53 15 -38
STAT...hot buffers moved to he 41 2 -39
STAT...CPU used by this sessio 1,880 1,839 -41
LATCH.SQL memory manager worka 456 412 -44
STAT...recursive cpu usage 1,880 1,835 -45
STAT...cluster key scans 51 5 -46
STAT...CPU used when call star 1,885 1,839 -46
STAT...Elapsed Time 1,914 1,866 -48
LATCH.kks stats 1,084 1,036 -48
STAT...cluster key scan block 55 5 -50
LATCH.object queue header heap 90 36 -54
STAT...DB time 1,915 1,860 -55
STAT...sorts (memory) 68 12 -56
STAT...free buffer inspected 61 0 -61
STAT...index scans kdiixs1 133 66 -67
LATCH.object queue header oper 136 60 -76
STAT...commit cleanouts 101 0 -101
STAT...commit cleanouts succes 101 0 -101
STAT...calls to kcmgas 101 0 -101
STAT...deferred (CURRENT) bloc 101 0 -101
LATCH.session idle bit 123 14 -109
STAT...parse count (total) 2,214 2,071 -143
LATCH.library cache load lock 206 28 -178
LATCH.checkpoint queue latch 420 240 -180
STAT...index fetch by key 217 21 -196
STAT...session cursor cache hi 2,255 2,058 -197
STAT...redo entries 211 10 -201
LATCH.enqueues 2,543 2,334 -209
LATCH.dml lock allocation 214 0 -214
STAT...opened cursors cumulati 2,289 2,067 -222
STAT...no work - consistent re 2,450 2,182 -268
STAT...db block gets from cach 345 30 -315
STAT...db block gets 345 30 -315
STAT...enqueue releases 1,327 1,007 -320
STAT...enqueue requests 1,328 1,007 -321
LATCH.undo global data 322 1 -321
STAT...consistent gets - exami 465 123 -342
STAT...buffer is not pinned co 600 228 -372
STAT...db block changes 451 43 -408
STAT...table fetch by rowid 545 102 -443
STAT...consistent gets 4,924 4,314 -610
STAT...consistent gets from ca 4,924 4,314 -610
STAT...sorts (rows) 3,178 2,561 -617
STAT...buffer is pinned count 654 9 -645
LATCH.enqueue hash chains 3,074 2,336 -738
LATCH.library cache lock 1,008,133 1,007,327 -806
STAT...session logical reads 5,269 4,344 -925
LATCH.simulator hash latch 242 2,027 1,785
STAT...execute count 5,310 3,090 -2,220
STAT...calls to get snapshot s 5,413 3,087 -2,326
LATCH.library cache 1,040,087 1,043,596 3,509
LATCH.library cache pin 18,535 22,182 3,647
LATCH.row cache objects 37,693,219 37,688,109 -5,110
STAT...recursive calls 11,801 6,131 -5,670
LATCH.sequence cache 6,210 0 -6,210
LATCH.cache buffers chains 18,122 8,807 -9,315
LATCH.shared pool simulator 538,704 558,857 20,153
STAT...undo change vector size 22,736 2,148 -20,588
LATCH.session allocation 25,092 2,957 -22,135
STAT...physical read total byt 0 49,152 49,152
STAT...physical read bytes 0 49,152 49,152
STAT...redo size 65,780 2,928 -62,852
STAT...session uga memory 65,464 0 -65,464
STAT...session pga memory 131,072 65,536 -65,536
STAT...session pga memory max 262,144 131,072 -131,072
STAT...session uga memory max 315,052 65,464 -249,588
LATCH.shared pool 702,224 301,771 -400,453

Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
41,062,061 40,644,708 -417,353 101.03%


In passing, it looks like that the tests on 10.2.0.4 Win32bit revealed that the 10g RLS code has some built-in check which ignores non-filtering predicates like "1 = 1", at least the predicate doesn't show up in the DBMS_XPLAN.DISPLAY output whereas an actual filter predicate like "OBJECT_TYPE = 'TABLE'" does show up. Still the hard parse is forced, so it's even better if the query is effectively not modified.

It's worth to mention that the RLS policy adds a significant overhead. If you check the trace files you'll notice that the policy function gets called once per parse and obviously twice per execution, so a single parse/execute of a query causes two hard parses and three calls to the policy function.

By the way, Tanel Poder mentioned in the OTN thread that he demonstrated a quite similar solution some time back at HotSOS which I wasn't aware of. His demo shows some enhanced versions of the solution including the ability to check for particular SQLs so that not every SQL is affected. Thanks, Tanel, for the information and link.