Mohamed Houri’s Oracle Notes

March 31, 2018

From bind sensitive to bind aware

Filed under: adaptive cursor sharing,cursor sharing — hourim @ 1:20 pm

In the book I have co-authored I wrote chapter 4 on Adaptive Cursor Sharing which you can read here free of charge. In this chapter I said that Oracle uses an algorithm to transit a cursor from bind sensitive to bind aware. I have demonstrated that this algorithm handles three different cases:

  • when only two adjacent buckets are involved
  • when only two distinct buckets are involved
  • when all three buckets are involved

In this article and in this one I have explained reliably how the two first cases are handled. But I have always failed to decipher how Oracle manages the third case. I think that this article will finally explain the nature of the algorithm used by Oracle to mark bind aware a bind sensitive cursor when all buckets are involved. Here’s a function I have implemented for that purpose:

create or replace function fv_is_bind_aware
          (pin_first_bucket in number
          ,piv_sql_id       in varchar2
          ) 
return varchar2
-- ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
-- Date      : January 2018
-- Scope     : say whether the next execution at any bucket will
--             mark the underlying cursor bind aware or not.
--             This function is valid only when the bind sensitive
--             cursor has undergone executions at three buckets 0,1 and 2
--             without  being already bind aware 
-- Parameters: 
--      1) pin_first_bucket is the bucket at which the very first execution
--             has been done
--      2) piv_sql_id is the sql_id of the underlying cursor
--
--Usage      : select fv_is_bind_aware(0, 7ck8k47bnqpnv) from dual;
--             if 'Y' then the next execution will mark cursor bind aware
--             if 'N' then the cursor will not be hard parsed during the next
--             execution
-- ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
is
  ln_nbr_of_distantexecs number  := 0;
  ln_nbr_of_totalexecs   number := 0;
begin
  for x in (select 
               bucket_id
              ,count
            from 
               sys.v_$sql_cs_histogram
            where 
               sql_id = piv_sql_id 
            order by bucket_id
            )
  loop
    ln_nbr_of_totalexecs   := ln_nbr_of_totalexecs   +  x.count;
    ln_nbr_of_distantexecs := ln_nbr_of_distantexecs 
                            + (x.count *abs(x.bucket_id - pin_first_bucket));
  end loop;
  --                      
  if ln_nbr_of_distantexecs/ln_nbr_of_totalexecs >= 0.5 
  then 
     return 'Y';
  else 
     return 'N';
  end if;
end fv_is_bind_aware;
/

Using plain english the above function can be turned to:

  • When the number of executions done at distant buckets reaches half that of total executions at all buckets then mark the cursor bind aware during the next execution at any bucket.

The only subtlety here is to figure out what a distant bucket represents in this context. When you know how ACS works internally you know the importance Oracle gives to the very first execution of the bind sensistive cursor. Since there are three buckets 0, 1 and 2, a distant bucket represents the two buckets at which the very first execution didn’t occur. So Oracle will always keep track of the first bucket at which the cursor has been executed and compute the total number of executions done at the other two buckets (the adjacent one and the distant one). And for the sake of completeness Oracle considers:

  • total number of executions = sum(v_$sql_cs_histogram.count)
  • the total number of execution done at distant(non adjacent) bucket is doubled
ln_nbr_of_distantexecs := ln_nbr_of_distantexecs 
                            + (x.count *abs(x.bucket_id – pin_first_bucket));
-- Since bucket id 0 and 2 are the two distant buckets we have
abs (0-2) = abs (2-0) = 2

All cases I have tested so far confirmed the reliability of this function. Here’s below few of those test cases (the model as always can be found here):

alter system flush shared_pool;

select count(1) from t_acs where n2 = 1; –- very fist execution at bucket 0
select count(1) from t_acs where n2 = 1;
select count(1) from t_acs where n2 = 1;
–-
select count(1) from t_acs where n2 = 1000;
select count(1) from t_acs where n2 = 1000;
–-
select count(1) from t_acs where n2 = 1e6;

SQL_ID  7ck8k47bnqpnv, child number 0
-------------------------------------
------------------------------------------------
| Id  | Operation         | Name       | Rows  |
------------------------------------------------
|   0 | SELECT STATEMENT  |            |       |
|   1 |  SORT AGGREGATE   |            |     1 |
|*  2 |   INDEX RANGE SCAN| T_ACS_IDX1 |     1 |
------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("N2"=:SYS_B_1)

select
    child_number
   ,bucket_id
   ,count
 from
   gv$sql_cs_histogram
 where
    sql_id ='7ck8k47bnqpnv';

CHILD_NUMBER  BUCKET_ID      COUNT
------------ ---------- ----------
           0          0          3 → 3 executions at bucket n°0
           0          1          2 → 2 executions at bucket n°1
           0          2          1 → 1 executions at bucket n°2

Will the next execution at any bucket mark the cursor bind aware and hard parse a new execution plan? Let’s ask the function

SQL> select fv_is_bind_aware(0, '7ck8k47bnqpnv') iba from dual;

IBA
---
Y

The function is saying that the next execution will mark the cursor bind aware. Let’s check

select count(1) from t_acs where n2 = 100;

select
    child_number
   ,bucket_id
   ,count
 from
   gv$sql_cs_histogram
 where
    sql_id ='7ck8k47bnqpnv';
CHILD_NUMBER  BUCKET_ID      COUNT
------------ ---------- ----------
           1          0          1  –- a new bind aware child cursor 
           1          1          0
           1          2          0
           0          0          3
           0          1          2
           0          2          1

Indeed the function has correctly expected the transition from bind sensitive to bind aware.

Do you want another example? Here you are:

alter system flush shared_pool;
-- execute this 7 times
–- first execution occurred at bucket n°2
select count(1) from t_acs where n2 = 1e6;

–- execute this 2 times
select count(1) from t_acs where n2 = 1000;

-- execute this 2 times 
select count(1) from t_acs where n2 = 1;

select
    child_number
   ,bucket_id
   ,count
 from
   gv$sql_cs_histogram
 where
    sql_id ='7ck8k47bnqpnv';

CHILD_NUMBER  BUCKET_ID      COUNT
------------ ---------- ----------
           0          0          2
           0          1          2
           0          2          7

Since the very first execution occurred at bucket n°2 we are going to call the function as follows:


select fv_is_bind_aware(2, '7ck8k47bnqpnv') iba from dual;

IBA
---
Y

select count(1) from t_acs where n2 = 1e4;

select
    child_number
   ,bucket_id
   ,count
 from
   gv$sql_cs_histogram
 where
    sql_id ='7ck8k47bnqpnv';

CHILD_NUMBER  BUCKET_ID      COUNT
------------ ---------- ----------
           1          0          0
           1          1          1
           1          2          0
           0          0          2
           0          1          2
           0          2          7

Spot how the function has again correctly expected the transition.

Here’s another example where the very first execution has been done at bucket id n°1


alter system flush shared_pool;
-- run this 7 times
select count(1) from t_acs where n2 = 1000;

-- run this 2 time
select count(1) from t_acs where n2 = 1e6;

-- run this 2 times
select count(1) from t_acs where n2 = 100;

select
    child_number
   ,bucket_id
   ,count
 from
   gv$sql_cs_histogram
 where
    sql_id ='7ck8k47bnqpnv';

CHILD_NUMBER  BUCKET_ID      COUNT
------------ ---------- ----------
           0          0          2
           0          1          7
           0          2          2
-- check the transition using the function
select fv_is_bind_aware(1, '7ck8k47bnqpnv') iba from dual;

IBA
---
N

According to the function the next execution will not mark the cursor bind aware:

select count(1) from t_acs where n2 = 1e4;

select
    child_number
   ,bucket_id
   ,count
 from
   gv$sql_cs_histogram
 where
    sql_id ='7ck8k47bnqpnv';
CHILD_NUMBER  BUCKET_ID      COUNT
------------ ---------- ----------
           0          0          2
           0          1          8
           0          2          2

That’s again a correct expectation.

Let me emphasize here the importance of the first parameter of the function fv_is_bind_aware which represents the bucket id at which the very first execution of the cursor has been done under. Should I have used the wrong bucket id (0 and 2) the function would have done a wrong expectation as shown below(test have been done before the 8th execution above):

select fv_is_bind_aware(0, '7ck8k47bnqpnv') iba from dual;

IBA
---
Y

select fv_is_bind_aware(2, '7ck8k47bnqpnv') iba from dual;

IBA
---
Y

Now will the next execution mark the cursor bind aware?

select fv_is_bind_aware(1, '7ck8k47bnqpnv') iba from dual;

IBA
---
N

select count(1) from t_acs where n2 = 100;

select
    child_number
   ,bucket_id
   ,count
 from
   gv$sql_cs_histogram
 where
    sql_id ='7ck8k47bnqpnv';

CHILD_NUMBER  BUCKET_ID      COUNT
------------ ---------- ----------
           0          0          3
           0          1          8
           0          2          2

And the next execution?

select fv_is_bind_aware(1, '7ck8k47bnqpnv') iba from dual;

IBA
---
N

select count(1) from t_acs where n2 = 1e6;

select
    child_number
   ,bucket_id
   ,count
 from
   gv$sql_cs_histogram
 where
    sql_id ='7ck8k47bnqpnv';

CHILD_NUMBER  BUCKET_ID      COUNT
------------ ---------- ----------
           0          0          3
           0          1          8
           0          2          3

And so on until the function says it time for the cursor to switch

select fv_is_bind_aware(1, '7ck8k47bnqpnv') iba from dual;

IBA
---
N

select count(1) from t_acs where n2 = 100;
select count(1) from t_acs where n2 = 1e6;

select fv_is_bind_aware(1, '7ck8k47bnqpnv') iba from dual;

IBA
---
Y

select count(1) from t_acs where n2 = 1;

select
    child_number
   ,bucket_id
   ,count
 from
   gv$sql_cs_histogram
 where
    sql_id ='7ck8k47bnqpnv';

CHILD_NUMBER  BUCKET_ID      COUNT
------------ ---------- ----------
           1          0          1
           1          1          0
           1          2          0
           0          0          4
           0          1          8
           0          2          4

Summary

Adaptive Cursor Sharing in real life systems is known to cause performance pain rather than to solve the conflictual issue of sharing and optimizing it has been created for. But it is always nice to know how it works. Particularly to understand the transition of the cursor from bind sensistive to bind aware.

March 20, 2018

DDL optimisation is not working in 12cR2: really?

Filed under: Oracle — hourim @ 7:32 pm

If you want to know what DDL optimisation is then you can read this article I wrote a couple of years ago.

As the title already suggests, I have been surprised during the preparation of a database upgrade script from 11gR2 to 12cR2 to see the following alter table taking 5 hours instead of what should have been an instantaneous operation:

SQL> select banner from v$version;
BANNER
--------------------------------------------------------------------------------
Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production


SQL> alter table t1 add
  	(col1 number  default 0 null
       ,col2 number default 0 null
       ,col3 number default 0 null
       ,col4 number default 0 null
       ,col5 number default 0 null
       ,col6 number default 0 null
       ,col7 number default 0 null
      )
      /
Table altered.

Elapsed: 04:51:24.48

Oracle should have used the DDL optimisation technique which has been extended to nullable columns in 12cR1.

So what the heck is this? From where am I going to start troubleshooting this issue?

The first thing that came to my mind was to check the value of the hidden parameter, _add_col_optim_enabled, driven this feature. It might be possible that the DBA has un-set its default value during the database upgrade:

SQL> select
         n.ksppinm
        ,c.ksppstvl
        ,n.ksppdesc
       from
        sys.x$ksppi n
        ,sys.x$ksppcv c
       where n.indx=c.indx
       and n.ksppinm = '_add_col_optim_enabled';

KSPPINM                KSPPSTVL   KSPPDESC
---------------------- ---------- -----------------------------------
_add_col_optim_enabled TRUE       Allows new add column optimization

The DDL optimisation parameter is correctly set. If this parameter has been changed to FALSE the DDL optimisation feature would have, naturally, been cancelled as the following demonstrates:

create table t as select rownum n1 from dual connect by level <=10;

-- the following alter table will use the DDL optimisation
-- as the predicate of the execution plan confirms

alter table t add col1 number default 0 null;

select count(1) from t where col1=42;

select * from table(dbms_xplan.display_cursor);					   

---------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes |
---------------------------------------------------
|   0 | SELECT STATEMENT   |      |       |       |
|   1 |  SORT AGGREGATE    |      |     1 |     3 |
|*  2 |   TABLE ACCESS FULL| T    |     1 |     3 |
---------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter(DECODE(TO_CHAR(SYS_OP_VECBIT("SYS_NC00002$",0)),NULL
             ,NVL("COL1",0),'0',NVL("COL1",0),'1',"COL1")=42)

-- change the hidden parameter driving the DDL optimisation
alter session set "_add_col_optim_enabled"=false;

-- and add a new equivalent column
alter table t add col2 number default 0 null;

select count(1) from t where col2=42;

select * from table(dbms_xplan.display_cursor);	

---------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes |
---------------------------------------------------
|   0 | SELECT STATEMENT   |      |       |       |
|   1 |  SORT AGGREGATE    |      |     1 |     3 |
|*  2 |   TABLE ACCESS FULL| T    |     1 |     3 |
---------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 – filter("COL2"=42) -- DDL optimisation didn't occur.

After having ruled out the hidden parameter hypothesis, I embarked on a bibliography research checking the Oracle official documentation to see whether the DDL optimisation has actually been withdrawn in 12cR2 for nullable added columns having a default value or not. It is useless to say that this effort has been pointless.

Nowadays when all else fails Twitter might be there for a quick help:

Unfortunately not everyone is lucky. No answer 🙂

There was, nevertheless, something in the overnight SQL batch log that should have given me a hint about what was happeing under the hood:

SQL> alter table t1 add (colX numeric default 0 not null);

Table altered.

Elapsed: 00:500:00.06

While adding a nullable column with default value was taking an eternity, adding a not null column with default value to the same table was instantaneous. This database is reacting exactly as if I were running under an 11gR2 version. But I’ve completely neglected this option and continued exploring other possibilities until I decided to close my laptop and leave for the week end.

On Monday of the next week I shared this issue with one of my friends who suggested me to check the compatible parameter. No sooner said than done:

SQL> show parameter compatible

NAME                                 TYPE        VALUE
------------------------------------ ----------- ----------
compatible                           string      11.2.0.4.0

Now that I have this value in front of my eyes, bringing together the pieces of the puzzle becomes easy. I provisionned a new fresh copy of Production database, upgraded it to 12.2.0.1.0, checked the compatible parameter:

SQL> show parameter compatible

NAME                                 TYPE        VALUE
------------------------------------ ----------- --------
compatible                           string      12.2.0.1

and launched again the same alter table which obviously completed in less a second:

SQL> alter table t1 add
  	(col1 number  default 0 null
       ,col2 number default 0 null
       ,col3 number default 0 null
       ,col4 number default 0 null
       ,col5 number default 0 null
       ,col6 number default 0 null
       ,col7 number default 0 null
      )
      /
Table altered.

Elapsed: 00:00:00.10

Bottom Line

It doesn’t matter what Oracle version you are running, the only features that you will be allowed to use are those enabled by the Oracle version you will set in the compatible parameter. Thus don’t be surprised to see new features not kicking in if you set the compatible mode to a prior release value where these intended features were not implemented yet.

March 17, 2018

Library cache lock

Filed under: Oracle — hourim @ 7:55 am

This is a very simple note, as much for my own documentation as anything else, showing how I have extremely rapidly identified what was causing a database application to wait on a library cache lock wait event.

The ASH of my customer case was showing the following list of predominant wait events:

select event, count(1)
from gv$active_session_history
where
    sample_time between to_date('09032018 00:46:00', 'ddmmyyyy hh24:mi:ss')
                and     to_date('09032018 10:44:00', 'ddmmyyyy hh24:mi:ss')
group by event
order by 2 desc;

EVENT                                  COUNT(1)
------------------------------------ ----------
library cache lock                       350174
library cache: mutex X                    54474
cursor: pin S wait on X                   10896
                                           2964

Naturally I wanted to know what sql_id is responsible of these library cache wait events first via ASH

select sql_id, count(1)
from gv$active_session_history
where
    sample_time between to_date('09032018 00:46:00', 'ddmmyyyy hh24:mi:ss')
                and     to_date('09032018 10:44:00', 'ddmmyyyy hh24:mi:ss')
and event in 
 ('library cache lock','library cache: mutex X','cursor: pin S wait on X')
group by sql_id
order by 2 desc;

SQL_ID            COUNT(1)
----------------- --------
6tcs65pchhp71       147902
9mqzzppbpa64j         7373
                         3	

And then via classical dbms_xplan to get the corresponding execution plan and v$sql to get the SQL text respectively:

SQL> select * from table(dbms_xplan.display_cursor('6tcs65pchhp71',null));

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------
SQL_ID: 6tcs65pchhp71 cannot be found
SQL> select sql_fulltext, executions, end_of_fetch_count
    from gv$sql
    where sql_id = '6tcs65pchhp71';

no rows selected

Let’s summarize: there is a sql_id which is responsible of a dramatic library cache wait event that I am monitoring at real time basis and which

  • has no execution plan in memory
  • and is not present in gv$sql

The above two points manifestly are symptoms of a sql query which hasn’t gone beyond the parse phase. In other words it might be a query which Oracle is not able to soft parse and thereby it has never reached the hard parse phase nor the execution step. Hopefully ASH can clearly show this:

select 
     in_parse
    ,in_hard_parse
    ,in_sql_execution
    ,count(1)
from gv$active_session_history
where
    sample_time between to_date('09032018 00:46:00', 'ddmmyyyy hh24:mi:ss')
                and     to_date('09032018 10:44:00', 'ddmmyyyy hh24:mi:ss')
and
   sql_id = '6tcs65pchhp71'
group by 
     in_parse
    ,in_hard_parse
    ,in_sql_execution
order by 4 desc;

I I I   COUNT(1)
- - - ----------
Y N N     162758
Y Y N        385

Indeed this query is almost always in the “parse” phase. So the initial question of what is causing this dramatic library cache lock turned to be : why this query is sticking at the parse phase?

I don’t know why I decided to look at the dba_hist_sqltext but it made my day:

SQL> select sql_text from dba_hist_sqltext where sql_id = '6tcs65pchhp71';

SQL_TEXT
--------------------------------------------------------------------------------
select col1, col2,...,coln from t1;

I was again lucky that this query has no where clause and no bind variable value to use so that I tried to run it as is and here what I found:

select col1, col2,...,coln 
from t1;
     *
ERROR at line 15:
ORA-00600 : internal error code, arguments: [qksvcGetGuardCol:2], [50574], [0], [],
[],[],[],[],[],[],[],[],[],

The multi-user concurrent system was repeating the same query several times and since this query was always failing during the parse phase we observed this library cache lock at the top of the wait events.

March 11, 2018

Which execution plan will be used?

Filed under: Sql Plan Managment — hourim @ 4:08 pm

Following a question raised by Franck Pachot on Twitter, I was surprised that 43% of the answers were false. The question was terribly simple : an SQL Plan Baseline contains two execution plans:

  • Plan 1: is enabled but not accepted
  • Plan 2: is not enabled but accepted

If the Cost Based Optimiser comes up with Plan 1, which execution plan will the query finally be allowed to use?

There are very simple rules to know when it comes to the interaction between the CBO and the presence of SPM baselined plans:

  • Not enabled SPM plans will not be used regardless of their acceptance status
  • Enabled SPM plans will not be used if they are not accepted

From Franck’s question we understand that SPM Plan 2 is not enabled; so we will rule it out from the correct answer possibilities. We can see as well that SPM Plan 1 is not accepted which makes it unusable by the CBO. Since both SPM execution plans are not usable because of their enabled or accepted properties the CBO will use the plan it will come up with : Plan 1 in this case.

Here below the demonstration (the model can be found here):

alter session set cursor_sharing= force;
alter session set optimizer_capture_sql_plan_baselines=true;

select count(1) from t_acs where n2 = 1e6;
select count(1) from t_acs where n2 = 1e6;

alter session set optimizer_capture_sql_plan_baselines=false;

select  sql_handle, plan_name, enabled, accepted
from dba_sql_plan_baselines
where signature = '7542536418437113777';

SQL_HANDLE             PLAN_NAME                      ENA ACC
---------------------- ------------------------------ --- ---
SQL_68ac78e9166427b1   SQL_PLAN_6jb3sx4b689xj3069e6f9 YES YES

DECLARE
   l_p  PLS_INTEGER;
BEGIN
  l_p := DBMS_SPM.alter_sql_plan_baseline(
            sql_handle      => 'SQL_68ac78e9166427b1',
            plan_name       => 'SQL_PLAN_6jb3sx4b689xj3069e6f9',
            attribute_name  => 'enabled',
            attribute_value => 'NO');
END;
/

select  sql_handle, plan_name, enabled, accepted
from dba_sql_plan_baselines
where signature = '7542536418437113777';

SQL_HANDLE                     PLAN_NAME                      ENA ACC
------------------------------ ------------------------------ --- ---
SQL_68ac78e9166427b1           SQL_PLAN_6jb3sx4b689xj3069e6f9 NO  YES

We have our Plan 2: Accepted but not Enabled.

Next I will generate Plan 1: Enabled but not Accepted

select count(1) from t_acs where n2 = 1;

SQL> select count(1) from t_acs where n2 = 1;

  COUNT(1)
----------
         1

SQL> select * from table(dbms_xplan.display_cursor)


SQL_ID  7ck8k47bnqpnv, child number 1

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

NOTE: cannot fetch plan for SQL_ID: 7ck8k47bnqpnv, CHILD_NUMBER: 1
      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)

Whenever I see this error I know that it has been raised because the CBO comes up with an execution plan that doesn’t match one of the SPM baselined plans:

select  sql_handle, plan_name, enabled, accepted
from dba_sql_plan_baselines
where signature = '7542536418437113777';

SQL_HANDLE                     PLAN_NAME                      ENA ACC
------------------------------ ------------------------------ --- ---
SQL_68ac78e9166427b1           SQL_PLAN_6jb3sx4b689xj3069e6f9 NO  YES
SQL_68ac78e9166427b1           SQL_PLAN_6jb3sx4b689xjf5f8c88e YES NO

Here we go: we have an SPM baseline with two execution plans exactly as asked by Franck

select * from table(dbms_xplan.display_sql_plan_baseline(sql_handle => 'SQL_68ac78e9166427b1'));
 
--------------------------------------------------------------------------------
SQL handle: SQL_68ac78e9166427b1
SQL text: select count(:"SYS_B_0") from t_acs where n2 = :"SYS_B_1"
--------------------------------------------------------------------------------
 
--------------------------------------------------------------------------------
Plan name: SQL_PLAN_6jb3sx4b689xjf5f8c88e         Plan id: 4126722190
Enabled: YES     Fixed: NO      Accepted: NO      Origin: AUTO-CAPTURE
Plan rows: From dictionary
--------------------------------------------------------------------------------
 
Plan hash value: 1687207741
--------------------------------------------------------------------------------
| Id  | Operation         | Name       | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |            |     1 |     3 |     3   (0)| 00:00:01 |
|   1 |  SORT AGGREGATE   |            |     1 |     3 |            |          |
|*  2 |   INDEX RANGE SCAN| T_ACS_IDX1 |     1 |     3 |     3   (0)| 00:00:01 |
--------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   2 - access("N2"=:SYS_B_1)
 
--------------------------------------------------------------------------------
Plan name: SQL_PLAN_6jb3sx4b689xj3069e6f9         Plan id: 812246777
Enabled: NO      Fixed: NO      Accepted: YES     Origin: AUTO-CAPTURE
Plan rows: From dictionary
--------------------------------------------------------------------------------
 
Plan hash value: 535703726
----------------------------------------------------------------------------
| Id  | Operation          | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |       |     1 |     3 |   628   (3)| 00:00:01 |
|   1 |  SORT AGGREGATE    |       |     1 |     3 |            |          |
|*  2 |   TABLE ACCESS FULL| T_ACS |  1099K|  3219K|   628   (3)| 00:00:01 |
----------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter("N2"=:SYS_B_1)

Next I will execute the above query with a bind variable value that will favor the index range scan plan which is present in the SPM baseline, is enabled but not accepted:

SQL> @53on
alter session set events '10053 trace name context forever, level 1';
alter session set "_optimizer_trace"=all;

select count(1) from t_acs where n2 = 100;

SQL_ID  7ck8k47bnqpnv, child number 1

Plan hash value: 1687207741
--------------------------------------------------------
| Id  | Operation         | Name       | Rows  | Bytes |
--------------------------------------------------------
|   0 | SELECT STATEMENT  |            |       |       |
|   1 |  SORT AGGREGATE   |            |     1 |     3 |
|*  2 |   INDEX RANGE SCAN| T_ACS_IDX1 |   100 |   300 |
--------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("N2"=:SYS_B_1)

SQL> @53off
alter session set events '10053 trace name context off';

The absence of the Note at the bottom of the above execution plan indicates that the CBO didn’t use any execution plan from the SPM baseline but it uses rather the execution plan it comes up with during the compilation phase. In the corresponding 10053 trace file we can read the following lines:

SPM: statement found in SMB

SPM: finding a match for the generated plan, planId = 4126722190
SPM: plan baseline non-existant or empty (no accepted plans) so using cost-based plan, planId = 4126722190

The developer at Oracle could not be clearer than this : non-existant or empty (no accepted plans) so using cost-based plan

March 5, 2018

SEMI JOIN in modern relational databases

Filed under: Oracle — hourim @ 8:17 pm

A semi join returns rows only from the first table provided at least one matching row is found in the second table. The difference between a conventional join and a semi join is that rows from the first table are returned once at most even when the join column of the second table contains duplicate rows. There is no ANSI SQL way to invoke a semi join. The following syntax doesn’t exist:

  SQL>  select 
          t1.* 
        from t1 
          semi join t2 
        on t1.n1= t2.n1

In almost all modern relational databases, the semi join logical operation is triggered via the predicate IN, ANY, SOME, EXISTS and DISTINCT. MS-SQL Server has an extra particularity which makes it using a semi join during an INTERSECT operation as we will see later in this article.

The following queries illustrate these diferent semi-join cases in a 12.2.0.1 Oracle release:

SQL> create table t1
     as
        select
            rownum n1,
            mod(rownum,5) n2,
            trunc( (rownum - 1 / 3) ) n3
        from
            dual
        connect by
            level <= 1e4; SQL> create table t2
     as
        select
            rownum n1,
            mod(rownum,3) n2,
            trunc( (rownum - 1 / 5) ) n3
        from
            dual
        connect by
        level <= 5;

1. Using IN, ANY and SOME

SQL> select 
       t1.n1
     from
       t1
     where
       t1.n1 in (select t2.n1 from t2);

SQL> select 
       t1.n1
     from
       t1
     where
      t1.n1 = any (select t2.n1 from t2);

SQL> select 
       t1.n1
     from
       t1
     where
    t1.n1 = some (select t2.n1 from t2);
   
Plan hash value: 1275841967
----------------------------------------------------------------
| Id  | Operation            | Name | Starts | E-Rows | A-Rows |
----------------------------------------------------------------
|   0 | SELECT STATEMENT     |      |      1 |        |      5 |
|*  1 |  HASH JOIN RIGHT SEMI|      |      1 |      5 |      5 |
|   2 |   TABLE ACCESS FULL  | T2   |      1 |      5 |      5 |
|   3 |   TABLE ACCESS FULL  | T1   |      1 |  10000 |  10000 |
----------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("T1"."N1"="T2"."N1")

2. Using EXISTS

select 
   t1.n1
 from
   t1
 where
   exists (select null from t2 where t2.n1 = t1.n1);

Plan hash value: 1275841967
----------------------------------------------------------------
| Id  | Operation            | Name | Starts | E-Rows | A-Rows |
----------------------------------------------------------------
|   0 | SELECT STATEMENT     |      |      1 |        |      5 |
|*  1 |  HASH JOIN RIGHT SEMI|      |      1 |      5 |      5 |
|   2 |   TABLE ACCESS FULL  | T2   |      1 |      5 |      5 |
|   3 |   TABLE ACCESS FULL  | T1   |      1 |  10000 |  10000 |
----------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("T2"."N1"="T1"."N1")

3. Using DISTINCT in INNER join and the effect of the 12cR1 Partial join

select 
  distinct
   t1.n1
 from
   t1
 inner join t2
 on (t1.n1 = t2.n1);

Plan hash value: 3703458891
---------------------------------------------------------------
| Id  | Operation           | Name | Starts | E-Rows | A-Rows |
---------------------------------------------------------------
|   0 | SELECT STATEMENT    |      |      1 |        |      5 |
|   1 |  HASH UNIQUE        |      |      1 |      5 |      5 |
|*  2 |   HASH JOIN SEMI    |      |      1 |      5 |      5 |
|   3 |    TABLE ACCESS FULL| T2   |      1 |      5 |      5 |
|   4 |    TABLE ACCESS FULL| T1   |      1 |  10000 |    256 | –- only 256 rows
---------------------------------------------------------------

Outline Data
-------------

  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('12.2.0.1')
      DB_VERSION('12.2.0.1')
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$58A6D7F6")
      MERGE(@"SEL$1" >"SEL$2")
      OUTLINE(@"SEL$2")
      OUTLINE(@"SEL$1")
      FULL(@"SEL$58A6D7F6" "T2"@"SEL$1")
      FULL(@"SEL$58A6D7F6" "T1"@"SEL$1")
      LEADING(@"SEL$58A6D7F6" "T2"@"SEL$1" "T1"@"SEL$1")
      USE_HASH(@"SEL$58A6D7F6" "T1"@"SEL$1")
      USE_HASH_AGGREGATION(@"SEL$58A6D7F6")
      PARTIAL_JOIN(@"SEL$58A6D7F6" "T1"@"SEL$1")
      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------
   2 – access("T1"."N1"="T2"."N1")

The apparition of the semi join in the above execution plan is the result of the partial join transformation introduced by Oracle as from 12cR1. Earlier versions were not able to use this partial join transformation scanning, as such, the entire content of t1 table is scanned instead of tiny 256 rows as shown below:

select 
   /*+ NO_PARTIAL_JOIN(@"SEL$58A6D7F6" "T1"@"SEL$1") */
  distinct
   t1.n1
 from
   t1
 inner join t2
 on (t1.n1 = t2.n1);

Plan hash value: 975306333

---------------------------------------------------------------
| Id  | Operation           | Name | Starts | E-Rows | A-Rows |
---------------------------------------------------------------
|   0 | SELECT STATEMENT    |      |      1 |        |      5 |
|   1 |  HASH UNIQUE        |      |      1 |      5 |      5 |
|*  2 |   HASH JOIN         |      |      1 |      5 |      5 |
|   3 |    TABLE ACCESS FULL| T2   |      1 |      5 |      5 |
|   4 |    TABLE ACCESS FULL| T1   |      1 |  10000 |  10000 | -- 10,000 rows
---------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("T1"."N1"="T2"."N1")

So far all the semi join logical operations have been executed via a HASH JOIN physical operation. This doesn’t mean that a semi joins can’t be used in a NESTED LOOPS physical operation. Here’s below the demonstratation:

SQL> create index t2_idx on t2(n1);
SQL> select 
       t1.n1
     from
       t1
     where
      t1.n1 in (select t2.n1 from t2);

----------------------------------------------------------------
| Id  | Operation          | Name   | Starts | E-Rows | A-Rows |
----------------------------------------------------------------
|   0 | SELECT STATEMENT   |        |      1 |        |      5 |
|   1 |  NESTED LOOPS SEMI |        |      1 |      5 |      5 |
|   2 |   TABLE ACCESS FULL| T1     |      1 |  10000 |  10000 |
|*  3 |   INDEX RANGE SCAN | T2_IDX |  10000 |      1 |      5 |
----------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - access("T1"."N1"="T2"."N1")

4. SEMI join and uniqueness
I started this article by specifying that a semi join guaranties at most one row will be returned (per join column) from the left table even if there are duplicate rows in the join column of the second table. An example being worth a thousand words so here we go:

SQL> -- insert first a duplicate row in the rigth table
SQL> insert into t2 values(5,42,42);
SQL> commit;

-- first we will start using a conventional join
SQL> select 
   t1.n1
 from
   t1
 inner join t2
 on (t1.n1 = t2.n1);
        N1
----------
         1
         2
         3
         4
         5
         5
6 rows selected

----------------------------------------------------------------
| Id  | Operation          | Name   | Starts | E-Rows | A-Rows |
----------------------------------------------------------------
|   0 | SELECT STATEMENT   |        |      1 |        |      6 |
|   1 |  NESTED LOOPS      |        |      1 |      5 |      6 |
|   2 |   TABLE ACCESS FULL| T1     |      1 |  10000 |  10000 |
|*  3 |   INDEX RANGE SCAN | T2_IDX |  10000 |      1 |      6 |
----------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 – access("T1"."N1"="T2"."N1")

-- and now a semi join
SQL> select 
       t1.n1
     from
       t1
     where
      t1.n1 in (select t2.n1 from t2);

        N1
----------
         1
         2
         3
         4
         5

5 rows selected
----------------------------------------------------------------
| Id  | Operation          | Name   | Starts | E-Rows | A-Rows |
----------------------------------------------------------------
|   0 | SELECT STATEMENT   |        |      1 |        |      5 |
|   1 |  NESTED LOOPS SEMI |        |      1 |      5 |      5 |
|   2 |   TABLE ACCESS FULL| T1     |      1 |  10000 |  10000 |
|*  3 |   INDEX RANGE SCAN | T2_IDX |  10000 |      1 |      5 |
----------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - access("T1"."N1"="T2"."N1")

It is for this reason that the semi join has been implemented: do not duplicate rows from the outer table when they multiple join with rows from the inner table.

Since now we know the semi join main goal we can infer that, as long as, Oracle is sure that the right table has no duplicate values in the join column, it will fall back to a simple inner join. Let’s check:

SQL> drop index t2_idx;
SQL> create unique index t2_uq_idx on t2(n1);
SQL> select
       t1.n1
     from
       t1
     where
       exists (select null from t2 where t2.n1 = t1.n1);

        N1
     ------
         1
         2
         3
         4
         5
-------------------------------------------------------------------
| Id  | Operation          | Name      | Starts | E-Rows | A-Rows |
-------------------------------------------------------------------
|   0 | SELECT STATEMENT   |           |      1 |        |      5 |
|   1 |  NESTED LOOPS      |           |      1 |      5 |      5 |
|   2 |   TABLE ACCESS FULL| T1        |      1 |  10000 |  10000 |
|*  3 |   INDEX UNIQUE SCAN| T2_UQ_IDX |  10000 |      1 |      5 |
-------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - access("T2"."N1"="T1"."N1")

Notice that we have no semi join anymore. Thanks to the unique index on t2(n1) table, Oracle knows that there are no duplicate rows in the join column of the outer table. It can then reliably use an inner join because rows from the outer table will at most join exactly once with rows from the inner table.

There exists another way to make Oracle falling to an inner join instead of a semi join even when there are duplicate rows in the join column of the outer table. In fact whenever Oracle uses an operation that eliminates duplicate rows from the outer table (for example sort unique or group by) it can confidently use an inner join in place of a semi join. Here’s below one case demontrated:

SQL> drop index t2_uq_idx;
SQL> insert into t2 values(5,42,42);

SQL> create unique index t1_uq_idx on t1(n1);

SQL> select
       t1.n1
     from
       t1
     where
       exists (select null from t2 where t2.n1 = t1.n1);

        N1
     ------
         1
         2
         3
         4
         5
--------------------------------------------------------------------
| Id  | Operation           | Name      | Starts | E-Rows | A-Rows |
--------------------------------------------------------------------
|   0 | SELECT STATEMENT    |           |      1 |        |      5 |
|   1 |  NESTED LOOPS       |           |      1 |      5 |      5 |
|   2 |   SORT UNIQUE       |           |      1 |      5 |      5 |
|   3 |    TABLE ACCESS FULL| T2        |      1 |      5 |      6 |
|*  4 |   INDEX UNIQUE SCAN | T1_UQ_IDX |      5 |      1 |      5 | -- 5 rows
--------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - access("T2"."N1"="T1"."N1")

As you can see Oracle didn’t use a semi join because it has scanned all rows from the outer table, ordered them and eliminated duplicate rows via the SORT UNIQUE operation. As such when joining with the t1 table Oracle knows that it can join t2 rows at most exactly once. Notice in passing that while the semi join has full scanned the t1 table (10,000 rows) the inner join touched only 5 distinct index keys.

5. SEMI join and foreign key integrity

Suppose now that we want to select rows from a child table matching their parent rows in the parent table.

–- drop and recreate table t1 and t2
SQL> create index t1_idx on t1(n1);
SQL> alter table t1 add constraint t1_uq unique (n1);
SQL> alter table t2 add constraint t2_t1_fk foreign key (n1) references t1(n1);

The setup is now done. But let’s disable first the foreign key, the unique constraint and try a semi join query:

SQL> alter table t1 disable constraint t1_uq;
SQL> alter table t2 disable constraint t2_t1_fk;

SQL> select
        t2.n1
     from
        t2
     where
       exists (select null from t1 where t1.n1 = t2.n1);

-----------------------------------------------------------------------
|   Id  | Operation               | Name   | Starts | E-Rows | A-Rows |
-----------------------------------------------------------------------
|     0 | SELECT STATEMENT        |        |      1 |        |      5 |
|- *  1 |  HASH JOIN SEMI         |        |      1 |      5 |      5 |
|     2 |   NESTED LOOPS SEMI     |        |      1 |      5 |      5 |
|-    3 |    STATISTICS COLLECTOR |        |      1 |        |      5 |
|     4 |     TABLE ACCESS FULL   | T2     |      1 |      5 |      5 |
|  *  5 |    INDEX RANGE SCAN     | T1_IDX |      5 |  10000 |      5 |
|-    6 |   INDEX FAST FULL SCAN  | T1_IDX |      0 |  10000 |      0 |
-----------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("T1"."N1"="T2"."N1")
   5 - access("T1"."N1"="T2"."N1")

Note
-----
   - this is an adaptive plan (rows marked '-' are inactive)

As expected a classical semi join operation.

Let’s now enable the unique key of the parent table t1;

SQL> alter table t1 enable constraint t1_uq;

SQL> select
        t2.n1
     from
        t2
     where
       exists (select null from t1 where t1.n1 = t2.n1);

----------------------------------------------------------------
| Id  | Operation          | Name   | Starts | E-Rows | A-Rows |
----------------------------------------------------------------
|   0 | SELECT STATEMENT   |        |      1 |        |      5 |
|   1 |  NESTED LOOPS      |        |      1 |      5 |      5 |
|   2 |   TABLE ACCESS FULL| T2     |      1 |      5 |      5 |
|*  3 |   INDEX RANGE SCAN | T1_IDX |      5 |      1 |      5 |
----------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - access("T1"."N1"="T2"."N1")

The semi join has gone because Oracle knows that there is a unique constraint on the join column from the outer table t1, it can then safely use an inner join.

Finally let’s enable the foreign key and re-execute the semi join query:

SQL> alter table t2 enable constraint t2_t1_fk;

SQL> select
        t2.n1
     from
        t2
     where
       exists (select null from t1 where t1.n1 = t2.n1);

-------------------------------------------------------------
| Id  | Operation         | Name | Starts | E-Rows | A-Rows |
-------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |      1 |        |      5 |
|*  1 |  TABLE ACCESS FULL| T2   |      1 |      5 |      5 |
-------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("T2"."N1" IS NOT NULL)

Oracle can use a trusted foreign key relationship to remove a logical semi-join and accesses only the t2 table.

5. SEMI join and INTERSECT

In SQL Server an intersect set operation can also be done via a semi-join as the following proves:

create table t1(n1 int, n2 int,n3 int) ;
create table t2(n1 int, n2 int, n3 int) ;

insert into t1(n1,n2,n3)
select top 10000
  row_number() over (order by a.name)
 ,row_number() over (order by a.name)%5
 ,(row_number() over (order by a.name) -1) /3
from sys.all_objects a cross join sys.all_objects;

insert into t2(n1,n2,n3)
select top 5
  row_number() over (order by a.name )
 ,row_number() over (order by a.name)%3
 ,(row_number() over (order by a.name)-1)/5
from sys.all_objects a cross join sys.all_objects;

select t2.n1 from t2 intersect select t1.n1 from t1;


But neither Oracle nor PostgreSQL use a semi join when evaluating an intersect set operation as the followings prove respectively:

–- Oracle 12cR2
SQL> select t2.n1 from t2 intersect select t1.n1 from t1;

---------------------------------------------------------------
| Id  | Operation           | Name | Starts | E-Rows | A-Rows |
---------------------------------------------------------------
|   0 | SELECT STATEMENT    |      |      1 |        |      5 |
|   1 |  INTERSECTION       |      |      1 |        |      5 |
|   2 |   SORT UNIQUE       |      |      1 |      6 |      6 |
|   3 |    TABLE ACCESS FULL| T2   |      1 |      6 |      6 |
|   4 |   SORT UNIQUE       |      |      1 |  10000 |  10000 |
|   5 |    TABLE ACCESS FULL| T1   |      1 |  10000 |  10000 |
---------------------------------------------------------------
-- PostgreSQL 10.1
create table t1 as
  select 
     generate_series(1, 1e4) n1
	,generate_series(1, 1e4)%5 n2
	,(generate_series(1, 1e4)-1)/3 n3;
	
create table t2 as
  select 
     generate_series(1, 5) n1
	,generate_series(1, 5)%3 n2
	,(generate_series(1, 5)-1)/5 n3;
	
select t2.n1 from t2 intersect select t1.n1 from t1;


postgres=# explain analyze select t2.n1 from t2 intersect select t1.n1 from t1;
                                                           QUERY PLAN
------------------------------------------------------------------------------------------------------------------------
 HashSetOp Intersect  (cost=0.00..347.00 rows=200 width=36) (actual time=13.186..13.189 rows=5 loops=1)
   ->  Append  (cost=0.00..316.90 rows=12040 width=36) (actual time=0.363..9.571 rows=10005 loops=1)
         ->  Subquery Scan on "*SELECT* 1"  (cost=0.00..55.90 rows=2040 width=36) (actual time=0.362..0.369 rows=5 loops=1)
               ->  Seq Scan on t2  (cost=0.00..30.40 rows=2040 width=4) (actual time=0.050..0.053 rows=5 loops=1)
         ->  Subquery Scan on "*SELECT* 2"  (cost=0.00..261.00 rows=10000 width=9) (actual time=0.031..7.743 rows=10000 loops=1)
               ->  Seq Scan on t1  (cost=0.00..161.00 rows=10000 width=5) (actual time=0.029..4.478 rows=10000 loops=1)
 Planning time: 0.555 ms
 Execution time: 13.911 ms

6. SUMMARY

We have seen in this article how a semi join logical operation is triggered when using IN, ANY, SOME, EXISTS and DISTINCT in several modern relational databases. We’ve outlined as well that, in contrast to Oracle and PostgreSQL, SQL-Server can use a semi join during an INTERSECT set operation. We’ve demonstrated that while a regular joins can duplicate rows, semi joins do not produce any duplicates. They are defined to return (or not) rows only from one table of the join. We’ve also shown that, as long as the CBO is sure that the right table has no duplicate values in the join column, it will fall back to a simple inner join where extra transformations become possible and where the left table might not be fully scanned.

March 1, 2018

Diagnosing the past : CPU bound

Filed under: Oracle — hourim @ 6:24 pm

Few weeks ago I have been confronted to a weird real life system performance issue which, I believe is worth a sharing blog post. It started by a customer complaint about a dramatic slow in inserts of commands and products so that the application in its entirety appeared frozen. A very quick look-up over ASH shows no particular wait events or any new TOP SQL that I am not aware of. I know this application to such an extent that I can recognize its top queries via their sql_id. This is why my first impression was that there is no particular unusual wait event to point out except a high CPU consumption.

But the Load Profile of the corresponding one hour AWR report looks very odd:

Load Profile                    Per Second   Per Transaction  Per Exec  Per Call
~~~~~~~~~~~~~~~            ---------------   --------------- --------- ---------
             DB Time(s):              95.2               4.7      0.02     0.02
              DB CPU(s):               7.7               0.1      0.00     0.00
      Background CPU(s):               0.2               0.0      0.00     0.00
      Redo size (bytes):         439,216.3          18,666.4
  Logical read (blocks):       1,774,174.9          75,401,1
          Block changes:           2,465.0             104.8
 Physical read (blocks):           3,609.2             153.4
Physical write (blocks):             135.2               5.8
       Read IO requests:           2,436.8             103.6
      Write IO requests:              53.6               2.3
           Read IO (MB):              28.2               1.2
          Write IO (MB):               1.1               0.0
           IM scan rows:               0.0               0.0
Session Logical Read IM:               
             User calls:           5,423.4             230.5
           Parses (SQL):             244.4              10.4
      Hard parses (SQL):               0.5               0.0
     SQL Work Area (MB):              28.3               1.2
                 Logons:               0.7               0.0
         Executes (SQL):           4,470.6             190.0
              Rollbacks:               0.2               0.0
           Transactions:              23.5

Have you ever seen such a dramatic Load Profile? The foreground sessions spend collectively 95 seconds of time for each wall clock second. All those sessions were either actively working or waiting. They burned 7.7 of CPU per wall clock second. For a machine of 24 cores this seems to be a CPU constrained application. The overall workload is generating 1,77 million of logical blocks read per second which represent a rate of approximatively 6GB of logical blocks read per hour. And only a tiny percentage of those block reads are changed (2,465/1,774,174 = 0,13%).

I was really intrigued by this abnormal situation since I didn’t spot any unusual wait event or SQL query. While I was drilling down the different sections of the AWR report, cross-checking properly the performance key indicators they deliver, something in the TOP 10 Foreground Events captured my attention:

Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                           Total Wait      Avg   % DB    Wait
Event                                Waits Time (sec)    Wait(ms)  time Class
------------------------------ ----------- ---------- --------- ------ --------
db file sequential read          2,813,888        32K     11.37    9.3 User I/O
DB CPU                                          27,9K              8.1
db file parallel read              278,494      10,8K     38.67    3.1 User I/O
read by other session              444,473       4785     10.77    1.4 User I/O
direct path read                   311,471     4718,6     15.15    1.4 User I/O
gc cr block 2-way                  577,081     2366,4      4.10     .7 Cluster
log file sync                       89,040     2254,7     25.32     .7 Commit
db file scattered read              138,798    2136,8     15.40     .6 User I/O
gc current block 2-way              368,907    1994,1      5.41     .6 Cluster
gc buffer busy acquire              329,900    1776,8      5.39     .5 Cluster
  • The % DB time column doesn’t sum up to 100% (or near this number) totalling only 26,4%
  • The disk is very slow servicing the physical I/O and background events with a dramatic average time wait.

When the %DB time column doesn’t add up to nearly 100% it generally indicates a symptom of a CPU bounded application. Indeed this is confirmed a little bit upward in the same AWR report via the HOST CPU section:

Host CPU
~~~~~~~~                  Load Average
 CPUs Cores Sockets     Begin       End     %User   %System  %WIO  %Idle
----- ----- ------- --------- --------- --------- --------- ------ -----
   48    24       4     55.57   219.13       92.0       2.3    2.3   5.0

The application was already over CPU bounded at the beginning (55) and completely frozen at the end of the load (219 CPU). For a machine with 24 cores, the DB CPU load is indeed very high

 DB CPU Load = DB CPU time/Elapsed Time
            = 27900/3600 = 7.7

And so is the DB time load


              Snap Id      Snap Time      Sessions Curs/Sess  Instance
            --------- ------------------- -------- --------- ---------
Begin Snap:     28812 06-Feb-18 13:00:01       365      12.5         2
  End Snap:     28813 06-Feb-18 14:00:15       421      12.5         2
   Elapsed:               60.23 (mins)
   DB Time:            5,734.18 (mins)

DB time Load = DB time/Elapsed Time
              = 5734.1/60.23 = 95.2

So what else?

I asked the storage team to check the performance of the underlying disk. The confirmation of the dramatic disk latency has been obviously confirmed by the storage team. But the fundamental and legitimate question is what has changed per regards to the yesterday normal functioning of the application that might explain this performance deterioration?

While I was trying to figure out a solution I asked a help from a DBA who is the primary owner of another critical application. To my surprise this DBA told me that one of his applications is also suffering from similar performance deterioration and that this application is hosted by the same server as the one hosting the application I am trying to troubleshoot. What a coincidence.

A couple of minutes later we found that a critical batch has been triggered in the other DBA application. This batch was extensively executing a parallel query using a very high degree of parallelism (DOP) which was consuming the whole SAN bandwidth. Needless to say that when this batch job has been stopped the initial problem I was trying to fix vanishes by itself and the database returned to its normal functioning

Bottom Line

When you are troubleshooting an application which seems to be completely frozen and where the disk is very badly servicing the database and where the DB time % column of the AWR Top 10 foreground Events section is not summing up to 100% then you are probably CPU bounded. In such case, don’t forget to consider, among the panoply of your check list, whether others applications hosted in the same server are not stressing the disk with very aggressive parallel queries.

Create a free website or blog at WordPress.com.

Tony's Oracle Tips

Tony Hasler's light hearted approach to learning about Oracle

Richard Foote's Oracle Blog

Focusing Specifically On Oracle Indexes, Database Administration and Some Great Music

Hatem Mahmoud's blog

Just another blog : Databases, Linux and other stuffs

Mohamed Houri’s Oracle Notes

Qui se conçoit bien s’énonce clairement

Oracle Diagnostician

Performance troubleshooting as exact science

Raheel's Blog

Things I have learnt as Oracle DBA

Coskan's Approach to Oracle

What I learned about Oracle

So Many Oracle Manuals, So Little Time

“Books to the ceiling, Books to the sky, My pile of books is a mile high. How I love them! How I need them! I'll have a long beard by the time I read them”—Lobel, Arnold. Whiskers and Rhymes. William Morrow & Co, 1988.

Carlos Sierra's Tools and Tips

Tools and Tips for Oracle Performance and SQL Tuning

Oracle Scratchpad

Just another Oracle weblog

OraStory

Dominic Brooks on Oracle Performance, Tuning, Data Quality & Sensible Design ... (Now with added Sets Appeal)