SQL_IDs and baselines

There have been some interesting posts from Marcin Przepiorowski and Kerry Osborne about mapping sql plan management (spm) baselines to a corresponding sql id.

The key to sql plan baselines (DBA_SQL_PLAN_BASELINES) is SIGNATURE.

And why signature? It’s not just another change to the key to identifying sql statements (HASH_VALUE -> (NEW_)HASH_VALUE / OLD_HASH_VALUE -> SQL_ID).

It’s use in baselines because it’s a more flexible mechanism than a straight up hash – One sql plan baseline can be used against more than one sql id.

As Christian Antognini explains so effectively in his book, when baselines are involved, a sql statement is “normalized to make it both case-insensitive and independent of the blank spaces in the text”.

So, when you look at statements in V$SQL, we’re not talking here about the FORCE_MATCHING_SIGNATURE but EXACT_MATCHING_SIGNATURE.

For example, let’s find three statements with different sql ids but the same signature:

SQL> create table t1
  2  (col1 number);

Table created.

SQL> select /*+ find_me */
  2         *
  3  from   t1
  4  where        col1 = 3;

no rows selected

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

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
SQL_ID  cr6chh7p7vvzt, child number 0
-------------------------------------
select /*+ find_me */        * from   t1 where        col1 = 3

Plan hash value: 3617692013

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |     2 (100)|          |
|*  1 |  TABLE ACCESS FULL| T1   |     1 |    13 |     2   (0)| 00:00:01 |

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

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

   1 - filter("COL1"=3)


22 rows selected.

SQL> select /*+ find_me */
  2         *
  3  from   t1
  4  where  col1 =        3;

no rows selected

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

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
SQL_ID  8j52h3wtgvu3n, child number 0
-------------------------------------
select /*+ find_me */        * from   t1 where  col1 =        3

Plan hash value: 3617692013

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |     2 (100)|          |
|*  1 |  TABLE ACCESS FULL| T1   |     1 |    13 |     2   (0)| 00:00:01 |

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

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

   1 - filter("COL1"=3)


22 rows selected.

SQL> SELECT /*+ find_me */ *
  2  FROM   t1
  3  WHERE  col1 =        3;

no rows selected

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

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
SQL_ID  894k8t6nu8kbf, child number 0
-------------------------------------
SELECT /*+ find_me */ * FROM   t1 WHERE  col1 =        3

Plan hash value: 3617692013

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |     2 (100)|          |
|*  1 |  TABLE ACCESS FULL| T1   |     1 |    13 |     2   (0)| 00:00:01 |

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

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

   1 - filter("COL1"=3)

22 rows selected.

SQL> select sql_id, hash_value, old_hash_value, exact_matching_signature, force_matching_signature
  2  from v$sql 
  3  where sql_id IN ('cr6chh7p7vvzt','8j52h3wtgvu3n','894k8t6nu8kbf');

SQL_ID        HASH_VALUE OLD_HASH_VALUE EXACT_MATCHING_SIGNATURE FORCE_MATCHING_SIGNATURE
------------- ---------- -------------- ------------------------ ------------------------
894k8t6nu8kbf 2846116206     4072117629               4.4562E+18               1.2887E+19
8j52h3wtgvu3n  855500916     4269126066               4.4562E+18               1.2887E+19
cr6chh7p7vvzt 3934121977      717076022               4.4562E+18               1.2887E+19

Now, let’s load them into a SPM baseline:

SQL> declare
  2   l_op pls_integer;
  3  begin
  4   l_op := dbms_spm.load_plans_from_cursor_cache(sql_id =>'cr6chh7p7vvzt');
  5   l_op := dbms_spm.load_plans_from_cursor_cache(sql_id =>'8j52h3wtgvu3n');
  6   l_op := dbms_spm.load_plans_from_cursor_cache(sql_id =>'894k8t6nu8kbf');
  7  end;
  8  /

PL/SQL procedure successfully completed.

SQL> set long 10000
SQL> select to_char(signature), sql_text from dba_sql_plan_baselines where signature = 4456219368825
610060 order by created desc;

TO_CHAR(SIGNATURE)
----------------------------------------
SQL_TEXT
--------------------------------------------------------------------------------
4456219368825610060
select /*+ find_me */
       *
from   t1
where        col1 = 3


SQL> 

Note how the SQL text is from the first statement, the only statement that caused the baseline plan to be created.

What’s the primary purpose of the SQL text in DBA_SQL_PLAN_BASELINES – well, probably as Christian again suggests, to check that the statement for the baseline is actually equivalent to the one being run in the event of hash collisons.

So, now let’s re-run those SELECTs from earlier and watch the baseline kick in for all three:

SQL> select /*+ find_me */
  2         *
  3  from   t1
  4  where        col1 = 3;

no rows selected

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

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
SQL_ID  cr6chh7p7vvzt, child number 0
-------------------------------------
select /*+ find_me */        * from   t1 where        col1 = 3

Plan hash value: 3617692013

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |     2 (100)|          |
|*  1 |  TABLE ACCESS FULL| T1   |     1 |    13 |     2   (0)| 00:00:01 |

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

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

   1 - filter("COL1"=3)

Note
-----
   - SQL plan baseline SQL_PLAN_3vpxbwzn11rucdbd90e8e used for this statement

23 rows selected.

SQL> select /*+ find_me */
  2         *
  3  from   t1
  4  where  col1 =        3;

no rows selected

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

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
SQL_ID  8j52h3wtgvu3n, child number 0
-------------------------------------
select /*+ find_me */        * from   t1 where  col1 =        3

Plan hash value: 3617692013

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |     2 (100)|          |
|*  1 |  TABLE ACCESS FULL| T1   |     1 |    13 |     2   (0)| 00:00:01 |

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

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

   1 - filter("COL1"=3)

Note
-----
   - SQL plan baseline SQL_PLAN_3vpxbwzn11rucdbd90e8e used for this statement

23 rows selected.

SQL> SELECT /*+ find_me */ *
  2  FROM   t1
  3  WHERE  col1 =        3;

no rows selected

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

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
SQL_ID  894k8t6nu8kbf, child number 0
-------------------------------------
SELECT /*+ find_me */ * FROM   t1 WHERE  col1 =        3

Plan hash value: 3617692013

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |     2 (100)|          |
|*  1 |  TABLE ACCESS FULL| T1   |     1 |    13 |     2   (0)| 00:00:01 |

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

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

   1 - filter("COL1"=3)

Note
-----
   - SQL plan baseline SQL_PLAN_3vpxbwzn11rucdbd90e8e used for this statement

23 rows selected.

SQL> 

That’s it really.

So, just showing that signature to sql id is not necessarily a one-to-one relationship but can be one-to-many.

Whilst we’re talking baselines, have you read these interesting posts from Maxym Kharchenko (they’re from a while back but I’ve only recently discovered his blog) showing that, amongst other things, because baselines are essentially based on a sql text match, they can kick in where you don’t intend them to, for example statements that look the same but aren’t and might involve objects with the same name but in different schemas, even different structures. When you think about it, it makes sense how it can happen but it surely can’t be intended that way.

Cardinality Feedback

True to form, Kerry Osborne has another excellent post, this time on Cardinality Feedback.

If the mark of a good post is that it sets you off thinking and investigating then he’s nailed it again.

I started to comment on his post, but it was getting long and messy and I thought it easy to make a comment with a post of my own. Apart from anything else, I always seem to cock up the formatting when making longer comments with examples, etc.

So, hopefully, you’ve read Kerry’s article and he asked where Oracle stored the opt_estimate fudge factor feedback that he could see in his trace and that came through when using a baseline created from the plan changed by cardinality feedback.

My initial reaction was that I thought they would be independent and so began this little investigation (which isn’t finished yet).

First tangent of the day … on the subject of OPT_ESTIMATE – it was my belief that this was one of the principal mechanisms used by sql plan baselines. I know it was very popular with standalone sql profiles. I’ve got a controlled number of baselines in my environment – a couple of hundred – none of them use OPT_ESTIMATE in SQLOBJ$DATA.COMP_DATA. Surprising.

Anyway, I thought in terms of having a standalone demo on Cardinality Feedback, why reinvent the wheel?

On his blog article on the subject, Tom Kyte has a standalone demo. Perfect I thought, I’ll reuse it.

And it goes a little something like this:

1. Create table and package:

create or replace type str2tblType as table of varchar2(30);
/
create or replace function str2tbl( 
  p_str in varchar2, 
  p_delim in varchar2 default ',' )
return str2tblType
PIPELINED
as
  l_str      long default p_str || p_delim;
  l_n        number;
begin
   loop
       l_n := instr( l_str, p_delim );
       exit when (nvl(l_n,0) = 0);
       pipe row ( ltrim(rtrim(substr(l_str,1,l_n-1))) );
       l_str := substr( l_str, l_n+1 );
   end loop;
   return;
end;
/

2. Set up variable in sql*plus and execute sql statement once, get plan

var in_list varchar2(255)
exec :in_list := 'DBMS_PIPE,DBMS_OUTPUT,UTL_FILE';

select * from TABLE(cast( str2tbl(:in_list ) as str2tblType) ) t;

select * from table(dbms_xplan.display_cursor);

Which produced the following plan:

SQL> select * from TABLE(cast( str2tbl(:in_list ) as str2tblType) ) t;

COLUMN_VALUE
------------------------------
DBMS_PIPE
DBMS_OUTPUT
UTL_FILE

3 rows selected.

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

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
SQL_ID  d7bc3g2ccymkt, child number 0
-------------------------------------
select * from TABLE(cast( str2tbl(:in_list ) as str2tblType) ) t

Plan hash value: 2407808827

---------------------------------------------------------------------------------------------
| Id  | Operation                         | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                  |         |       |       |    34 (100)|          |
|   1 |  COLLECTION ITERATOR PICKLER FETCH| STR2TBL |  8168 | 16336 |    34   (3)| 00:00:01 |
---------------------------------------------------------------------------------------------


13 rows selected.

SQL> 

Hopefully, no surprises there.

According to the original demo, if I rinse and repeat and should get some feedback kicking right in there.

SQL> select * from TABLE(cast( str2tbl(:in_list ) as str2tblType) ) t;

COLUMN_VALUE
------------------------------
DBMS_PIPE
DBMS_OUTPUT
UTL_FILE

3 rows selected.

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

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------
SQL_ID  d7bc3g2ccymkt, child number 0
-------------------------------------
select * from TABLE(cast( str2tbl(:in_list ) as str2tblType) ) t

Plan hash value: 2407808827

---------------------------------------------------------------------------------------------
| Id  | Operation                         | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                  |         |       |       |    34 (100)|          |
|   1 |  COLLECTION ITERATOR PICKLER FETCH| STR2TBL |  8168 | 16336 |    34   (3)| 00:00:01 |
---------------------------------------------------------------------------------------------


13 rows selected.

SQL> 

Oh!

Nope.

And doesn’t matter how often I repeated, same difference.

So, this probably the right time to mention version, right?

SQL> select * from v$version;

BANNER
------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
PL/SQL Release 11.2.0.2.0 - Production
CORE    11.2.0.2.0      Production
TNS for Linux: Version 11.2.0.2.0 - Production
NLSRTL Version 11.2.0.2.0 - Production

At this point, something I’d read by the Optimzer Development Group rang a bell:

For similar reasons, execution statistics for queries containing bind variables can be problematic. In cardinality feedback, we limit the feedback to portions of the plan whose estimates are not affected by bind variables. For instance, if a table has a filter comparing a column to a bind value, the cardinality of that table will not be used. However, cardinality feedback can still be used for cardinalities elsewhere in the plan.

Sounds relevant, doesn’t it?

Let’s substitute the bind with a literal.

So, we’re going to run this:

select * from TABLE(cast( str2tbl('DBMS_PIPE,DBMS_OUTPUT,UTL_FILE' ) as str2tblType) ) t;

select * from table(dbms_xplan.display_cursor);

which gave me:

SQL> select * from TABLE(cast( str2tbl('DBMS_PIPE,DBMS_OUTPUT,UTL_FILE' ) as str2tblType) ) t;

COLUMN_VALUE
------------------------------
DBMS_PIPE
DBMS_OUTPUT
UTL_FILE

3 rows selected.

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

PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------------------------------
SQL_ID  8udfh089hyh6d, child number 0
-------------------------------------
select * from TABLE(cast( str2tbl('DBMS_PIPE,DBMS_OUTPUT,UTL_FILE' ) as
str2tblType) ) t

Plan hash value: 2407808827

---------------------------------------------------------------------------------------------
| Id  | Operation                         | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                  |         |       |       |    34 (100)|          |
|   1 |  COLLECTION ITERATOR PICKLER FETCH| STR2TBL |  8168 | 16336 |    34   (3)| 00:00:01 |
---------------------------------------------------------------------------------------------


14 rows selected.

And again

SQL> select * from TABLE(cast( str2tbl('DBMS_PIPE,DBMS_OUTPUT,UTL_FILE' ) as str2tblType) ) t;

COLUMN_VALUE
------------------------------
DBMS_PIPE
DBMS_OUTPUT
UTL_FILE

3 rows selected.

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

PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------------------------------
SQL_ID  8udfh089hyh6d, child number 1
-------------------------------------
select * from TABLE(cast( str2tbl('DBMS_PIPE,DBMS_OUTPUT,UTL_FILE' ) as
str2tblType) ) t

Plan hash value: 2407808827

---------------------------------------------------------------------------------------------
| Id  | Operation                         | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                  |         |       |       |    33 (100)|          |
|   1 |  COLLECTION ITERATOR PICKLER FETCH| STR2TBL |     6 |    12 |    33   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------

Note
-----
   - cardinality feedback used for this statement


18 rows selected.

SQL> 

So, cardinality feedback successfully demoed with cardinality estimates reduced from the blocksize-related default for a collection to something altogether more accurate.

Now we need to move on to a case where these improved cardinality estimates actually affect the plan.

Fortunately, Tom’s demo does just that with a new table:

create table data  as
select * from all_objects;

create index data_idx on data(object_name);

exec dbms_stats.gather_table_stats( user, 'DATA' );

And a new statement:

with T as
( select /*+ find_me */ 
         distinct * 
  from   TABLE(cast( str2tbl( 'DBMS_PIPE,DBMS_OUTPUT,UTL_FILE' ) as str2tblType) ) t 
  where rownum > 0 )
select * from data, t 
where data.object_name = t.column_value;

select * from table(dbms_xplan.display_cursor(format=>'-bytes'));

which gives the following (actual sql output snipped):

SQL> with T as
  2  ( select /*+ find_me */
  3           distinct *
  4    from   TABLE(cast( str2tbl( 'DBMS_PIPE,DBMS_OUTPUT,UTL_FILE' ) as str2tblType) ) t
  5    where rownum > 0 )
  6  select * from data, t
  7  where data.object_name = t.column_value;

.......

5 rows selected.

SQL> 
SQL> select * from table(dbms_xplan.display_cursor(format=>'-bytes'));

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
SQL_ID  c4m3t9jwvs3ht, child number 0
-------------------------------------
with T as ( select /*+ find_me */          distinct *   from
TABLE(cast( str2tbl( 'DBMS_PIPE,DBMS_OUTPUT,UTL_FILE' ) as str2tblType)
) t   where rownum > 0 ) select * from data, t where data.object_name =
t.column_value

Plan hash value: 892089582

------------------------------------------------------------------------------------------
| Id  | Operation                              | Name    | Rows  | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                       |         |       |   318 (100)|          |
|*  1 |  HASH JOIN                             |         | 15014 |   318   (5)| 00:00:02 |
|   2 |   VIEW                                 |         |  8168 |    36   (9)| 00:00:01 |
|   3 |    HASH UNIQUE                         |         |  8168 |    36   (9)| 00:00:01 |
|   4 |     COUNT                              |         |       |            |          |
|*  5 |      FILTER                            |         |       |            |          |
|   6 |       COLLECTION ITERATOR PICKLER FETCH| STR2TBL |  8168 |    34   (3)| 00:00:01 |
|   7 |   TABLE ACCESS FULL                    | DATA    | 58781 |   279   (3)| 00:00:02 |
------------------------------------------------------------------------------------------

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

   1 - access("DATA"."OBJECT_NAME"="T"."COLUMN_VALUE")
   5 - filter(ROWNUM>0)


28 rows selected.

SQL> 

As expected, no cardinality feedback yet, collection estimate back to default.

And I’m just going to monitor what’s in V$SQL:

SQL> select sql_id, child_number, plan_hash_value, executions, is_shareable, sql_plan_baseline 
  2  from v$sql 
  3  where sql_id = 'c4m3t9jwvs3ht';

SQL_ID        CHILD_NUMBER PLAN_HASH_VALUE EXECUTIONS I SQL_PLAN_BASELINE
------------- ------------ --------------- ---------- - ------------------------------
c4m3t9jwvs3ht            0       892089582          1 Y

1 row selected.

SQL> 

Now re-run:

SQL> with T as
  2  ( select /*+ find_me */ 
  3           distinct * 
  4    from   TABLE(cast( str2tbl( 'DBMS_PIPE,DBMS_OUTPUT,UTL_FILE' ) as str2tblType) ) t 
  5    where rownum > 0 )
  6  select * from data, t 
  7  where data.object_name = t.column_value;

...............

5 rows selected.

SQL> 
SQL> select * from table(dbms_xplan.display_cursor(format=>'-bytes'));

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
SQL_ID  c4m3t9jwvs3ht, child number 1
-------------------------------------
with T as ( select /*+ find_me */          distinct *   from
TABLE(cast( str2tbl( 'DBMS_PIPE,DBMS_OUTPUT,UTL_FILE' ) as str2tblType)
) t   where rownum > 0 ) select * from data, t where data.object_name =
t.column_value

Plan hash value: 3947981921

--------------------------------------------------------------------------------------------
| Id  | Operation                               | Name     | Rows  | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                        |          |       |    43 (100)|          |
|   1 |  NESTED LOOPS                           |          |       |            |          |
|   2 |   NESTED LOOPS                          |          |     6 |    43   (3)| 00:00:01 |
|   3 |    VIEW                                 |          |     3 |    34   (3)| 00:00:01 |
|   4 |     HASH UNIQUE                         |          |     3 |    34   (3)| 00:00:01 |
|   5 |      COUNT                              |          |       |            |          |
|*  6 |       FILTER                            |          |       |            |          |
|   7 |        COLLECTION ITERATOR PICKLER FETCH| STR2TBL  |     6 |    33   (0)| 00:00:01 |
|*  8 |    INDEX RANGE SCAN                     | DATA_IDX |     2 |     2   (0)| 00:00:01 |
|   9 |   TABLE ACCESS BY INDEX ROWID           | DATA     |     2 |     3   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------

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

   6 - filter(ROWNUM>0)
   8 - access("DATA"."OBJECT_NAME"="T"."COLUMN_VALUE")

Note
-----
   - cardinality feedback used for this statement


34 rows selected.

SQL> 

And in V$SQL:

SQL> select sql_id, child_number, plan_hash_value, executions, is_shareable, sql_plan_baseline 
  2  from v$sql 
  3  where sql_id = 'c4m3t9jwvs3ht';

SQL_ID        CHILD_NUMBER PLAN_HASH_VALUE EXECUTIONS I SQL_PLAN_BASELINE
------------- ------------ --------------- ---------- - ------------------------------
c4m3t9jwvs3ht            0       892089582          1 N
c4m3t9jwvs3ht            1      3947981921          1 Y

2 rows selected.

SQL> 

So, cardinality feedback has come to the rescue, adjusted our estimates and this time we’ve got a better plan for the numbers concerned with NESTED LOOPS rather than a HASH JOIN.

What happens if, as Kerry did, I create a baseline for this improved statement using his create_baseline.sql script?

SQL> @create_baseline
Enter value for sql_id: c4m3t9jwvs3ht
Enter value for plan_hash_value: 3947981921
Enter value for fixed (NO): 
Enter value for enabled (YES): 
Enter value for plan_name (ID_sqlid_planhashvalue): my_cf_baseline
old  16: l_sql_id := '&&sql_id';
new  16: l_sql_id := 'c4m3t9jwvs3ht';
old  17: l_plan_hash_value := to_number('&&plan_hash_value');
new  17: l_plan_hash_value := to_number('3947981921');
old  18: l_fixed := '&&fixed';
new  18: l_fixed := 'NO';
old  19: l_enabled := '&&enabled';
new  19: l_enabled := 'YES';
old  40:     decode('&&plan_name','X0X0X0X0','SQLID_'||'&&sql_id'||'_'||'&&plan_hash_value','&&plan_
new  40:     decode('my_cf_baseline','X0X0X0X0','SQLID_'||'c4m3t9jwvs3ht'||'_'||'3947981921','my_cf_
Baseline MY_CF_BASELINE created.
SQL> 

And now I re-run the statement:

SQL> with T as
  2  ( select /*+ find_me */ 
  3           distinct * 
  4    from   TABLE(cast( str2tbl( 'DBMS_PIPE,DBMS_OUTPUT,UTL_FILE' ) as str2tblType) ) t 
  5    where rownum > 0 )
  6  select * from data, t 
  7  where data.object_name = t.column_value;

....

5 rows selected.

SQL> 
SQL> select * from table(dbms_xplan.display_cursor(format=>'-bytes'));

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
SQL_ID  c4m3t9jwvs3ht, child number 2

An uncaught error happened in prepare_sql_statement : ORA-01403: no data found

NOTE: cannot fetch plan for SQL_ID: c4m3t9jwvs3ht, CHILD_NUMBER: 2
      Please verify value of SQL_ID and CHILD_NUMBER;
      It could also be that the plan is no longer in cursor cache (check v$sql_plan)


8 rows selected.

SQL> 

Oh dear. Can we just ignore that and come back to it at a later date? Let’s stick a pin in it, as they say.

I’ll just try again:

SQL> with T as
  2  ( select /*+ find_me */ 
  3           distinct * 
  4    from   TABLE(cast( str2tbl( 'DBMS_PIPE,DBMS_OUTPUT,UTL_FILE' ) as str2tblType) ) t 
  5    where rownum > 0 )
  6  select * from data, t 
  7  where data.object_name = t.column_value;

........

5 rows selected.

SQL> 
SQL> select * from table(dbms_xplan.display_cursor(format=>'-bytes'));

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
SQL_ID  c4m3t9jwvs3ht, child number 2
-------------------------------------
with T as ( select /*+ find_me */          distinct *   from
TABLE(cast( str2tbl( 'DBMS_PIPE,DBMS_OUTPUT,UTL_FILE' ) as str2tblType)
) t   where rownum > 0 ) select * from data, t where data.object_name =
t.column_value

Plan hash value: 3947981921

--------------------------------------------------------------------------------------------
| Id  | Operation                               | Name     | Rows  | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                        |          |       | 24591 (100)|          |
|   1 |  NESTED LOOPS                           |          |       |            |          |
|   2 |   NESTED LOOPS                          |          | 15014 | 24591   (1)| 00:02:03 |
|   3 |    VIEW                                 |          |  8168 |    36   (9)| 00:00:01 |
|   4 |     HASH UNIQUE                         |          |  8168 |    36   (9)| 00:00:01 |
|   5 |      COUNT                              |          |       |            |          |
|*  6 |       FILTER                            |          |       |            |          |
|   7 |        COLLECTION ITERATOR PICKLER FETCH| STR2TBL  |  8168 |    34   (3)| 00:00:01 |
|*  8 |    INDEX RANGE SCAN                     | DATA_IDX |     2 |     2   (0)| 00:00:01 |
|   9 |   TABLE ACCESS BY INDEX ROWID           | DATA     |     2 |     3   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------

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

   6 - filter(ROWNUM>0)
   8 - access("DATA"."OBJECT_NAME"="T"."COLUMN_VALUE")

Note
-----
   - SQL plan baseline SQL_PLAN_6w2j9bx7xvu6h5268a54a used for this statement


34 rows selected.

SQL> 

And what do we have in V$SQL?

SQL> select sql_id, child_number, plan_hash_value, executions, is_shareable, sql_plan_baseline 
  2  from v$sql 
  3  where sql_id = 'c4m3t9jwvs3ht';

SQL_ID        CHILD_NUMBER PLAN_HASH_VALUE EXECUTIONS I SQL_PLAN_BASELINE
------------- ------------ --------------- ---------- - ------------------------------
c4m3t9jwvs3ht            0       892089582          1 N
c4m3t9jwvs3ht            2      3947981921          1 Y SQL_PLAN_6w2j9bx7xvu6h5268a54a

2 rows selected.

SQL> 

So we can see that the baseline worked.

We can also see that the baseline, in this example, operated independently of the cardinality feedback so whilst we got our nice plan from the more accurate cardinality, we got the estimates from the default estimate of the collection.

Which is not exactly what I expected.

From Kerry’s post, he managed to get a statement using both a baseline and cardinality feedback as illustrated by his dbms_xplan output of:

Note
-----
   - SQL plan baseline SQLID_0CM4R08VJ075R_1255158658 used for this statement
   - cardinality feedback used for this statement

This is what I expected to get and then I was going to flush the shared pool in the hope of having a baseline and the original non-feedback estimates.

But no matter how many times I re-ran the statement I couldn’t get the cardinality feedback to kick back in.

So, unfortunately, I got to that end result without the all-important bit in the middle. Which is a bit weird. And warrants further investigation at some point.

I thought maybe the MONITOR hint might be the key difference to getting feedback working with baselines but not according to what I’ve tried so far. I couldn’t get the two features to work together.

But the bottom line is that I think this shows that the baseline did not use anything to maintain that those nice accurate estimates from cardinality feedback, only the end result plan.

And that’s backed up by the set of hints in the baseline which doesn’t include any OPT_ESTIMATE.

Suffice to say that this is really fledgling functionality and, as such, you expect subtle and no-so-subtle tweaks along the way as illustrated by the possible change of behaviour with bind variables when comparing my results above with the ones in Tom’s original article.

SQL Tuning Set to Baseline to Advisor

In my previous post “Advisor to Baseline – am I missing something?”, the answer was an inevitable “Yes”.

Just as a reminder, what I had tried to do was:

  1. Create a Tuning Set from some statements in AWR
  2. Create and execute a Tuning Task based on the Tuning Set
  3. Accept the simple profile recommendations from the Advisor
  4. Create a SQL Plan Baseline from the Tuning Set and with it all the new profiles

What happened was that I ended up with a bunch of standalone profiles from the Advisor – see DBA_SQL_PROFILES and/or SQLOBJ$ of object type 1, looking at hints in COMP_DATA of SQLOBJ$DATA or packing to staging table and inspecting there.

And I ended up with a bunch of SQL Plan Baselines with hints from the old plans for statements that I had run through the Advisor because they were rubbish (DBA_SQL_PLAN_BASELINES and SQLOBJ$ of object type 2, looking at hints in COMP_DATA of SQLOBJ$DATA or packing to staging table and inspecting there.)

Quick question – what happens if you have some SQL Plan Baselines with some “bad” hints whilst there also exist some standalone sql profiles with some “good” hints?

From my observations, the Baselines will win. The bad plans will be used. However, because when baselines are being used, on hard parse the optimizer will generate a plan anyway and record any differences in plans generated. So when generating the plan anyway, the standalone sql profiles kick in and so the baseline will contain unaccepted “better” plans ready to be evolved for subsequent executions (unaccepted depending on whether you’re runing with automatic evolution or not).

And back to what I should have done initially and that’s:

  1. Create a Tuning Set from some statements in AWR
  2. Create a SQL Plan Baseline from the Tuning Set
  3. Create and execute a Tuning Task based on the Tuning Set
  4. Accept the simpler, non-parallel profile recommendations from the Advisor

This way the profiles get created not as standalone profiles but part of SQL Plan Baselines – SQLOB$ object type 2 – and accepted and enabled in DBA_SQL_PLAN_BASELINES (FLAGS=11 in SQLOBJ$).

I’ll back this all up with some proof and isolated examples one day.
At the minute, everything’s just too manic, manic trying to get this stuff to work, manic fighting management FUD about just about any new feature since Oracle 9…

Advisor to Baseline – am I missing something?

I’ve mentioned before that I’m in the middle of an upgrade to 11.2.0.2.

I’ve been looking at the SQL Tuning Advisor, looking at Baselines, running into a performance crippling bug with baseline capture, running away from baselines, and now coming back to baselines now that the bug has been approved by the client internally.

Here’s what I want to do:

  • Create a Guaranteed Restore Point
  • Run “The Batch”
  • Run a Tuning Advisor on the top N statements
  • Accept some of the Advisor recommendations
  • Export these recommendations
  • Flashback to restore point
  • Import
  • Rerun same “The Batch”

(It may be that RAT would be a good solution for this cycle – we’re not licensing it I believe)

So, running the batch – done.

Some performance degradations – check.

Given 30 minutes to look at some pretty big statements statement, the good old SQL Tuning Advisor can come up with far more than I can (there’s still a place for manual tuning, of course).

So, if I take from AWR the top N statements by some metric from “The Batch” and give the SQL Tuning Advisor a few hours to chunter away, it should be a really positive contribution in a short space of time.

First up, this is a nice little function – DBMS_SQLTUNE.SELECT_WORKLOAD_REPOSITORY.

So, I know the AWR snaps that cover “The Batch” so to get the top 50 statements for example by elapsed time from AWR, I do this:

SELECT *
FROM   TABLE(dbms_sqltune.select_workload_repository
             (begin_snap        => 4005,
              end_snap          => 4011,
              basic_filter      => 'parsing_schema_name in (''ABC'',''XYZ'')',
              ranking_measure1  => 'elapsed_time',
              result_limit      => 50,
              attribute_list    => 'ALL'
              )) p;

I’ve not included the output because it’s a bit wide. Suffice to say, I’ve got my 50 statements.

I can load these up into a SQL tuning set like this:

DECLARE
 baseline_cursor DBMS_SQLTUNE.SQLSET_CURSOR;
BEGIN
  DBMS_SQLTUNE.CREATE_SQLSET(
    sqlset_name => 'MY_11G_TUNING_SET', 
    description  => 'My 11g tuning set');
 OPEN baseline_cursor FOR
      SELECT VALUE(p)
      FROM   TABLE(dbms_sqltune.select_workload_repository
             (begin_snap        => 4005,
              end_snap          => 4011,
              basic_filter      => 'parsing_schema_name in (''ABC'',''XYZ'')',
              ranking_measure1  => 'elapsed_time',
              result_limit      => 50,
              attribute_list    => 'ALL'
              )) p; 
    DBMS_SQLTUNE.LOAD_SQLSET(
             sqlset_name     => 'MY_11G_TUNING_SET',
             populate_cursor => baseline_cursor);
END;
/

And then I can set the advisor on this bad boy thus:

DECLARE
 l_task_name   varchar2(200) := 'MY_11g_TUNING_TASK';
 l_sqlset_name varchar2(200) := 'MY_11G_TUNING_SET';
BEGIN
 l_task_name :=
 dbms_sqltune.create_tuning_task
 (sqlset_name  => l_sqlset_name,
  task_name    => l_task_name,
  time_limit   => 15300);
 dbms_sqltune.set_tuning_task_parameter
 (task_name    => l_task_name,
  parameter    => 'LOCAL_TIME_LIMIT',
  value        => DBMS_SQLTUNE.TIME_LIMIT_DEFAULT);
 dbms_sqltune.execute_tuning_task
 (task_name    => l_task_name);
END;
/

Note that I’ve given it a few hours to go off and do its stuff but I’ve restricted it to 30 minutes per statement using the TIME_LIMIT_DEFAULT argument.

Some time later, it’s done and I can get back the results like so:

SELECT dbms_sqltune.report_tuning_task('MY_11g_TUNING_TASK'') 
FROM DUAL; 

And I get a great big stonking report back. Again, no point copying it in here.

Suffice to say that it mentions a bunch of indexes, doing lots more work in parallel, but for now I don’t want to rush into accepting profiles running all 50 statements simultaneously with a DOP of 48 :) – I’m just interested in the simpler SQL profiles it is recommending.

Next, I accept the sql profiles.

I can see them in dba_sql_profiles.

And I know I can move these around using DBMS_SQLTUNE.CREATE_STGTAB_SQLPROF, PACK_STGTAB_SQLPROF and UNPACK_STGTAB_SQLPROF.

That would do me fine. I can do this. Initial aims up top met.

But, I thought I’d be able to run the advisor, accept the profiles and somehow move all this stuff into a baseline, then move the baseline.

But it’s not working as planned.

I’ve already got the tuning set and I’ve accepted the profiles recommended.

I had thought that if I used DBMS_SPM.LOAD_PLANS_FROM_SQLSET that it would use the information from the profiles.

But that doesn’t seem possible.

What’s in the baseline is the hints to get the original plans from the SQL statements concerned – i.e. the hints to get the plans which the Advisor subsequently poo-pooed as trumpable with a profile.

And I think it’s because I need to run the SQL with the profiles so that the appropriate plans exist against the relevant SQL, then create a tuning set of those sql statements and their plans and then load that into a baseline which can use the specific hints for a specific executed plan.

Of course, I might have got it the wrong way round. I know a baseline re-optimises statements at hard parse time and the SQL Tuning Advisor can run on baselines.

But it definitely seems at the moment that the initial baseline population needs an executed plan.

More later perhaps if I decide to knock up a specific isolated example to demonstrate or work it out … but not today though. It’s Friday after all.

Buggy overhead of SQL Plan Baseline Capture

There’s at least one bug related to the performance overhead of SQL Baseline Capture and ASH is less than clear with recursive SQL

First up – apologies, I’ve not got a reproducible test case because I flushed the shared pool between tests and the whole performance degradation scenario disappeared. I should have known when one of the Metalink notes talked about the problem disappearing when bouncing the instance that I shouldn’t have touched the shared pool. Now I can’t reproduce. I’m going to keep trying, but for now, let me tell you what I’ve got (I am trying to be more precise in my blogging but yet again it’s something woolly or nothing).

With that out the way, we’re in the initial stages of an upgrade from 9.2.0.8 on 32-bit Solaris to 11.2.0.2 on 64-bit Linux, a one-step all-or-nothing change-everything at once upgrade.

Plan was to run with optimizer_features_enable set to 9.2.0, various other parameters set to current production settings and to capture 9i plans into a baseline.

Initial runs of “The Batch” started, all processes reported as slow. The initial major contributor turns out to be recursive SQL related to SQL Plan Baseline Capture (see bug#11600319, also bug #11719151 and doc id 1295054.1 – thanks to Timur Akhmadeev for the pointers)

I haven’t yet raised this with Oracle Support because a) I can’t face the wait for a response and b) local red tape means that patches need to be approved by the DB Engineering team and approval for non-production environments is difficult (I’m not going there, not now).

Bug # 11719151 – “RECURSIVE MERGE WHEN optimizer_capture_sql_plan_baseline=true DOING FTS” – is certainly relevant.
The MERGE statement into SQLOBJ$AUXDATA does use a FULL TABLE SCAN. But if I were to show you the AWR reports then you’d see the MERGE statement into SQLOBJ$DATA was the bigger problem and the MERGE statement into SQLOBJ$ also not insignificant.

Pick a metric, any metric:
3 out of the top 10 by Elapsed Time, 2 out of the top 5, 1 of the top 1.

        Elapsed                  Elapsed Time
        Time (s)    Executions  per Exec (s)  %Total   %CPU    %IO    SQL Id
---------------- -------------- ------------- ------ ------ ------ -------------
         6,481.5        242,111          0.03   43.2   22.6   56.1 1vxm21mhmgy07
MERGE INTO sqlobj$data USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET comp_data = :2 WHERE

         2,403.4        242,108          0.01   16.0   95.4    3.9 44z7snw61qx9x
MERGE INTO sqlobj$auxdata USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET description = :2,

           898.7        242,111          0.00    6.0   98.6     .1 7xm5j53mxbtpn
MERGE INTO sqlobj$ USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET name = :2,

By CPU Time:

    CPU                   CPU per           Elapsed
  Time (s)  Executions    Exec (s) %Total   Time (s)   %CPU    %IO    SQL Id
---------- ------------ ---------- ------ ---------- ------ ------ -------------
   2,292.8      242,108       0.01   39.9    2,403.4   95.4    3.9 44z7snw61qx9x
MERGE INTO sqlobj$auxdata USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET description = :2,


   1,464.0      242,111       0.01   25.5    6,481.5   22.6   56.1 1vxm21mhmgy07
MERGE INTO sqlobj$data USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET comp_data = :2 WHERE

     885.7      242,111       0.00   15.4      898.7   98.6     .1 7xm5j53mxbtpn
MERGE INTO sqlobj$ USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET name = :2,

By Gets:

     Buffer                 Gets              Elapsed
      Gets   Executions   per Exec   %Total   Time (s)   %CPU    %IO    SQL Id
----------- ----------- ------------ ------ ---------- ------ ------ -----------
 49,599,141     242,108        204.9   46.9    2,403.4   95.4    3.9 44z7snw61qx
MERGE INTO sqlobj$auxdata USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET description = :2,

 29,107,449     242,111        120.2   27.5    6,481.5   22.6   56.1 1vxm21mhmgy
MERGE INTO sqlobj$data USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET comp_data = :2 WHERE

 16,671,818     242,111         68.9   15.7      898.7   98.6     .1 7xm5j53mxbt
MERGE INTO sqlobj$ USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET name = :2,

By executions:

 Executions   Rows Processed  Rows per Exec   Time (s)   %CPU    %IO    SQL Id
------------ --------------- -------------- ---------- ------ ------ -----------
     242,111         242,111            1.0    6,481.5   22.6   56.1 1vxm21mhmgy
MERGE INTO sqlobj$data USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET comp_data = :2 WHERE

     242,111         242,111            1.0      898.7   98.6     .1 7xm5j53mxbt
MERGE INTO sqlobj$ USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET name = :2,


     242,111         242,074            1.0       34.6   95.7     .2 9zr2sbbp1d4
SELECT /*+ INDEX(sqlobj$ (name obj_type)) */ signature, category 
FROM sqlobj$ WHERE name = :1 AND obj_type = :2

     242,108         242,108            1.0    2,403.4   95.4    3.9 44z7snw61qx
MERGE INTO sqlobj$auxdata USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET description = :2,

So, you get the message.

Furthermore, at the top of every Segment Statistic by X Metric, it’s either one of the LOBs or the LOB Index related to these three tables.

By the way, what’s in these SQLOBJ$ tables – no surprises it’s the baseline data.
See also:
Kerry Osborne – Do SQL Baselines Use Hints/
Christian Antognini – SQL Profiles in the Data Dictionary
Christian Antognini – Troubleshooting Oracle Performance

If I move over to the ASH data and give an example of what that was showing, then we can go and look at those SQLOBJ$ tables for the SQL concerned.

The ASH data – probably my most favorite feature of the last few years – I’m only displaying a little bit of in terms of height and width. But it illustrates the second point I wanted to highlight – that recursive SQL is not properly reported. Whilst the SQL_ID column differs from the TOP_LEVEL_SQL_ID (which I’ve omitted to keep it slim), this is still the SQL Id of a nested lookup, not the SQL Id of the recursive MERGE which you might have expected – I can see pros and cons of both I suppose.

  1  select to_char(sample_time,'HH24:MI:SS') sample_time, session_id, sql_id
  2  ,      sql_plan_operation, event
  3  from   v$active_session_history
  4  where  session_id      = 1388
  5  and    session_serial# = 147
  6  and    sample_id between 14596749 and 14596800
  7* order by sample_id
SQL> /

SAMPLE_T SESSION_ID SQL_ID        SQL_PLAN_OPERATION             EVENT
-------- ---------- ------------- ------------------------------ -----------------------------------
10:57:04       1388 d99anrdgbb4jf SELECT STATEMENT
10:57:05       1388                                              log file sync
10:57:06       1388 d99anrdgbb4jf
10:57:07       1388 d99anrdgbb4jf MERGE                          direct path write
10:57:08       1388 d99anrdgbb4jf MERGE                          flashback log file sync
10:57:09       1388 d99anrdgbb4jf                                direct path read
10:57:10       1388 d99anrdgbb4jf MERGE                          buffer busy waits
10:57:11       1388 d99anrdgbb4jf SELECT STATEMENT               latch: shared pool
10:57:12       1388 d99anrdgbb4jf MERGE                          direct path read
10:57:13       1388 d99anrdgbb4jf TABLE ACCESS
10:57:14       1388 d99anrdgbb4jf INDEX
10:57:15       1388 d99anrdgbb4jf MERGE                          direct path write
10:57:16       1388 d99anrdgbb4jf TABLE ACCESS
10:57:17       1388 d99anrdgbb4jf TABLE ACCESS
10:57:18       1388 d99anrdgbb4jf                                direct path read
10:57:19       1388 d99anrdgbb4jf TABLE ACCESS
10:57:20       1388 d99anrdgbb4jf MERGE
10:57:21       1388                                              log file sync
10:57:22       1388                                              log file sync
10:57:23       1388 d99anrdgbb4jf MERGE                          direct path write
10:57:24       1388 d99anrdgbb4jf MERGE                          direct path write
10:57:25       1388 d99anrdgbb4jf TABLE ACCESS
10:57:26       1388 d99anrdgbb4jf                                direct path read
10:57:27       1388 d99anrdgbb4jf                                direct path read
10:57:28       1388 d99anrdgbb4jf MERGE                          db file sequential read
10:57:29       1388 d99anrdgbb4jf MERGE
10:57:30       1388                                              log file sync
10:57:31       1388 d99anrdgbb4jf MERGE                          db file sequential read
10:57:32       1388 d99anrdgbb4jf MERGE
10:57:33       1388 d99anrdgbb4jf INDEX
10:57:34       1388 d99anrdgbb4jf MERGE                          buffer busy waits
10:57:35       1388 d99anrdgbb4jf MERGE                          buffer busy waits
10:57:36       1388 d99anrdgbb4jf MERGE                          flashback log file sync
10:57:37       1388 d99anrdgbb4jf MERGE                          direct path write
10:57:38       1388 d99anrdgbb4jf MERGE                          db file sequential read
10:57:39       1388 d99anrdgbb4jf MERGE                          db file sequential read
10:57:40       1388 d99anrdgbb4jf MERGE                          buffer busy waits
10:57:41       1388 d99anrdgbb4jf MERGE                          enq: TX - index contention
10:57:42       1388 d99anrdgbb4jf MERGE                          buffer busy waits
10:57:43       1388 d99anrdgbb4jf MERGE                          db file sequential read
10:57:44       1388 d99anrdgbb4jf MERGE                          db file sequential read
10:57:45       1388                                              log file sync
10:57:46       1388 d99anrdgbb4jf TABLE ACCESS
10:57:47       1388 d99anrdgbb4jf MERGE                          flashback log file sync
10:57:48       1388 d99anrdgbb4jf MERGE JOIN
10:57:49       1388 d99anrdgbb4jf MERGE                          db file sequential read
10:57:50       1388 d99anrdgbb4jf MERGE                          db file sequential read
10:57:51       1388 d99anrdgbb4jf TABLE ACCESS
10:57:52       1388 d99anrdgbb4jf MERGE                          direct path write
10:57:53       1388 d99anrdgbb4jf TABLE ACCESS
10:57:54       1388 d99anrdgbb4jf MERGE                          db file sequential read
10:57:55       1388 d99anrdgbb4jf SELECT STATEMENT

52 rows selected.

SQL> 

By the way, I was also a little surprised to see the direct path read/write operations in the ASH data but these SQLOBJ$ tables that we’re constantly MERGING into recursively have LOBS and further investigation revealed these events to be associated with those LOB segments.

As you can see from above, lots of MERGE operations which have nothing directly to do with SQL_ID d99anrdgbb4jf which looks like the statement below. By the time I’ve got to some of this data for the purposes of this, it’s gone from V$SQL so I’m fetched it from AWR.

SQL> select * from table(dbms_xplan.display_awr('d99anrdgbb4jf'));

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------
SQL_ID d99anrdgbb4jf
--------------------
SELECT XXXX_XXX FROM XXXX_XXXX WHERE XXXX_XXXX = 'MSD' AND XXXX_XXXX =:B1

Plan hash value: 878181930

-------------------------------------------------------------------------------
| Id  | Operation                   | Name            | Rows  | Bytes | Cost  |
-------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |                 |       |       |     2 |
|   1 |  TABLE ACCESS BY INDEX ROWID| XXXX_XXXX       |     1 |    18 |     2 |
|   2 |   INDEX RANGE SCAN          | XXXX_XXXX_IDX_1 |     1 |       |     2 |
-------------------------------------------------------------------------------

Note
-----
   - cpu costing is off (consider enabling it)

19 rows selected.

SQL> 

Baselines are stored according to signature. SQL statements have hash_values, sql ids and also exact/force matching signatures. By the way, the latter can be translated from the text of the sql statement using DBMS_SQLTUNE.SQLTEXT_TO_SIGNATURE using the FORCE_MATCH parameter for either the exact or force matching signature.

In AWR, we’ve only got the FORCE_MATCHING_SIGNATURE of this sql statement sql_id ‘d99anrdgbb4jf’ but take it was the same as the EXACT_MATCHING_SIGNATURE.

SQL> select distinct sql_id, force_matching_signature, to_char(force_matching_signature)
  2  from dba_hist_sqlstat 
  3  where sql_id = 'd99anrdgbb4jf'; 

SQL_ID        FORCE_MATCHING_SIGNATURE TO_CHAR(FORCE_MATCHING_SIGNATURE)
------------- ------------------------ ----------------------------------------
d99anrdgbb4jf               3.9882E+17 398819076860959259

SQL> 

I used this signature to see what was happening with the baseline data.

There’s not much point in me pasting the outputs of those tables. I could see that the SYS.SQLOBJ$.LAST_EXECUTED, SYS.SQLOBJ$AUXDATA.CREATED (!?!) and SYS.SQLOBJ$AUXDATA.LAST_MODIFIED were being updated although not the additional metrics like BUFFER_GETS, EXECUTIONS, etc in SYS.SQLOBJ$DATA.

But then I flushed the cache and like that … the performance degradation was gone and not reproducible… for now.

That’s all there is really.

Oh, by the way, I did trace one session while it was reproducing. Below are some of the relevant bits.
I was using a simple slow-by-slow lookup because I was then going to use concurrent sessions which initially were causing me problems with SMO rowcache lock contention – quite possibly related again to the baselines, but I never got that far into the investigation before we flashed it all back and turned off capture.
Also, looping lookups were relevant to one of the bug notes above and are very much representative of some of the legacy Pro*C codebase.

...
BEGIN
 DBMS_OUTPUT.DISABLE;
 FOR r IN (SELECT * FROM t1)
 LOOP
     FOR x IN (SELECT id FROM t1 WHERE code = r.code)
     LOOP
       DBMS_OUTPUT.PUT_LINE(x.id);
     END LOOP;
 END LOOP;
END;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.01          0          0          0           0
Execute      1      1.07       1.10          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      1.08       1.11          0          0          0           0

Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: 4106  

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net break/reset to client                   2        0.00          0.00
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.00          0.00
  log file sync                                   1        0.06          0.06
********************************************************************************

....

SQL ID: 0jjc60pmrntdv
Plan Hash: 3617692013
SELECT * 
FROM
 T1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          1           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       66      0.01       0.01          0        279          0        6600
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       68      0.01       0.02          0        279          1        6600

Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: 4106     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
   6600  TABLE ACCESS FULL T1 (cr=279 pr=0 pw=0 time=13232 us cost=498 size=22700000 card=100000)

********************************************************************************

SQL ID: 33kddu0j5ykq6
Plan Hash: 2946553998
SELECT ID 
FROM
 T1 WHERE CODE = :B1 


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute   6507     18.15      37.59       6504      54980       6523           0
Fetch     6506      0.28       0.28          0      26024          0        6506
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    13014     18.43      37.88       6504      81004       6523        6506

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: 4106     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS BY INDEX ROWID T1 (cr=4 pr=0 pw=0 time=233 us cost=2 size=26 card=1)
      1   INDEX UNIQUE SCAN I1 (cr=3 pr=0 pw=0 time=211 us cost=1 size=0 card=1)(object id 97386)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  latch: cache buffers chains                    22        0.00          0.00
  library cache: mutex X                          4        0.00          0.00
  latch: shared pool                              8        0.00          0.00
********************************************************************************

SQL ID: 9zr2sbbp1d4fs
Plan Hash: 2462756431
SELECT /*+ INDEX(sqlobj$ (name obj_type)) */ signature, category              
FROM
 sqlobj$                                                                  
  WHERE name = :1                                                             
          AND obj_type = :2


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse      435      0.01       0.01          0          0          0           0
Execute    435      0.06       0.06          0          0          0           0
Fetch      435      0.01       0.02          1        871          0         434
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1305      0.09       0.10          1        871          0         434

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 2)

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  INDEX RANGE SCAN I_SQLOBJ$NAME_TYPE (cr=3 pr=1 pw=0 time=10195 us cost=1 size=54 card=1)(object id 199)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        1        0.00          0.00
  db file sequential read                         1        0.00          0.00
********************************************************************************

SQL ID: 47y3mqvyhpkvs
Plan Hash: 1888265482
SELECT obj_type, plan_id, name, flags, last_executed                          
FROM
 sqlobj$                                                                  
  WHERE signature = :1                                                        
          AND category = :2


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        1      0.00       0.00          0          2          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0          2          0           0

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 2)

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  INDEX RANGE SCAN SQLOBJ$_PKEY (cr=2 pr=0 pw=0 time=51 us cost=1 size=74 card=1)(object id 198)

********************************************************************************

....

SQL ID: 7xm5j53mxbtpn
Plan Hash: 2110601055
MERGE INTO sqlobj$                                                            
  USING dual ON (:1 IS NULL)                                                  
    WHEN MATCHED THEN                                                         
        UPDATE SET name = :2,                                                 
                     flags = :3,                                              
                       last_executed = :4                                     
              WHERE signature = :5                                            
                      AND category = :6                                       
                        AND obj_type = :7                                     
                          AND plan_id = :8                                    
                    WHEN NOT MATCHED THEN                                     
                        INSERT (signature, category, obj_type, plan_id, name, 
                                  flags, last_executed)                       
                            VALUES (:9, :10, :11, :12, :13, :14, :15)


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse     6505      0.35       0.37          0          0          0           0
Execute   6505     29.78      31.78         52     430259      13126        6505
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    13010     30.13      32.16         52     430259      13126        6505

Misses in library cache during parse: 1
Misses in library cache during execute: 2
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 2)

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  MERGE  SQLOBJ$ (cr=2 pr=0 pw=0 time=748 us)
      1   VIEW  (cr=2 pr=0 pw=0 time=202 us)
      1    MERGE JOIN OUTER (cr=2 pr=0 pw=0 time=198 us cost=7 size=162488 card=2138)
      1     TABLE ACCESS FULL DUAL (cr=2 pr=0 pw=0 time=169 us cost=2 size=2 card=1)
      0     VIEW  (cr=0 pr=0 pw=0 time=7 us cost=5 size=158212 card=2138)
      0      FILTER  (cr=0 pr=0 pw=0 time=3 us)
      0       INDEX FAST FULL SCAN SQLOBJ$_PKEY (cr=0 pr=0 pw=0 time=0 us cost=9 size=158212 card=2138)(object id 198)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  latch: cache buffers chains                    23        0.00          0.00
  db file sequential read                        52        0.89          1.03
  buffer busy waits                              65        0.00          0.00
  log file switch completion                      4        0.24          0.44
  library cache: mutex X                          2        0.00          0.00
********************************************************************************

SQL ID: 44z7snw61qx9x
Plan Hash: 1133963577
MERGE INTO sqlobj$auxdata                                                     
  USING dual ON (:1 IS NULL)                                                  
    WHEN MATCHED THEN                                                         
        UPDATE SET description = :2,                                          
                     creator = nvl(:3, creator),                              
                       origin = :4,                                           
                         version = :5,                                        
                           created = :6,                                      
                             last_modified = :7,                              
                               last_verified = nvl(:8, last_verified),        
                                 parse_cpu_time = null,                       
                                   optimizer_cost = nvl(:9, optimizer_cost),  
                                     module = nvl(:10, module),               
                                       action = nvl(:11, action),             
                                         priority = nvl(:12, priority),       
                                           optimizer_env = nvl(:13, 
  optimizer_env),                                      bind_data = nvl(:14, 
  bind_data),                                              
  parsing_schema_name = nvl(:15, parsing_schema_name),                        
    executions = nvl(:16, executions),                                        
      elapsed_time = nvl(:17, elapsed_time),                                  
        cpu_time = nvl(:18, cpu_time),                                        
          buffer_gets = nvl(:19, buffer_gets),                                
            disk_reads = nvl(:20, disk_reads),                                
              direct_writes = nvl(:21, direct_writes),                        
                rows_processed = nvl(:22, rows_processed),                    
                  fetches = nvl(:23, fetches),                                
                    end_of_fetch_count = nvl(:24, end_of_fetch_count),        
                      task_id = nvl(:25, task_id),                            
                        task_exec_name = nvl(:26, task_exec_name),            
                          task_obj_id = nvl(:27, task_obj_id),                
                            task_fnd_id = nvl(:28, task_fnd_id),              
                              task_rec_id = nvl(:29, task_rec_id),            
                                flags = 0,                                    
                                  spare1 = null,                              
                                    spare2 = null                             
                           WHERE signature = :30                              
                                   AND category = :31                         
                                     AND obj_type = :32                       
                                       AND plan_id = :33                      
                                 WHEN NOT MATCHED THEN                        
                                     INSERT (signature, category, obj_type, 
  plan_id,                                       description, creator, origin,
   version,                                        created, last_modified, 
  last_verified, parse_cpu_time,                        optimizer_cost, 
  module, action, priority,                                     optimizer_env,
   bind_data, parsing_schema_name, executions,                    
  elapsed_time, cpu_time, buffer_gets, disk_reads,                            
    direct_writes, rows_processed, fetches,end_of_fetch_count,                
      task_id, task_exec_name, task_obj_id, task_fnd_id,                      
        task_rec_id, flags, spare1, spare2)                                   
  VALUES (:34, :35, :36, :37,                                                 
            :38, :39, :40, :41,                                               
              :42, :43, null, null,                                           
                :44, :45, :46, :47,                                           
                  :48, :49, :50, :51,                                         
                    :52, :53, :54, :55,                                       
                      :56, :57, :58, :59,                                     
                        :60, :61, :62, :63,                                   
                          :64, 0, null, null)


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse     6504      0.47       0.49          0          0          0           0
Execute   6504     66.69      70.05        429    1631914      14302        6504
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    13008     67.16      70.55        429    1631914      14302        6504

Misses in library cache during parse: 1
Misses in library cache during execute: 2
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 2)

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  MERGE  SQLOBJ$AUXDATA (cr=3 pr=0 pw=0 time=810 us)
      1   VIEW  (cr=2 pr=0 pw=0 time=134 us)
      1    MERGE JOIN OUTER (cr=2 pr=0 pw=0 time=122 us cost=18 size=784646 card=2138)
      1     TABLE ACCESS FULL DUAL (cr=2 pr=0 pw=0 time=91 us cost=2 size=2 card=1)
      0     VIEW  (cr=0 pr=0 pw=0 time=15 us cost=16 size=780370 card=2138)
      0      FILTER  (cr=0 pr=0 pw=0 time=2 us)
      0       TABLE ACCESS FULL SQLOBJ$AUXDATA (cr=0 pr=0 pw=0 time=0 us cost=20 size=780370 card=2138)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        2        0.00          0.00
  db file sequential read                       429        0.29          2.56
  buffer busy waits                              58        0.00          0.00
  latch: cache buffers chains                    25        0.00          0.00
  log file switch completion                      1        0.05          0.05
  latch: object queue header operation            1        0.00          0.00
  library cache: mutex X                          2        0.00          0.00
********************************************************************************

SQL ID: 1vxm21mhmgy07
Plan Hash: 984916430
MERGE INTO sqlobj$data                                                        
  USING dual ON (:1 IS NULL)                                                  
    WHEN MATCHED THEN                                                         
        UPDATE SET comp_data = :2                                             
          WHERE signature = :3                                                
                  AND category = :4                                           
                    AND obj_type = :5                                         
                      AND plan_id = :6                                        
                WHEN NOT MATCHED THEN                                         
                    INSERT (signature, category, obj_type, plan_id, comp_data,
                              spare1, spare2)                                 
                        VALUES (:7, :8, :9, :10, :11, null, null)


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse     6053      0.35       0.36          0          0          0           0
Execute   6053     38.42     192.12      14420     500403     235414        6053
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    12106     38.78     192.48      14420     500403     235414        6053

Misses in library cache during parse: 1
Misses in library cache during execute: 2
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 2)

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  MERGE  SQLOBJ$DATA (cr=43 pr=2 pw=1 time=8478 us)
      1   VIEW  (cr=2 pr=0 pw=0 time=140 us)
      1    MERGE JOIN OUTER (cr=2 pr=0 pw=0 time=131 us cost=9 size=303596 card=2138)
      1     TABLE ACCESS FULL DUAL (cr=2 pr=0 pw=0 time=109 us cost=2 size=2 card=1)
      0     VIEW  (cr=0 pr=0 pw=0 time=5 us cost=7 size=299320 card=2138)
      0      FILTER  (cr=0 pr=0 pw=0 time=3 us)
      0       INDEX FAST FULL SCAN SQLOBJ$DATA_PKEY (cr=0 pr=0 pw=0 time=0 us cost=6 size=299320 card=2138)(object id 205)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                      8367        1.04         43.76
  flashback log file sync                      7828        0.26         25.34
  direct path write                            6052        0.47         36.62
  direct path read                             6045        0.42         16.34
  enq: HW - contention                         1138        0.89         24.42
  Disk file operations I/O                       12        0.00          0.00
  latch: cache buffers chains                   860        0.00          0.03
  buffer busy waits                             764        1.00          6.00
  read by other session                          24        0.03          0.34
  latch: enqueue hash chains                      2        0.00          0.00
  enq: TX - index contention                     57        0.05          0.21
  buffer deadlock                                11        0.00          0.00
  latch free                                      2        0.00          0.00
  library cache: mutex X                          8        0.00          0.00
  latch: cache buffers lru chain                  4        0.00          0.00
  log file switch (checkpoint incomplete)         3        0.14          0.28
  enq: TX - allocate ITL entry                    1        0.00          0.00
  latch: undo global data                         1        0.00          0.00

.....


SQL ID: 1zatw56z32vcg
Plan Hash: 1469453527
SELECT obj_type, plan_id, description, creator, origin,                       
         created, last_modified                                               
    
FROM
 sqlobj$auxdata                                                           
  WHERE signature = :1                                                        
          AND category = :2


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse     6505      0.10       0.12          0          0          0           0
Execute   6505      0.91       0.96          0          0          0           0
Fetch    13010      0.30       0.29          0      26020          0        6505
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    26020      1.32       1.38          0      26020          0        6505

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 2)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS BY INDEX ROWID SQLOBJ$AUXDATA (cr=4 pr=0 pw=0 time=87 us cost=2 size=315 card=1)
      1   INDEX RANGE SCAN I_SQLOBJ$AUXDATA_PKEY (cr=3 pr=0 pw=0 time=51 us cost=1 size=0 card=1)(object id 209)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  latch: cache buffers chains                     5        0.00          0.00
********************************************************************************

SQL ID: bt51szvfrcdpn
Plan Hash: 1876815449
SELECT obj_type, plan_id, comp_data                                           
FROM
 sqlobj$data                                                              
  WHERE signature = :1                                                        
          AND category = :2


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse     6504      0.13       0.12          0          0          0           0
Execute   6504      0.82       0.82          0          0          0           0
Fetch    13008      0.28       0.32          0      19516          0        6504
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    26016      1.24       1.27          0      19516          0        6504

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 2)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  INDEX RANGE SCAN SQLOBJ$DATA_PKEY (cr=3 pr=0 pw=0 time=89 us cost=1 size=140 card=1)(object id 205)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  latch: cache buffers chains                    17        0.00          0.00
********************************************************************************

SQL ID: 1vxm21mhmgy07
Plan Hash: 2462756431
MERGE INTO sqlobj$data                                                        
  USING dual ON (:1 IS NULL)                                                  
    WHEN MATCHED THEN                                                         
        UPDATE SET comp_data = :2                                             
          WHERE signature = :3                                                
                  AND category = :4                                           
                    AND obj_type = :5                                         
                      AND plan_id = :6                                        
                WHEN NOT MATCHED THEN                                         
                    INSERT (signature, category, obj_type, plan_id, comp_data,
                              spare1, spare2)                                 
                        VALUES (:7, :8, :9, :10, :11, null, null)


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse     6523      0.18       0.19          0          0          0           0
Execute   6523      3.15       8.90       1059      34474      17486         452
Fetch     6071      0.22       0.20          0      12142          0        6071
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    19117      3.55       9.30       1059      46616      17486        6523

Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 2)

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  MERGE  SQLOBJ$DATA (cr=79 pr=3 pw=1 time=16359 us)
   2440   VIEW  (cr=43 pr=0 pw=0 time=15141 us)
   2440    MERGE JOIN OUTER (cr=43 pr=0 pw=0 time=13065 us cost=9 size=303596 card=2138)
      1     TABLE ACCESS FULL DUAL (cr=2 pr=0 pw=0 time=59 us cost=2 size=2 card=1)
   2440     VIEW  (cr=41 pr=0 pw=0 time=7394 us cost=7 size=299320 card=2138)
   2440      FILTER  (cr=41 pr=0 pw=0 time=6050 us)
   2440       INDEX FAST FULL SCAN SQLOBJ$DATA_PKEY (cr=41 pr=0 pw=0 time=3971 us cost=6 size=299320 card=2138)(object id 205)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                       607        0.09          1.96
  direct path read                              450        0.03          0.51
  flashback log file sync                       592        0.01          1.51
  direct path write                             452        0.02          1.02
  latch: cache buffers chains                    72        0.00          0.00
  buffer busy waits                              54        0.00          0.01
  enq: HW - contention                           70        0.04          0.61
  enq: TX - index contention                      8        0.00          0.00
  read by other session                           1        0.01          0.01
********************************************************************************

SQL ID: 44z7snw61qx9x
Plan Hash: 1133963577

*** 2011-03-01 11:38:27.933
MERGE INTO sqlobj$auxdata                        
                               USING dual ON (:1 IS NULL)                     
                                 WHEN MATCHED THEN                            
                                     UPDATE SET description = :2,             
                                                  creator = nvl(:3, creator), 
                                                    origin = :4,              
                                                      version = :5,           
                                                        created = :6,         
                                                          last_modified = :7, 
                                                            last_verified = 
  nvl(:8, last_verified),                                       
  parse_cpu_time = null,                                                      
    optimizer_cost = nvl(:9, optimizer_cost),                                 
      module = nvl(:10, module),                                              
        action = nvl(:11, action),                                            
          priority = nvl(:12, priority),                                      
            optimizer_env = nvl(:13, optimizer_env),                          
              bind_data = nvl(:14, bind_data),                                
                parsing_schema_name = nvl(:15, parsing_schema_name),          
                  executions = nvl(:16, executions),                          
                    elapsed_time = nvl(:17, elapsed_time),                    
                      cpu_time = nvl(:18, cpu_time),                          
                        buffer_gets = nvl(:19, buffer_gets),                  
                          disk_reads = nvl(:20, disk_reads),                  
                            direct_writes = nvl(:21, direct_writes),          
                              rows_processed = nvl(:22, rows_processed),      
                                fetches = nvl(:23, fetches),                  
                                  end_of_fetch_count = nvl(:24, 
  end_of_fetch_count),                            task_id = nvl(:25, task_id),
                                                    task_exec_name = nvl(:26, 
  task_exec_name),                                    task_obj_id = nvl(:27, 
  task_obj_id),                                          task_fnd_id = 
  nvl(:28, task_fnd_id),                                          task_rec_id 
  = nvl(:29, task_rec_id),                                          flags = 0,
                                                                      spare1 =
   null,                                                                
  spare2 = null                                                      WHERE 
  signature = :30                                                             
    AND category = :31                                                        
      AND obj_type = :32                                                      
        AND plan_id = :33                                                     
  WHEN NOT MATCHED THEN                                                       
      INSERT (signature, category, obj_type, plan_id,                         
                description, creator, origin, version,                        
                  created, last_modified, last_verified, parse_cpu_time,      
                    optimizer_cost, module, action, priority,                 
                      optimizer_env, bind_data, parsing_schema_name, 
  executions,                    elapsed_time, cpu_time, buffer_gets, 
  disk_reads,                              direct_writes, rows_processed, 
  fetches,end_of_fetch_count,                    task_id, task_exec_name, 
  task_obj_id, task_fnd_id,                            task_rec_id, flags, 
  spare1, spare2)                                   VALUES (:34, :35, :36, 
  :37,                                                           :38, :39, 
  :40, :41,                                                           :42, 
  :43, null, null,                                                         
  :44, :45, :46, :47,                                                         
    :48, :49, :50, :51,                                                       
      :52, :53, :54, :55,                                                     
        :56, :57, :58, :59,                                                   
          :60, :61, :62, :63,                                                 
            :64

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        252          2           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0        252          2           1

Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 2)

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  MERGE  SQLOBJ$AUXDATA (cr=252 pr=0 pw=0 time=4892 us)
   2440   VIEW  (cr=252 pr=0 pw=0 time=7181 us)
   2440    MERGE JOIN OUTER (cr=252 pr=0 pw=0 time=5835 us cost=18 size=784646 card=2138)
      1     TABLE ACCESS FULL DUAL (cr=2 pr=0 pw=0 time=71 us cost=2 size=2 card=1)
   2440     VIEW  (cr=250 pr=0 pw=0 time=4912 us cost=16 size=780370 card=2138)
   2440      FILTER  (cr=250 pr=0 pw=0 time=3808 us)
   2440       TABLE ACCESS FULL SQLOBJ$AUXDATA (cr=250 pr=0 pw=0 time=2953 us cost=20 size=780370 card=2138)

********************************************************************************

SQL ID: bsa0wjtftg3uw
Plan Hash: 2020579421
select file# 
from
 file$ where ts#=:1


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       15      0.00       0.00          0         29          0          14
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       17      0.00       0.00          0         29          0          14

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 3)

Rows     Row Source Operation
-------  ---------------------------------------------------
     14  TABLE ACCESS BY INDEX ROWID FILE$ (cr=29 pr=0 pw=0 time=88 us cost=1 size=35 card=5)
     14   INDEX RANGE SCAN I_FILE2 (cr=15 pr=0 pw=0 time=151 us cost=1 size=0 card=5)(object id 44)




********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.01       0.01          0          0          0           0
Execute      2      1.08       1.14          0          0          1           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      1.09       1.15          0          0          1           0

Misses in library cache during parse: 1

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  log file sync                                   3        0.06          0.07
  SQL*Net message to client                       6        0.00          0.00
  SQL*Net message from client                     6       27.68         47.53
  reliable message                                1        0.00          0.00
  Disk file operations I/O                        3        0.00          0.00
  Parameter File I/O                              8        0.01          0.02
  SQL*Net break/reset to client                   2        0.00          0.00
  direct path read                             6503        0.75         18.96
  latch: cache buffers chains                    78        0.00          0.00
  buffer busy waits                             103        0.00          0.00
  library cache: mutex X                         17        0.00          0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse    39047      1.64       1.70          0          0          1           0
Execute  45549    158.03     342.53      22465    2652285     286877       19521
Fetch    39115      1.12       1.16          1      84889          0       32634
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   123711    160.80     345.40      22466    2737174     286878       52155

Misses in library cache during parse: 21
Misses in library cache during execute: 17

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                       15        0.00          0.00
  db file sequential read                      9457        1.04         49.35
  flashback log file sync                      8420        0.26         26.86
  direct path write                            6504        0.47         37.64
  direct path read                             6495        0.42         16.86
  enq: HW - contention                         1208        0.89         25.03
  latch: cache buffers chains                  1024        0.00          0.04
  buffer busy waits                             941        1.00          6.02
  read by other session                          25        0.03          0.36
  latch: enqueue hash chains                      2        0.00          0.00
  library cache: mutex X                         16        0.00          0.00
  enq: TX - index contention                     65        0.05          0.21
  buffer deadlock                                11        0.00          0.00
  log file switch completion                      5        0.24          0.50
  latch free                                      2        0.00          0.00
  latch: shared pool                              8        0.00          0.00
  latch: object queue header operation            1        0.00          0.00
  latch: cache buffers lru chain                  4        0.00          0.00
  log file switch (checkpoint incomplete)         3        0.14          0.28
  enq: TX - allocate ITL entry                    1        0.00          0.00
  latch: undo global data                         1        0.00          0.00

    4  user  SQL statements in session.
19540  internal SQL statements in session.
19544  SQL statements in session.
********************************************************************************


....

       1  session in tracefile.
       4  user  SQL statements in trace file.
   19540  internal SQL statements in trace file.
   19544  SQL statements in trace file.
      20  unique SQL statements in trace file.
 3288358  lines in trace file.
     394  elapsed seconds in trace file.
Follow

Get every new post delivered to your Inbox.

Join 68 other followers