December 22, 2010, 6:21 pm
Ha. This one was a little surprising. I ran across a SQL statement that gets fired off hundreds at a time in rapid succession. Each execution taking several seconds – too long for thousands of executions in a row. The statement looked like this (cleaned up to protect the guilty):
b1 := '10355P034001SGL00066';
b2 := '10355P034001SGL00066';
select count(cust_id)
from customers
where substr(cust_id,1,length(:b1)) = :b2;
What was the developer trying to do? How can we fix it? Your comments are welcomed.
Continue reading ‘Funny Developer Tricks – (substr(cust_id,1,length(:b1))’ »
December 10, 2010, 11:32 am
In a previous post (GATHER_PLAN_STATISTICS) I mentioned that SQL Profiles and Baselines can both be applied to a single statement. In this case, it appears that the hints are merged. The Notes section of the XPLAN output shows that both the Baseline and the Profile are in effect. I wanted to prove to myself that the hints from both the Profile and Baseline were indeed applied. So here’s my simple test case:
Basic Design For the Test:
- Use a Baseline to make a statement do something it wouldn’t normally do
- Add a Profile that makes the same statement do something else it wouldn’t normally do
- Verify that the statement now does both “thingies”
> !sql
sqlplus "/ as sysdba"
SQL*Plus: Release 11.2.0.1.0 Production on Tue Feb 2 20:09:53 2010
Copyright (c) 1982, 2009, Oracle. All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
SYS@LAB112> -- first the set up
SYS@LAB112> -- 32M row table with an index on col1
SYS@LAB112> !cat avgskewi.sql
select avg(pk_col) from kso.skew
where col1 = 136133
/
SYS@LAB112> @avgskewi
AVG(PK_COL)
-----------
15636133
1 row selected.
Elapsed: 00:00:00.00
SYS@LAB112>
SYS@LAB112> @find_sql
Enter value for sql_text: %where col1 = 136133%
Enter value for sql_id:
SQL_ID CHILD PLAN_HASH EXECS AVG_ETIME AVG_LIO SQL_TEXT
------------- ------ ---------- ---------- ------------- ------------ ------------------------------------------------------------
84q0zxfzn5u6s 0 3723858078 3 .00 36 select avg(pk_col) from kso.skew where col1 = 136133
1 row selected.
Elapsed: 00:00:00.12
SYS@LAB112>
SYS@LAB112> @dplan
Enter value for sql_id: 84q0zxfzn5u6s
Enter value for child_no:
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID 84q0zxfzn5u6s, child number 0
-------------------------------------
select avg(pk_col) from kso.skew where col1 = 136133
Plan hash value: 3723858078
------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 35 (100)| |
| 1 | SORT AGGREGATE | | 1 | 24 | | |
| 2 | TABLE ACCESS BY INDEX ROWID| SKEW | 35 | 840 | 35 (0)| 00:00:01 |
|* 3 | INDEX RANGE SCAN | SKEW_COL1 | 35 | | 3 (0)| 00:00:01 |
------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
3 - access("COL1"=136133)
20 rows selected.
Elapsed: 00:00:00.03
SYS@LAB112>
SYS@LAB112> -- so the index is used as expected - does 36 lio's and completes in < 1/100 of a second
SYS@LAB112> -- now let's make it do something it wouldn't normally do (with a Baseline)
SYS@LAB112> -- one way is to create a Profile, create a Baseline on top, drop the Profile
SYS@LAB112>
SYS@LAB112>
SYS@LAB112>
SYS@LAB112> @create_1_hint_sql_profile
Enter value for sql_id: 84q0zxfzn5u6s
Enter value for profile_name (PROFILE_sqlid_MANUAL): PROFILE_84q0zxfzn5u6s_GPS
Enter value for category (DEFAULT):
Enter value for force_matching (false):
Enter value for hint: full(skew@sel$1)
Profile PROFILE_84q0zxfzn5u6s_FULL created.
PL/SQL procedure successfully completed.
SYS@LAB112> @avgskewi
AVG(PK_COL)
-----------
15636133
Elapsed: 00:00:12.71
SYS@LAB112>
SYS@LAB112> @find_sql
Enter value for sql_text:
Enter value for sql_id: 84q0zxfzn5u6s
no rows selected
Elapsed: 00:00:00.18
SYS@LAB112>
SYS@LAB112> -- run again, SPM makes you run it twice ...
SYS@LAB112>
SYS@LAB112> @avgskewi
AVG(PK_COL)
-----------
15636133
Elapsed: 00:00:07.32
SYS@LAB112>
SYS@LAB112> @find_sql
Enter value for sql_text:
Enter value for sql_id: 84q0zxfzn5u6s
SQL_ID CHILD PLAN_HASH EXECS AVG_ETIME AVG_LIO SQL_TEXT
------------- ------ ---------- ---------- ------------- ------------ ------------------------------------------------------------
84q0zxfzn5u6s 0 568322376 1 7.31 162,301 select avg(pk_col) from kso.skew where col1 = 136133
Elapsed: 00:00:00.10
SYS@LAB112>
SYS@LAB112> @dplan
Enter value for sql_id: 84q0zxfzn5u6s
Enter value for child_no:
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID 84q0zxfzn5u6s, child number 0
-------------------------------------
select avg(pk_col) from kso.skew where col1 = 136133
Plan hash value: 568322376
---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 28360 (100)| |
| 1 | SORT AGGREGATE | | 1 | 24 | | |
|* 2 | TABLE ACCESS FULL| SKEW | 35 | 840 | 28360 (1)| 00:05:41 |
---------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("COL1"=136133)
Note
-----
- SQL profile PROFILE_84q0zxfzn5u6s_FULL used for this statement
23 rows selected.
Elapsed: 00:00:00.05
SYS@LAB112>
SYS@LAB112> -- so it's now doing a full table scan, 162K lio's and takes several seconds
SYS@LAB112>
SYS@LAB112> -- now create the Baseline on the statement that's already using a Profile
SYS@LAB112>
SYS@LAB112> @create_baseline
Enter value for sql_id: 84q0zxfzn5u6s
Enter value for plan_hash_value: 568322376
Enter value for fixed (NO):
Enter value for enabled (YES):
Enter value for plan_name (SQL_sqlid_planhashvalue):
sql_id: 84q0zxfzn5u6s
plan_hash_value: 568322376
fixed: NO
enabled: YES
plan_name: SQL_84q0zxfzn5u6s_568322376
sql_handle: SYS_SQL_94dc89c011141f02
Baseline SQL_84q0zxfzn5u6s_568322376 created.
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.06
SYS@LAB112>
SYS@LAB112> @avgskewi
AVG(PK_COL)
-----------
15636133
Elapsed: 00:00:07.44
SYS@LAB112> @avgskewi
AVG(PK_COL)
-----------
15636133
Elapsed: 00:00:07.52
SYS@LAB112>
SYS@LAB112> -- obviously still doing the full table scan, but let's check anyway
SYS@LAB112>
SYS@LAB112> @dplan
Enter value for sql_id: 84q0zxfzn5u6s
Enter value for child_no:
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID 84q0zxfzn5u6s, child number 0
-------------------------------------
select avg(pk_col) from kso.skew where col1 = 136133
Plan hash value: 568322376
---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 28360 (100)| |
| 1 | SORT AGGREGATE | | 1 | 24 | | |
|* 2 | TABLE ACCESS FULL| SKEW | 35 | 840 | 28360 (1)| 00:05:41 |
---------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("COL1"=136133)
Note
-----
- SQL profile PROFILE_84q0zxfzn5u6s_FULL used for this statement
- SQL plan baseline SQL_84Q0ZXFZN5U6S_568322376 used for this statement
24 rows selected.
Elapsed: 00:00:00.03
SYS@LAB112>
SYS@LAB112> -- let's check hints in Profile and Baseline
SYS@LAB112>
SYS@LAB112> @sql_profile_hints
Enter value for profile_name: PROFILE_84q0zxfzn5u6s_FULL
HINT
------------------------------------------------------------------------------------------------------------------------------------------------------
full(skew@sel$1)
1 rows selected.
Elapsed: 00:00:00.10
SYS@LAB112>
SYS@LAB112> @baseline_hints
Enter value for baseline_plan_name: SQL_84Q0ZXFZN5U6S_568322376
OUTLINE_HINTS
------------------------------------------------------------------------------------------------------------------------------------------------------
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('11.2.0.1')
DB_VERSION('11.2.0.1')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
FULL(@"SEL$1" "SKEW"@"SEL$1")
6 rows selected.
Elapsed: 00:00:00.09
SYS@LAB112>
SYS@LAB112> -- so the Baseline has inherited the full hint
SYS@LAB112>
SYS@LAB112> -- now let's drop the original Profile and add another non-standard hint to see if they are merged
SYS@LAB112>
SYS@LAB112> @drop_sql_profile
Enter value for profile_name: PROFILE_84q0zxfzn5u6s_FULL
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.02
SYS@LAB112>
SYS@LAB112> @create_1_hint_sql_profile
Enter value for sql_id: 84q0zxfzn5u6s
Enter value for profile_name (PROFILE_sqlid_MANUAL): PROFILE_84q0zxfzn5u6s_GPS
Enter value for category (DEFAULT):
Enter value for force_matching (false):
Enter value for hint: GATHER_PLAN_STATISTICS
Profile PROFILE_84q0zxfzn5u6s_GPS created.
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.05
SYS@LAB112> @avgskewi
AVG(PK_COL)
-----------
15636133
1 row selected.
Elapsed: 00:00:07.51
SYS@LAB112> /
AVG(PK_COL)
-----------
15636133
1 row selected.
Elapsed: 00:00:08.22
SYS@LAB112>
SYS@LAB112> -- if that worked we should still have the full table scan from the Baseline, and the extended stats from the Profile with GATHER_PLAN_STATISTICS
SYS@LAB112>
SYS@LAB112> !cat dplan_allstats.sql
set lines 180
select * from table(dbms_xplan.display_cursor('&sql_id','&child_no','allstats +peeked_binds'))
/
SYS@LAB112> @dplan_allstats
Enter value for sql_id: 84q0zxfzn5u6s
Enter value for child_no:
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID 84q0zxfzn5u6s, child number 1
-------------------------------------
select avg(pk_col) from kso.skew where col1 = 136133
Plan hash value: 568322376
----------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads |
----------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 2 | | 2 |00:00:15.69 | 324K| 324K|
| 1 | SORT AGGREGATE | | 2 | 1 | 2 |00:00:15.69 | 324K| 324K|
|* 2 | TABLE ACCESS FULL| SKEW | 2 | 35 | 64 |00:00:12.02 | 324K| 324K|
----------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("COL1"=136133)
Note
-----
- SQL profile PROFILE_84q0zxfzn5u6s_GPS used for this statement
- SQL plan baseline SQL_84Q0ZXFZN5U6S_568322376 used for this statement
24 rows selected.
Elapsed: 00:00:00.03
SYS@LAB112>
SYS@LAB112> -- notice that the XPLAN output has A-Rows and A-Time columns - means GATHER_PLAN_STATISTICS was used
SYS@LAB112> -- otherwise it would have thrown a warning message
SYS@LAB112>
SYS@LAB112> -- so that worked - it merged the hints!
SYS@LAB112>
SYS@LAB112> -- quick verify
SYS@LAB112>
SYS@LAB112> @sql_profile_hints
Enter value for profile_name: PROFILE_84q0zxfzn5u6s_GPS
HINT
------------------------------------------------------------------------------------------------------------------------------------------------------
GATHER_PLAN_STATISTICS
1 rows selected.
Elapsed: 00:00:00.04
SYS@LAB112> @baseline_hints
Enter value for baseline_plan_name: SQL_84Q0ZXFZN5U6S_568322376
OUTLINE_HINTS
-----------------------------------------------------------------------------------------------------------------------------------------------------------
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('11.2.0.1')
DB_VERSION('11.2.0.1')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
FULL(@"SEL$1" "SKEW"@"SEL$1")
6 rows selected.
Elapsed: 00:00:00.09
SYS@LAB112>
SYS@LAB112> -- one more test, drop the Profile and the extended stats should go away
SYS@LAB112>
SYS@LAB112> @drop_sql_profile
Enter value for profile_name: PROFILE_84q0zxfzn5u6s_GPS
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.02
SYS@LAB112> @avgskewi
AVG(PK_COL)
-----------
15636133
1 row selected.
Elapsed: 00:00:07.20
SYS@LAB112> /
AVG(PK_COL)
-----------
15636133
1 row selected.
Elapsed: 00:00:07.91
SYS@LAB112> @dplan_allstats
Enter value for sql_id: 84q0zxfzn5u6s
Enter value for child_no:
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID 84q0zxfzn5u6s, child number 1
-------------------------------------
select avg(pk_col) from kso.skew where col1 = 136133
Plan hash value: 568322376
--------------------------------------------
| Id | Operation | Name | E-Rows |
--------------------------------------------
| 0 | SELECT STATEMENT | | |
| 1 | SORT AGGREGATE | | 1 |
|* 2 | TABLE ACCESS FULL| SKEW | 35 |
--------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("COL1"=136133)
Note
-----
- SQL plan baseline SQL_84Q0ZXFZN5U6S_568322376 used for this statement
- Warning: basic plan statistics not available. These are only collected when:
* hint 'gather_plan_statistics' is used for the statement or
* parameter 'statistics_level' is set to 'ALL', at session or system level
26 rows selected.
Elapsed: 00:00:00.03
SYS@LAB112>
SYS@LAB112> -- yep no more extended stats (warning message), but the full table scan is still working
SYS@LAB112>
SYS@LAB112> -- let's put it back the way it was
SYS@LAB112>
SYS@LAB112> @baselines
Enter value for sql_text:
Enter value for name:
Enter value for plan_name: SQL_84Q0ZXFZN5U6S_568322376
SQL_HANDLE PLAN_NAME SQL_TEXT ENABLED ACC FIX LAST_EXECUTED
------------------------------ ------------------------------ -------------------------------------------------- ------- --- --- ----------------
SYS_SQL_94dc89c011141f02 SQL_84Q0ZXFZN5U6S_568322376 select avg(pk_col) from kso.skew YES YES NO 02-feb-10 20:19
1 row selected.
Elapsed: 00:00:00.04
SYS@LAB112>
SYS@LAB112> @drop_baseline
Enter value for sql_handle: SYS_SQL_94dc89c011141f02
Enter value for plan_name: SQL_84Q0ZXFZN5U6S_568322376
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.01
SYS@LAB112> @avgskewi
AVG(PK_COL)
-----------
15636133
1 row selected.
Elapsed: 00:00:00.01
SYS@LAB112> /
AVG(PK_COL)
-----------
15636133
1 row selected.
Elapsed: 00:00:00.00
SYS@LAB112> @dplan_allstats
Enter value for sql_id: 84q0zxfzn5u6s
Enter value for child_no:
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID 84q0zxfzn5u6s, child number 0
-------------------------------------
select avg(pk_col) from kso.skew where col1 = 136133
Plan hash value: 3723858078
-----------------------------------------------------------
| Id | Operation | Name | E-Rows |
-----------------------------------------------------------
| 0 | SELECT STATEMENT | | |
| 1 | SORT AGGREGATE | | 1 |
| 2 | TABLE ACCESS BY INDEX ROWID| SKEW | 35 |
|* 3 | INDEX RANGE SCAN | SKEW_COL1 | 35 |
-----------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
3 - access("COL1"=136133)
Note
-----
- Warning: basic plan statistics not available. These are only collected when:
* hint 'gather_plan_statistics' is used for the statement or
* parameter 'statistics_level' is set to 'ALL', at session or system level
26 rows selected.
Elapsed: 00:00:00.03
SYS@LAB112>
SYS@LAB112> -- back to using the index and no stats
As usual I used a bunch of my scripts. I believe all the scripts referenced can be found in one of these two zip files:
Controlling Execution Plans Zip File
My Favorite Scripts 2010 zip file
I have a few thoughts as to why the developers decided to implement these two features this way. Remember that SQL Profiles were designed to be generated by the SQL Tuning Advisor which does statistical analysis on a query and potentially produces hints to correct calculations that the optimizer would otherwise get wrong. So it’s possible that the developers decided they wanted these types of statistical correction hints to be combined with plans already being “enforced” by Baselines. I must say though that I don’t really think these two constructs would work well together in most cases as the hints may well end up working against each other. And since Baselines are aware of the plan they are trying to reproduce, anything that actually alters the plan would basically disable all the hints associated with the Baseline. Although I expect that the plan output would probably still say the Baseline had been used. – I haven’t tested that though – so much to do, so little time.