Adventures with VPD I: Result Cache

Oh, the challenges of implementing VPD on a mature system!

Like partitioning and other major features, implementing VPD on a “mature”* database that has been “evolving”* over many years can be nowhere near as simple as designing such a solution from scratch. (* “Mature” databases have not necessarily “evolved” in a way that you might recommend. Best practice might not apply.)

Anyway, I’ve been intending to write a case study of my current VPD implementation, dealing with some detail of the buy versus build decision of VPD versus OLS and the subsequent challenges and incompatibilities with various features. As usual, that article awaits but I wanted to kick off a mini-series on the various difficulties experienced (and this series might then help the coming together of a single article on the whole experience).

Challenge I
The challenge illustrated here is VPD + Result Cache.

Spoiler: For those who don’t want to read the whole article (it’s a bit long and the formatting which doesn’t help), the two work together but beware the subtle differences in behaviour between the SQL and PL/SQL Result Cache – read the documentation for each.

Quick Background
First a bit of background information which may help put these snippets of info into some sort of context.

  • As mentioned, this is a database that has been around for quite a few years now.
  • There has been a simple requirement to restrict access such that:
    • Users in the US can only see US data.
    • Users in the Rest of the World (ROW) cannot see US data.
  • VPD, OLS and a separate database were the options considered with VPD considered the only practical solution for one reason or another.

Demo
Let’s get into it.

Step 1: First up, script to create users for this demo:

  1. User to own table – APP_DATA
  2. User to own manage VPD security – SECURITY_MGR
  3. User to simulate app user with US visibility
  4. User to simulate app user with ROW visibility
-- Schema to hold some data
CREATE USER APP_DATA
IDENTIFIED BY password
DEFAULT TABLESPACE USERS
TEMPORARY TABLESPACE TEMP
QUOTA UNLIMITED ON USERS
ACCOUNT UNLOCK;

GRANT CREATE SESSION TO app_data;
GRANT CREATE TABLE TO app_data;
GRANT CREATE PROCEDURE TO app_data; 

-- Schema to manage security policies
CREATE USER SECURITY_MGR
IDENTIFIED BY password
DEFAULT TABLESPACE USERS
TEMPORARY TABLESPACE TEMP
QUOTA UNLIMITED ON USERS
ACCOUNT UNLOCK;

GRANT EXEMPT ACCESS POLICY TO security_mgr;
GRANT CREATE SESSION TO security_mgr;
GRANT CREATE TABLE TO security_mgr;
GRANT CREATE ANY CONTEXT TO security_mgr;
GRANT CREATE TRIGGER TO security_mgr;
GRANT ADMINISTER DATABASE TRIGGER TO security_mgr;
GRANT SELECT ANY TABLE TO security_mgr;
GRANT ALTER ANY TABLE TO security_mgr;
GRANT UPDATE ANY TABLE TO security_mgr;
GRANT EXECUTE ON DBMS_RLS TO security_mgr;
GRANT CREATE ANY TRIGGER TO security_mgr;
GRANT ADMINISTER DATABASE TRIGGER TO security_mgr;

-- User to see only US data
CREATE USER APP_USER_US
IDENTIFIED BY password
DEFAULT TABLESPACE USERS
TEMPORARY TABLESPACE TEMP
QUOTA UNLIMITED ON USERS
ACCOUNT UNLOCK;

GRANT CREATE SESSION TO app_user_us;

-- User to see only non-US data
CREATE USER APP_USER_ROW
IDENTIFIED BY password
DEFAULT TABLESPACE USERS
TEMPORARY TABLESPACE TEMP
QUOTA UNLIMITED ON USERS
ACCOUNT UNLOCK;

GRANT CREATE SESSION TO app_user_row;

Step 2: Next up, script to create table and data for this demo. It’s hardly imaginative nor a real world example…

conn app_data/password@dom11g

DROP TABLE cars;

CREATE TABLE cars
(id              NUMBER       NOT NULL
,make            VARCHAR2(48) NOT NULL
,security_label  VARCHAR2(6)  NOT NULL
,CONSTRAINT pk_cars PRIMARY KEY (id));

INSERT INTO app_data.cars
VALUES (1,'Audi','ROW');

INSERT INTO app_data.cars
VALUES (2,'Buick','US');

INSERT INTO app_data.cars
VALUES (3,'BMW','ROW');

INSERT INTO app_data.cars
VALUES (4,'Chrysler','US');

INSERT INTO app_data.cars
VALUES (5,'Citroen','US');

INSERT INTO app_data.cars
VALUES (6,'Dodge','US');

COMMIT;

GRANT SELECT ON cars TO app_user_us, app_user_row;

Step 3: Create vpd policies including

  • Create application context
  • Create package to manage context
  • Create logon trigger to set contexts
  • Create policy function that will apply predicates to policied tables
  • Apply policy to table
conn security_mgr/password@dom11g

CREATE CONTEXT security_ctx USING security_pkg;

CREATE OR REPLACE PACKAGE security_pkg
AS
  --
  PROCEDURE p_initialise_user;
  --
END security_pkg;
/

CREATE OR REPLACE PACKAGE BODY security_pkg
AS
  k_namespace CONSTANT VARCHAR2(12) := 'SECURITY_CTX';
  --
  PROCEDURE p_set_context (
    i_attribute  IN     VARCHAR2,
    i_value      IN     VARCHAR2
  )
  AS
  BEGIN
     --
     dbms_session.set_context(k_namespace,i_attribute,i_value);
     --
  END p_set_context;
  --
  PROCEDURE p_set_us_context
  AS
  BEGIN
     --
     p_set_context('CAN_SEE_US','Y');
     --
  END p_set_us_context;
  --
  PROCEDURE p_set_row_context
  AS
  BEGIN
     --
     p_set_context('CAN_SEE_ROW','Y');
     --
  END p_set_row_context;
  --
  PROCEDURE p_initialise_user
  AS
  BEGIN
     --
     IF USER = 'APP_USER_US'
     THEN
         --
         p_set_us_context;
         --
     ELSIF USER = 'APP_USER_ROW'
     THEN
         --
         p_set_row_context;
         --
     ELSE
         --
         p_set_us_context;
         p_set_row_context;
         --
     END IF;
     --
  END p_initialise_user;
  --
END security_pkg;
/

CREATE OR REPLACE TRIGGER tri_logon_set_rls_security
AFTER LOGON ON DATABASE
BEGIN
   --
   security_pkg.p_initialise_user;
   --
END tri_logon_set_rls_security;
/

CREATE OR REPLACE FUNCTION f_security_policy (
  i_schema                     IN     VARCHAR2 DEFAULT NULL,
  i_object                     IN     VARCHAR2 DEFAULT NULL
)
RETURN VARCHAR2
AS
BEGIN
   --
   RETURN CASE WHEN SYS_CONTEXT('SECURITY_CTX','CAN_SEE_US')  = 'Y'
               AND  SYS_CONTEXT('SECURITY_CTX','CAN_SEE_ROW') = 'Y'
               THEN NULL
               WHEN SYS_CONTEXT('SECURITY_CTX','CAN_SEE_US')  = 'Y'
               THEN ' security_label  = ''US'' '
               WHEN SYS_CONTEXT('SECURITY_CTX','CAN_SEE_ROW') = 'Y'
               THEN ' security_label = ''ROW'' '
          END;
   --
END f_security_policy;
/

begin
  dbms_rls.add_policy
  (object_schema   => 'APP_DATA',
   object_name     => 'CARS',
   policy_name     => 'RLS_CARS',
   function_schema => 'SECURITY_MGR',
   policy_function => 'F_SECURITY_POLICY',
   policy_type     => SYS.DBMS_RLS.SHARED_CONTEXT_SENSITIVE,
   statement_types => 'SELECT');
end;
/

Step 4: Test the VPD policies.
Step 4a: Connecting as APP_USER_US, we should only be able to see data from APP_DATA.CARS which is labelled as US:

conn app_user_us/password@dom11g

app_user_us@dom11g>select * from app_data.cars;

 ID MAKE       SECUR
--- ---------- -----
  2 Buick      US
  4 Chrysler   US
  5 Citroen    US
  6 Dodge      US

Elapsed: 00:00:00.01

Step 4b: Connecting as APP_USER_ROW, we should only be able to see data from APP_DATA.CARS which is labelled as ROW:

conn app_user_row/password@dom11g

app_user_row@dom11g>select * from app_data.cars;

app_user_row@dom11g>select * from app_data.cars;

 ID MAKE       SECUR
--- ---------- -----
  1 Audi       ROW
  3 BMW        ROW

Elapsed: 00:00:00.00
app_user_row@dom11g>

Good stuff. Spotted the mistake? Last time I checked, Citroen was French – should be labelled ROW. I’ll leave it in and update it after we’ve done some result cache queries just to show that that all works.

Step 5: Let’s take a look at the SQL result cache using the result_cache hint.
Step 5a: We’ll go with APP_USER_US first.

conn app_user_us/password@dom11g

app_user_us@dom11g>set autotrace on
app_user_us@dom11g>select /*+ result_cache */ * from app_data.cars;

 ID MAKE       SECUR
--- ---------- -----
  2 Buick      US
  4 Chrysler   US
  5 Citroen    US
  6 Dodge      US

Elapsed: 00:00:00.02

Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=ALL_ROWS (Cost=5 Card=4 Bytes=176)
   1    0   RESULT CACHE OF '25tyax8u9ktwf2g61acmsb5apa'
   2    1     TABLE ACCESS (FULL) OF 'CARS' (TABLE) (Cost=5 Card=4 Bytes=176)

Statistics
----------------------------------------------------------
        121  recursive calls
          0  db block gets
         58  consistent gets
          0  physical reads
          0  redo size
        508  bytes sent via SQL*Net to client
        427  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
          4  rows processed

app_user_us@dom11g>select /*+ result_cache */ * from app_data.cars;

 ID MAKE       SECUR
--- ---------- -----
  2 Buick      US
  4 Chrysler   US
  5 Citroen    US
  6 Dodge      US

Elapsed: 00:00:00.02

Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=ALL_ROWS (Cost=5 Card=4 Bytes=176)
   1    0   RESULT CACHE OF '25tyax8u9ktwf2g61acmsb5apa'
   2    1     TABLE ACCESS (FULL) OF 'CARS' (TABLE) (Cost=5 Card=4 Bytes=176)

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
          0  consistent gets
          0  physical reads
          0  redo size
        508  bytes sent via SQL*Net to client
        427  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          4  rows processed

I’m happy enough that it’s coming from the cache the second time.

Step 5a: How about APP_USER_US?

conn app_user_row/password@dom11g

app_user_row@dom11g>set autotrace on
app_user_row@dom11g>select /*+ result_cache */ * from app_data.cars;

 ID MAKE       SECUR
--- ---------- -----
  1 Audi       ROW
  3 BMW        ROW

Elapsed: 00:00:00.02

Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=ALL_ROWS (Cost=5 Card=2 Bytes=88)
   1    0   RESULT CACHE OF 'g0ubwn87rvz5s15cj3089zgn3h'
   2    1     TABLE ACCESS (FULL) OF 'CARS' (TABLE) (Cost=5 Card=2 Bytes=88)

Statistics
----------------------------------------------------------
         89  recursive calls
          0  db block gets
         57  consistent gets
          0  physical reads
          0  redo size
        473  bytes sent via SQL*Net to client
        427  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          2  rows processed

app_user_row@dom11g>select /*+ result_cache */ * from app_data.cars;

 ID MAKE       SECUR
--- ---------- -----
  1 Audi       ROW
  3 BMW        ROW

Elapsed: 00:00:00.02

Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=ALL_ROWS (Cost=5 Card=2 Bytes=88)
   1    0   RESULT CACHE OF 'g0ubwn87rvz5s15cj3089zgn3h'
   2    1     TABLE ACCESS (FULL) OF 'CARS' (TABLE) (Cost=5 Card=2 Bytes=88)

Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
          0  consistent gets
          0  physical reads
          0  redo size
        473  bytes sent via SQL*Net to client
        427  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          2  rows processed

Step 6: Let’s update that Citroen row – double check what happens.

conn app_data/password@dom11g

app_data@dom11g>update cars set security_label = 'ROW' where id = 5;

1 row updated.

Elapsed: 00:00:00.00
app_data@dom11g>commit;

Commit complete.

Step 7: Back to the visibility users
Step 7a: APP_USER_US

app_user_us@dom11g>select /*+ result_cache */ * from app_data.cars;

 ID MAKE       SECUR
--- ---------- -----
  2 Buick      US
  4 Chrysler   US
  6 Dodge      US

Elapsed: 00:00:00.00
app_user_us@dom11g>

Step 7b: APP_USER_ROW

app_user_row@dom11g>select /*+ result_cache */ * from app_data.cars;

 ID MAKE       SECUR
--- ---------- -----
  1 Audi       ROW
  3 BMW        ROW
  5 Citroen    ROW

Elapsed: 00:00:00.00
app_user_row@dom11g>

Looking more accurate now.

SQL Query Result Cache
So, the SQL Result Cache apparently works fine with VPD.
Let’s review what the documentation says:


Cached results are parameterized with the parameter values if any of the following constructs are used in the query:

Bind variables.

The following SQL functions: dbtimezone, sessiontimezone, userenv/sys_context (with constant variables), uid, and user.

NLS parameters.

Parameterized cache results can be reused if the query is equivalent and the parameter values are the same.

So what of the PL/SQL Function Result Cache?

Step 8: Create a result cache function to demonstrate (this is an artificial and simplified function – it demos what I want to demo, it’s derived from a real-world implementation but I would advocate using the result cache for this purpose)

conn app_data/password@dom11g

CREATE OR REPLACE PACKAGE cars_pkg
AS
--
FUNCTION f_get_make (
i_id IN cars.id%TYPE
)
RETURN cars.make%TYPE;
--
END cars_pkg;
/

CREATE OR REPLACE PACKAGE BODY cars_pkg
AS
--
TYPE t_cars IS TABLE of cars%ROWTYPE INDEX BY PLS_INTEGER;
--
FUNCTION f_get_cars
RETURN t_cars
RESULT_CACHE
RELIES_ON (cars)
AS
--
l_cars t_cars;
l_tmp_cars t_cars;
i PLS_INTEGER;
--
BEGIN
--
SELECT *
BULK COLLECT INTO l_tmp_cars
FROM cars;
--
i := l_tmp_cars.FIRST;
--
WHILE (i IS NOT NULL)
LOOP
--
l_cars(l_tmp_cars(i).id).id := l_tmp_cars(i).id;
l_cars(l_tmp_cars(i).id).make := l_tmp_cars(i).make;
l_cars(l_tmp_cars(i).id).security_label := l_tmp_cars(i).security_label;
--
i := l_tmp_cars.NEXT(i);
--
END LOOP;

--
RETURN l_cars;
--
END f_get_cars;
--
FUNCTION f_get_make (
i_id IN cars.id%TYPE
)
RETURN cars.make%TYPE
AS
--
l_cars t_cars;
--
BEGIN
--
l_cars := f_get_cars;
RETURN l_cars(i_id).make;
--
EXCEPTION
WHEN no_data_found THEN
RETURN NULL;
END f_get_make;
--
END cars_pkg;
/

GRANT EXECUTE ON cars_pkg TO app_user_us, app_user_row;

Step 9: Let’s try it using this.
Step 9a: As APP_USER_US initially

app_user_us@dom11g>var v varchar2(48)
app_user_us@dom11g>set autoprint on
app_user_us@dom11g>select * from app_data.cars;

 ID MAKE       SECUR
--- ---------- -----
  2 Buick      US
  4 Chrysler   US
  6 Dodge      US

Elapsed: 00:00:00.01
app_user_us@dom11g>exec :v := app_data.cars_pkg.f_get_make(1);

PL/SQL procedure successfully completed.

V
---------------

Elapsed: 00:00:00.01
app_user_us@dom11g>exec :v := app_data.cars_pkg.f_get_make(2);

PL/SQL procedure successfully completed.

V
---------------
Buick

Elapsed: 00:00:00.01

As expected, APP_USER_US cannot see the Audi data, can see Buick. Perfect!
Step 9b: Let’s try APP_USER_ROW.

conn app_user_row/password@dom11g

app_user_row@dom11g>var v varchar2(48)
app_user_row@dom11g>set autoprint on
app_user_row@dom11g>select * from app_data.cars;

  ID MAKE       SECUR
---- ---------- -----
   1 Audi       ROW
   3 BMW        ROW
   5 Citroen    ROW

Elapsed: 00:00:00.00
app_user_row@dom11g>exec :v := app_data.cars_pkg.f_get_make(1);

PL/SQL procedure successfully completed.

V
----------

Elapsed: 00:00:00.01
app_user_row@dom11g>exec :v := app_data.cars_pkg.f_get_make(2);

PL/SQL procedure successfully completed.

V
----------
Buick

Elapsed: 00:00:00.01
app_user_row@dom11g>

Wrong! And just what I wanted to demo. By implementing a result function like this, I have bypassed my VPD and rendered results from this function unpredictable depending on who ran the results which were cached.

So, with the PL/SQL function RESULT_CACHE directive you have to be careful, not necessarily anymore so than certain other features but just something to be aware of.

Before I knew the solution, but after I had these results, what happened when I combined VPD with such a Result Cache mis-implementation was not a massive surprise, but I had expected that either an error message would be raised, similiar to Materialized Views or the MERGE statement (forward references to future articles on the challenges of combining VPD with those two), or perhaps that the RESULT_CACHE directive would be ignored.

However the behaviour is documented and the answer is very much documented in the PL/SQL Language Reference:

Making Result-Cached Functions Handle Session-Specific Settings

The PL/SQL function result-caching feature does not automatically handle dependence on session-specific application contexts. If you must cache the results of a function that depends on session-specific application contexts, you must pass the application context to the function as a parameter. You can give the parameter a default value, so that not every user must specify it.

The same advice applies to other session specific settings, e.g. NLS_DATE_FORMAT etc.

Step 10: Make safe the result_cache implementation of APP_DATA.CARS_PKG.

conn app_data/password@dom11g

CREATE OR REPLACE PACKAGE APP_DATA.cars_pkg
AS
  --
  FUNCTION f_get_make_safe (
    i_id          IN  cars.id%TYPE,
    i_can_see_us  IN  VARCHAR2 DEFAULT SYS_CONTEXT('SECURITY_CTX','CAN_SEE_US'),
    i_can_see_row IN  VARCHAR2 DEFAULT SYS_CONTEXT('SECURITY_CTX','CAN_SEE_ROW')
  )
  RETURN cars.make%TYPE;
  --
END cars_pkg;
/

CREATE OR REPLACE PACKAGE BODY APP_DATA.cars_pkg
AS
  --
  TYPE t_cars IS TABLE of cars%ROWTYPE INDEX BY PLS_INTEGER;
  --
  FUNCTION f_get_cars_safe (
    i_can_see_us  IN  VARCHAR2 DEFAULT SYS_CONTEXT('SECURITY_CTX','CAN_SEE_US'),
    i_can_see_row IN  VARCHAR2 DEFAULT SYS_CONTEXT('SECURITY_CTX','CAN_SEE_ROW')
  )
  RETURN t_cars
  RESULT_CACHE
  RELIES_ON (cars)
  AS
    --
    l_cars     t_cars;
    l_tmp_cars t_cars;
    i          PLS_INTEGER;
    --
  BEGIN
     --
     SELECT *
     BULK COLLECT INTO l_tmp_cars
     FROM   cars;
     --
     i := l_tmp_cars.FIRST;
     --
     WHILE (i IS NOT NULL)
     LOOP
         --
         l_cars(l_tmp_cars(i).id).id             := l_tmp_cars(i).id;
         l_cars(l_tmp_cars(i).id).make           := l_tmp_cars(i).make;
         l_cars(l_tmp_cars(i).id).security_label := l_tmp_cars(i).security_label;
         --
         i := l_tmp_cars.NEXT(i);
         --
     END LOOP;

     --
     RETURN l_cars;
     --
  END f_get_cars_safe;
  --
  FUNCTION f_get_make_safe (
    i_id          IN  cars.id%TYPE,
    i_can_see_us  IN  VARCHAR2 DEFAULT SYS_CONTEXT('SECURITY_CTX','CAN_SEE_US'),
    i_can_see_row IN  VARCHAR2 DEFAULT SYS_CONTEXT('SECURITY_CTX','CAN_SEE_ROW')
  )
  RETURN cars.make%TYPE
  AS
    --
    l_cars t_cars;
    --
  BEGIN
     --
     l_cars := f_get_cars_safe;
     RETURN l_cars(i_id).make;
     --
  EXCEPTION
       WHEN no_data_found THEN
            RETURN NULL;
  END f_get_make_safe;
  --
END cars_pkg;
/

Step 11: With this our previous function lookup should work as expected:
Step 11a: As APP_USER_US

conn app_user_us/password@dom11g

app_user_us@dom11g>var v varchar2(48)
app_user_us@dom11g>set autoprint on
app_user_us@dom11g>select * from app_data.cars;

  ID MAKE       SECUR
---- ---------- -----
   2 Buick      US
   4 Chrysler   US
   6 Dodge      US

Elapsed: 00:00:00.01
app_user_us@dom11g>exec :v := app_data.cars_pkg.f_get_make_safe(1);

PL/SQL procedure successfully completed.

V
----------

Elapsed: 00:00:00.01
app_user_us@dom11g>exec :v := app_data.cars_pkg.f_get_make_safe(2);

PL/SQL procedure successfully completed.

V
----------
Buick

Elapsed: 00:00:00.01

Step 11a: As APP_USER_ROW

conn app_user_row/password@dom11g

app_user_row@dom11g>var v varchar2(48)
app_user_row@dom11g>set autoprint on
app_user_row@dom11g>select * from app_data.cars;

  ID MAKE       SECUR
---- ---------- -----
   1 Audi       ROW
   3 BMW        ROW
   5 Citroen    ROW

Elapsed: 00:00:00.01
app_user_row@dom11g>exec :v := app_data.cars_pkg.f_get_make_safe(1);

PL/SQL procedure successfully completed.

V
----------
Audi

Elapsed: 00:00:00.01
app_user_row@dom11g>exec :v := app_data.cars_pkg.f_get_make_safe(2);

PL/SQL procedure successfully completed.

V
----------

Elapsed: 00:00:00.01
app_user_row@dom11g>

Problem fixed.

Moral
The moral of the story is simple in this case – RTFM.
This time everything I needed was there in the docs. I hadn’t picked up on it fully when I implemented the result cache procs when VPD wasn’t in the picture and I didn’t review the information up front when looking at the VPD solution.
Caveat Developer.

Documentation

Result_cache blocking II

Following on from my post yesterday, it belatedly occurred to me that I should have included some more information. Rather than add an addendum to the original where it might be missed by anyone interested that had already read it, I’m going kick off another post.

By the time, I got involved the problem had been ongoing for 25 minutes. All-in-all, the “incident” lasted 40 minutes. To get an accurate report, we need a snap that spans the problem, i.e. start snap is before problem started, end snap is post incident resolution. So, what follows are selected highlights from from a two hour AWR report.

Note the RC enqueues.

Apologies for the formatting – can’t see to find a combination which works well.

WORKLOAD REPOSITORY report for

DB Name         DB Id    Instance     Inst Num Startup Time    Release     RAC
------------ ----------- ------------ -------- --------------- ----------- ---
XXXX          3639132207 XXXX                1 29-Aug-08 18:50 11.1.0.6.0  NO

Host Name        Platform                         CPUs Cores Sockets Memory(GB)
---------------- -------------------------------- ---- ----- ------- ----------
xxxxxxxxxxxxxxxx Linux 64-bit for AMD               16    16       4      31.43

              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:      4824 12-Nov-08 11:00:50       411       7.9
  End Snap:      4827 12-Nov-08 13:00:59       355       7.5
   Elapsed:              120.15 (mins)
   DB Time:            5,716.93 (mins)

Cache Sizes                       Begin        End
~~~~~~~~~~~                  ---------- ----------
               Buffer Cache:     1,536M     1,920M  Std Block Size:         8K
           Shared Pool Size:     3,648M     3,264M      Log Buffer:     7,252K

Load Profile              Per Second    Per Transaction   Per Exec   Per Call
~~~~~~~~~~~~         ---------------    --------------- ---------- ----------
      DB Time(s):               47.6                5.2       0.01       0.34
       DB CPU(s):                1.2                0.1       0.00       0.01
       Redo size:          249,580.9           27,444.3
   Logical reads:           70,998.1            7,807.0
   Block changes:            1,765.9              194.2
  Physical reads:              643.1               70.7
 Physical writes:               79.0                8.7
      User calls:              140.9               15.5
          Parses:              278.0               30.6
     Hard parses:                1.3                0.1
W/A MB processed:       11,776,252.5        1,294,933.1
          Logons:                0.7                0.1
        Executes:            3,681.1              404.8
       Rollbacks:                0.2                0.0
    Transactions:                9.1

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:  100.00       Redo NoWait %:  100.00
            Buffer  Hit   %:   99.56    In-memory Sort %:  100.00
            Library Hit   %:   99.91        Soft Parse %:   99.55
         Execute to Parse %:   92.45         Latch Hit %:   99.98
Parse CPU to Parse Elapsd %:    0.00     % Non-Parse CPU:   98.46

 Shared Pool Statistics        Begin    End
                              ------  ------
             Memory Usage %:   56.10   52.34
    % SQL with executions>1:   87.04   91.24
  % Memory for SQL w/exec>1:   76.08   82.45

Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
latch free                          128,725     541,831   4209  158.0 Other
DB CPU                                            8,875           2.6
db file sequential read           1,497,779       2,158      1     .6 User I/O
SQL*Net message from dblink          24,546       1,263     51     .4 Network
enq: RC - Result Cache: Conten        4,056         854    210     .2 Applicatio
Host CPU (CPUs:   16 Cores:   16 Sockets:    4)
~~~~~~~~         Load Average
               Begin       End     %User   %System      %WIO     %Idle
           --------- --------- --------- --------- --------- ---------
                4.95      3.93       7.9       1.1       2.4      90.8

Instance CPU
~~~~~~~~~~~~
              % of total CPU for Instance:   8.4
              % of busy  CPU for Instance:  92.1
  %DB time waiting for CPU - Resource Mgr:   0.0

Memory Statistics
~~~~~~~~~~~~~~~~~                       Begin          End
                  Host Mem (MB):     32,187.8     32,187.8
                   SGA use (MB):      6,144.0      6,144.0
                   PGA use (MB):     11,531.6     11,354.8
    % Host Mem used for SGA+PGA:        54.91        54.91

Time Model Statistics                    DB/Inst: XXXX/XXXX  Snaps: 4824-4827
-> Total time in database user-calls (DB Time): 343015.7s
-> Statistics including the word "background" measure background process
   time, and so do not contribute to the DB time statistic
-> Ordered by % or DB time desc, Statistic name

Statistic Name                                       Time (s) % of DB Time
------------------------------------------ ------------------ ------------
sql execute elapsed time                            341,838.1         99.7
PL/SQL execution elapsed time                       314,071.3         91.6
DB CPU                                                8,875.0          2.6
RMAN cpu time (backup/restore)                          498.2           .1
parse time elapsed                                      280.7           .1
hard parse elapsed time                                 153.5           .0
connection management call elapsed time                 130.5           .0
repeated bind elapsed time                               30.3           .0
PL/SQL compilation elapsed time                          24.0           .0
Java execution elapsed time                              22.1           .0
hard parse (sharing criteria) elapsed time               21.4           .0
hard parse (bind mismatch) elapsed time                   7.5           .0
sequence load elapsed time                                6.9           .0
failed parse elapsed time                                 0.3           .0
inbound PL/SQL rpc elapsed time                           0.0           .0
DB time                                             343,015.7
background elapsed time                               1,339.8
background cpu time                                     845.1
          -------------------------------------------------------------
Operating System Statistics - Detail      DB/Inst: XXXX/XXXX  Snaps: 4824-4827

Snap Time           Load    %busy    %user     %sys    %idle  %iowait
--------------- -------- -------- -------- -------- -------- --------
12-Nov 11:00:50      4.9      N/A      N/A      N/A      N/A      N/A
12-Nov 12:00:55      1.3     10.9      9.5      1.2      3.4     89.1
12-Nov 12:18:01      0.4      3.3      2.6      0.7      0.1     96.7
12-Nov 13:00:59      3.9      9.1      7.9      1.1      2.0     90.9
          -------------------------------------------------------------

Foreground Wait Class                     DB/Inst: XXXX/XXXX Snaps: 4824-4827
-> s  - second, ms - millisecond -    1000th of a second
-> ordered by wait time desc, waits desc
-> %Timeouts: value of 0 indicates value was  Captured Time accounts for        162.1%  of Total DB time     343,015.70 (s)
-> Total FG Wait Time:           547,088.75 (s)  DB CPU time:       8,875.04 (s)

                                                                  Avg
                                      %Time       Total Wait     wait
Wait Class                      Waits -outs         Time (s)     (ms)  %DB time
-------------------- ---------------- ----- ---------------- -------- ---------
Other                         136,738     0          541,966     3964     158.0
DB CPU                                                 8,875                2.6
User I/O                    1,859,888     0            2,295        1       0.7
Network                     1,000,390     0            1,480        1       0.4
Application                     5,131     1            1,145      223       0.3
Commit                         11,616     0              126       11       0.0
Concurrency                    53,354    96               56        1       0.0
System I/O                  1,473,457     0               14        0       0.0
Configuration                     183    77                4       24       0.0
Administrative                     26     0                0       16       0.0
          -------------------------------------------------------------

Foreground Wait Events                   DB/Inst: XXXX/XXXX  Snaps: 4824-4827
-> s  - second, ms - millisecond -    1000th of a second
-> Only events with Total Wait Time (s) >= .001 are shown
-> ordered by wait time desc, waits desc (idle events last)
-> %Timeouts: value of 0 indicates value was  only enqueues with waits are shown
-> Enqueue stats gathered prior to 10g should not be compared with 10g data
-> ordered by Wait Time desc, Waits desc

Enqueue Type (Request Reason)
------------------------------------------------------------------------------
    Requests    Succ Gets Failed Gets       Waits  Wt Time (s) Av Wt Time(ms)
------------ ------------ ----------- ----------- ------------ --------------
RC-Result Cache: Enqueue (Result Cache: Contention)
     686,436      686,400           5       4,035          854         211.59
TX-Transaction (row lock contention)
          45           45           0           2          160      79,995.00
UL-User-defined
       3,393        3,352          41          42          123       2,930.95
WL-Being Written Redo Log
          57           28          29           8            9       1,123.75
RO-Multiple Object Reuse (fast object reuse)
          18           18           0           2            5       2,305.00
CF-Controlfile Transaction
     342,596      342,595           1          78            3          42.56
TX-Transaction (index contention)
       1,534        1,534           0          27            1          43.70
KO-Multiple Object Checkpoint (fast object checkpoint)
         198          198           0          22            1          49.55
PS-PX Process Reservation
       3,690        3,690           0          40            0            .75
HW-Segment High Water Mark
       7,628        7,628           0           1            0          20.00
TX-Transaction
      97,145       97,145           0           2            0           5.00
TH-Threshold Chain (metric threshold evaluation)
       1,306        1,306           0           1            0          10.00
SQ-Sequence Cache
      10,320       10,320           0          20            0            .00
          -------------------------------------------------------------
Latch Activity                           DB/Inst: XXXX/XXXX  Snaps: 4824-4827
-> "Get Requests", "Pct Get Miss" and "Avg Slps/Miss" are statistics for
   willing-to-wait latch get requests
-> "NoWait Requests", "Pct NoWait Miss" are for no-wait latch get requests
-> "Pct Misses" for both should be very close to 0.0

                                           Pct    Avg   Wait                 Pct
                                    Get    Get   Slps   Time       NoWait NoWait
Latch Name                     Requests   Miss  /Miss    (s)     Requests   Miss
------------------------ -------------- ------ ------ ------ ------------ ------
ASM db client latch               5,077    0.0             0            0    N/A
ASM map operation hash t              8    0.0             0            0    N/A
AWR Alerted Metric Eleme         99,177    0.0             0            0    N/A
Change Notification Hash          2,646    0.0             0            0    N/A
Consistent RBA                   71,683    0.0    1.0      0            0    N/A
DML lock allocation       1,632,832,756    0.0    0.8      1            0    N/A
DMON Work Queues Latch               96    0.0             0            0    N/A
Event Group Locks                 2,024    0.0             0            0    N/A
FAL request queue                   373    0.0             0            0    N/A
FAL subheap alocation               373    0.0             0            0    N/A
FIB s.o chain latch             334,842    0.0    0.0      0            0    N/A
FOB s.o list latch              368,326    0.0    0.3      0            0    N/A
File State Object Pool P              8    0.0             0            0    N/A
IPC stats buffer allocat              8    0.0             0            0    N/A
In memory undo latch              4,276    0.0             0            0    N/A
JOX SGA heap latch               10,787    0.0             0            0    N/A
JS Sh mem access                     24    0.0             0            0    N/A
JS broadcast autostart l            572    0.0             0            0    N/A
JS queue access latch                 8    0.0             0            0    N/A
JS queue state obj latch         60,816    0.0             0            0    N/A
JS slv state obj latch              503    0.0             0            0    N/A
KFC FX Hash Latch                     8    0.0             0            0    N/A
KFC Hash Latch                        8    0.0             0            0    N/A
KFCL LE Freelist                      8    0.0             0            0    N/A
KFR redo allocation latc              8    0.0             0            0    N/A
KGNFS-NFS:SHM structure               8    0.0             0            0    N/A
KGNFS-NFS:SVR LIST                    8    0.0             0            0    N/A
KJC message pool free li              8    0.0             0            0    N/A
KJCT flow control latch               8    0.0             0            0    N/A
KMG MMAN ready and start         28,680    0.0             0            0    N/A
KMG resize request state             32    0.0             0            0    N/A
KTF sga latch                        41    0.0             0        2,217    0.0
KWQMN job cache list lat            125    3.2    0.5      0            0    N/A
KWQP Prop Status                      6    0.0             0            0    N/A
KWQS pqsubs latch                    18    0.0             0            0    N/A
KWQS pqueue ctx latch                30    0.0             0            0    N/A
LGWR NS Write                   141,954    0.0    0.4      0            0    N/A
Locator state objects po              8    0.0             0            0    N/A
MQL Tracking Latch                    0    N/A             0          144    0.0
Memory Management Latch          26,752    0.0             0       28,680    0.0
Memory Queue                          8    0.0             0            0    N/A
Memory Queue Message Sub              8    0.0             0            0    N/A
Memory Queue Message Sub              8    0.0             0            0    N/A
Memory Queue Message Sub              8    0.0             0            0    N/A
Memory Queue Message Sub              8    0.0             0            0    N/A
Memory Queue Subscriber               8    0.0             0            0    N/A
MinActiveScn Latch              941,188    0.0    0.0      0            0    N/A
Mutex                                 8    0.0             0            0    N/A
Mutex Stats                           8    0.0             0            0    N/A
OS process                      110,192    0.0             0            0    N/A
OS process allocation             7,424    0.0    0.0      0            0    N/A
OS process: request allo          4,094    0.0             0            0    N/A
PL/SQL warning settings         192,843    0.0             0            0    N/A
QMT                                   8    0.0             0            0    N/A
Real-time plan statistic         34,211    0.7    0.3      0            0    N/A
Request id generation la             48    0.0             0            0    N/A
Result Cache: Latch           6,045,296    0.2    1.0   5.3E+05            0
Result Cache: SO Latch            2,558    0.0             0            0    N/A
SGA IO buffer pool latch          1,435    0.0             0        2,004    0.0
SGA blob parent                       8    0.0             0            0    N/A
Latch Activity                           DB/Inst: XXXX/XXXX  Snaps: 4824-4827
-> "Get Requests", "Pct Get Miss" and "Avg Slps/Miss" are statistics for
   willing-to-wait latch get requests
-> "NoWait Requests", "Pct NoWait Miss" are for no-wait latch get requests
-> "Pct Misses" for both should be very close to 0.0

                                           Pct    Avg   Wait                 Pct
                                    Get    Get   Slps   Time       NoWait NoWait
Latch Name                     Requests   Miss  /Miss    (s)     Requests   Miss
------------------------ -------------- ------ ------ ------ ------------ ------
SGA bucket locks                      8    0.0             0            0    N/A
SGA heap locks                        8    0.0             0            0    N/A
SGA pool locks                        8    0.0             0            0    N/A
SQL memory manager latch         21,875    4.0    1.0      0        2,391    0.1
SQL memory manager worka      2,866,488    0.0    0.0      0            0    N/A
Shared B-Tree                       364    0.0             0            0    N/A
Streams Generic                       8    0.0             0            0    N/A
Testing                               8    0.0             0            0    N/A
Token Manager                         8    0.0             0            0    N/A
Write State Object Pool               8    0.0             0            0    N/A
X$KSFQP                             168    0.0             0            0    N/A
XDB NFS Security Latch                8    0.0             0            0    N/A
XDB unused session pool               8    0.0             0            0    N/A
XDB used session pool                 8    0.0             0            0    N/A
active checkpoint queue          11,510    0.0    0.0      0            0    N/A
active service list              54,071    0.1    0.0      0        3,942    0.0
alert log latch                   6,176    0.0             0            0    N/A
archive control                   1,348    0.0             0            0    N/A
archive process latch             3,194    0.1    1.0      0            0    N/A
begin backup scn array            3,675    0.0             0            0    N/A
buffer pool                         652    0.0             0            0    N/A
business card                         8    0.0             0            0    N/A
cache buffer handles          2,530,118    0.0    0.0      0            0    N/A
cache buffers chains        606,040,029    0.0    0.0      0   14,793,597    0.0
cache buffers lru chain       1,547,224    0.1    0.1      0   12,707,295    0.1
cache table scan latch           57,513    0.0    0.0      0       57,513    0.0
cas latch                             8    0.0             0            0    N/A
change notification clie              8    0.0             0            0    N/A
channel handle pool latc          4,801    0.0             0            0    N/A
channel operations paren         57,667    0.0    0.0      0            0    N/A
checkpoint queue latch        1,103,984    0.0    0.1      0      465,121    0.0
client/application info       1,164,166    0.0    0.0      0            0    N/A
commit callback allocati          4,892    0.0             0            0    N/A
compile environment latc          4,760    0.0             0            0    N/A
corrupted undo seg lock          30,980    0.0    0.0      0            0    N/A
cp cmon/server latch                  8    0.0             0            0    N/A
cp pool latch                         8    0.0             0            0    N/A
cp server hash latch                  8    0.0             0            0    N/A
cp sga latch                      1,547    0.0             0            0    N/A
cv apply list lock                    8    0.0             0            0    N/A
cv free list lock                     8    0.0             0            0    N/A
deferred cleanup latch            1,547    0.0             0            0    N/A
dictionary lookup                     2    0.0             0            0    N/A
dml lock allocation               1,547    0.0             0            0    N/A
done queue latch                      8    0.0             0            0    N/A
dummy allocation                  9,584    0.3    0.0      0            0    N/A
enqueue hash chains           3,908,136    0.0    0.1      0          407    0.0
enqueues                      3,082,619    0.1    0.0      0            0    N/A
error message lists               1,911   12.9    0.2      0            0    N/A
fifth spare latch                     8    0.0             0            0    N/A
file cache latch                  5,840    0.0             0            0    N/A
flashback archiver latch             24    0.0             0            0    N/A
flashback copy                        8    0.0             0            0    N/A
gc element                            8    0.0             0            0    N/A
gcs commit scn state                  8    0.0             0            0    N/A
gcs partitioned table ha              8    0.0             0            0    N/A
gcs pcm hashed value buc              8    0.0             0            0    N/A
gcs resource freelist                 8    0.0             0            0    N/A
gcs resource hash                     8    0.0             0            0    N/A
gcs resource scan list                8    0.0             0            0    N/A
Latch Activity                           DB/Inst: XXXX/XXXX  Snaps: 4824-4827
-> "Get Requests", "Pct Get Miss" and "Avg Slps/Miss" are statistics for
   willing-to-wait latch get requests
-> "NoWait Requests", "Pct NoWait Miss" are for no-wait latch get requests
-> "Pct Misses" for both should be very close to 0.0

                                           Pct    Avg   Wait                 Pct
                                    Get    Get   Slps   Time       NoWait NoWait
Latch Name                     Requests   Miss  /Miss    (s)     Requests   Miss
------------------------ -------------- ------ ------ ------ ------------ ------
gcs shadows freelist                  8    0.0             0            0    N/A
ges domain table                      8    0.0             0            0    N/A
ges enqueue table freeli              8    0.0             0            0    N/A
ges group table                       8    0.0             0            0    N/A
ges process hash list                 8    0.0             0            0    N/A
ges process parent latch              8    0.0             0            0    N/A
ges resource hash list                8    0.0             0            0    N/A
ges resource scan list                8    0.0             0            0    N/A
ges resource table freel              8    0.0             0            0    N/A
ges value block free lis              8    0.0             0            0    N/A
global KZLD latch for me          2,785    0.0             0            0    N/A
global tx hash mapping            4,244    0.0             0            0    N/A
granule operation                     8    0.0             0            0    N/A
hash table column usage           1,614    0.0             0    3,551,922    0.0
hash table modification             487    0.0             0            0    N/A
internal temp table obje             77    0.0             0            0    N/A
intra txn parallel recov              8    0.0             0            0    N/A
io pool granule metadata              8    0.0             0            0    N/A
job workq parent latch                8    0.0             0        1,309    0.2
job_queue_processes para            591    0.0             0            0    N/A
k2q lock allocation                   8    0.0             0            0    N/A
kdlx hb parent latch                  8    0.0             0            0    N/A
kgb parent                            8    0.0             0            0    N/A
kks stats                        38,560    0.0             0            0    N/A
kokc descriptor allocati         97,640    0.0    0.3      0            0    N/A
krbmrosl                         53,549    0.0             0            0    N/A
ksfv messages                         8    0.0             0            0    N/A
kss move lock                        62    0.0             0            0    N/A
ksuosstats global area              492    0.0             0            0    N/A
ksv allocation latch              1,655    0.0             0            0    N/A
ksv class latch                     116    0.0             0            0    N/A
ksv msg queue latch                   8    0.0             0            0    N/A
ksz_so allocation latch           4,094    0.1    0.0      0            0    N/A
ktm global data                     168    0.0             0            0    N/A
kwqbsn:qsga                         299    0.0             0            0    N/A
lgwr LWN SCN                     71,741    0.0    0.0      0            0    N/A
library cache load lock           2,702    0.1    0.0      0            8    0.0
list of block allocation         41,711    0.0    0.0      0            0    N/A
loader state object free        427,580    0.0    0.0      0            0    N/A
lob segment dispenser la              8    0.0             0            0    N/A
lob segment hash table l             32    0.0             0            0    N/A
lob segment query latch               8    0.0             0            0    N/A
lock DBA buffer during m              8    0.0             0            0    N/A
logical standby cache                 8    0.0             0            0    N/A
logminer context allocat             85    0.0             0            0    N/A
logminer work area                    8    0.0             0            0    N/A
longop free list parent           1,220    0.0             0           87    0.0
mapped buffers lru chain              8    0.0             0            0    N/A
message pool operations           1,416    0.0             0            0    N/A
messages                        358,366    0.0    0.0      0            0    N/A
mostly latch-free SCN            72,594    0.3    0.0      0            0    N/A
msg queue latch                       8    0.0             0            0    N/A
multiblock read objects         249,432    0.0    0.0      0            0    N/A
name-service namespace b              8    0.0             0            0    N/A
ncodef allocation latch           1,547    0.0             0            0    N/A
object queue header heap        109,342    0.0    0.0      0      108,179    0.0
object queue header oper      7,078,993    0.0    0.1      0      108,350    0.2
object stats modificatio          3,832    0.0             0            0    N/A
parallel query alloc buf         10,064    0.5    0.0      0            0    N/A
parallel query stats              1,191   14.0    0.5      0            0    N/A
Latch Activity                           DB/Inst: XXXX/XXXX  Snaps: 4824-4827
-> "Get Requests", "Pct Get Miss" and "Avg Slps/Miss" are statistics for
   willing-to-wait latch get requests
-> "NoWait Requests", "Pct NoWait Miss" are for no-wait latch get requests
-> "Pct Misses" for both should be very close to 0.0

                                           Pct    Avg   Wait                 Pct
                                    Get    Get   Slps   Time       NoWait NoWait
Latch Name                     Requests   Miss  /Miss    (s)     Requests   Miss
------------------------ -------------- ------ ------ ------ ------------ ------
parameter list                    5,827    0.0             0            0    N/A
parameter table manageme          9,896    0.0    0.0      0            0    N/A
peshm                                 8    0.0             0            0    N/A
pesom_free_list                 298,774    0.0             0            0    N/A
pesom_hash_node                 299,604    0.0             0            0    N/A
pesom_heap_alloc                  1,705    0.0             0            0    N/A
post/wait queue                  22,585    0.0    0.0      0       11,709    0.0
process allocation                4,417    0.1    1.0      0        2,016    0.0
process group creation            4,094    0.1    0.0      0            0    N/A
process queue                     5,740    4.9    0.2      0            0    N/A
process queue reference         226,129    0.0    0.0      0       20,098    0.5
qmn task queue latch              1,572    2.2    0.2      0            0    N/A
query server freelists            4,003    0.2    0.0      0            0    N/A
query server process                 40    0.0             0           50    0.0
queued dump request                  24    0.0             0            0    N/A
readredo stats and histo         70,657    0.0             0            0    N/A
recovery domain hash lis              8    0.0             0            0    N/A
redo allocation                 236,306    0.1    0.1      0    6,110,775    0.0
redo copy                             8    0.0             0    6,111,637    0.0
redo writing                    235,335    0.0    0.0      0            0    N/A
resmgr group change latc        366,965    0.0             0            0    N/A
resmgr:active threads             9,584    0.0             0            0    N/A
resmgr:actses change gro          4,539    0.0             0            0    N/A
resmgr:actses change sta              9    0.0             0            0    N/A
resmgr:free threads list          9,576    1.3    0.6     23            0    N/A
resmgr:plan CPU method                8    0.0             0            0    N/A
resmgr:resource group CP              8    0.0             0            0    N/A
resmgr:schema config                244    0.0             0            0    N/A
resmgr:session queuing                8    0.0             0            0    N/A
resmgr:vc list latch                  1    0.0             0            0    N/A
rm cas latch                          8    0.0             0            0    N/A
row cache objects            24,881,624    0.0    0.1      0           90    0.0
rules engine aggregate s              6    0.0             0            0    N/A
rules engine rule set st            312    0.0             0            0    N/A
second spare latch                    8    0.0             0            0    N/A
sequence cache                1,510,566    0.0    0.0      0            0    N/A
session allocation           34,584,281    0.5    0.0      5            0    N/A
session idle bit              2,167,918    0.0    0.0      0            0    N/A
session queue latch                   8    0.0             0            0    N/A
session state list latch         17,034    0.3    0.1      0            0    N/A
session switching                 2,554    0.0             0            0    N/A
session timer                     3,939    0.0             0            0    N/A
shared pool                   5,851,141    0.1    0.2      2            0    N/A
shared pool sim alloc                 8    0.0             0            0    N/A
shared pool simulator        18,576,870    0.0    0.1      0            0    N/A
sim partition latch                   8    0.0             0            0    N/A
simulator hash latch         30,498,932    0.0    0.0      0            0    N/A
simulator lru latch          30,170,595    0.1    0.0      0      163,363    0.0
sort extent pool                139,425    0.0    0.0      0            0    N/A
space background task la          5,636    0.2    0.4      0        4,804    0.0
state object free list                6    0.0             0            0    N/A
statistics aggregation            2,520    0.0             0            0    N/A
tablespace key chain                  8    0.0             0            0    N/A
temp lob duration state           2,521    0.0             0            0    N/A
temporary table state ob          1,662    0.0             0            0    N/A
test excl. parent l0                  8    0.0             0            0    N/A
test excl. parent2 l0                 8    0.0             0            0    N/A
third spare latch                     8    0.0             0            0    N/A
threshold alerts latch            2,488    0.0             0            0    N/A
trace latch                          57    0.0             0            0    N/A
Latch Activity                           DB/Inst: XXXX/XXXX  Snaps: 4824-4827
-> "Get Requests", "Pct Get Miss" and "Avg Slps/Miss" are statistics for
   willing-to-wait latch get requests
-> "NoWait Requests", "Pct NoWait Miss" are for no-wait latch get requests
-> "Pct Misses" for both should be very close to 0.0

                                           Pct    Avg   Wait                 Pct
                                    Get    Get   Slps   Time       NoWait NoWait
Latch Name                     Requests   Miss  /Miss    (s)     Requests   Miss
------------------------ -------------- ------ ------ ------ ------------ ------
transaction allocation      398,751,031    0.0    0.9      0            0    N/A
transaction branch alloc          5,753    0.0             0            0    N/A
undo global data                439,645    0.0             0            0    N/A
user lock                        12,874    0.2    0.7      0            0    N/A
virtual circuit buffers               8    0.0             0            0    N/A
virtual circuit holder                8    0.0             0            0    N/A
virtual circuit queues                8    0.0             0            0    N/A
          -------------------------------------------------------------

Latch Sleep Breakdown                    DB/Inst: XXXX/XXXX  Snaps: 4824-4827
-> ordered by misses desc

                                       Get                                 Spin
Latch Name                        Requests       Misses      Sleeps        Gets
-------------------------- --------------- ------------ ----------- -----------
session allocation              34,584,281      180,605       6,062     175,033
DML lock allocation          1,632,832,756      170,158     129,597      59,222
cache buffers chains           606,040,029       64,824         207      64,625
simulator lru latch             30,170,595       30,868       1,064      29,852
transaction allocation         398,751,031       20,481      17,958       6,525
Result Cache: Latch              6,045,296        9,900      10,204       7,436
shared pool                      5,851,141        6,027       1,471       4,692
row cache objects               24,881,624        3,662         302       3,407
enqueues                         3,082,619        2,393         108       2,285
cache buffers lru chain          1,547,224        1,791         179       1,627
enqueue hash chains              3,908,136        1,512         172       1,344
cache buffer handles             2,530,118          915           7         908
SQL memory manager latch            21,875          878         877          61
shared pool simulator           18,576,870          857          88         787
object queue header operat       7,078,993          816          54         763
redo allocation                    236,306          342          24         318
simulator hash latch            30,498,932          317           1         316
process queue                        5,740          283          64         222
Real-time plan statistics           34,211          247          85         165
error message lists                  1,911          246          44         205
mostly latch-free SCN               72,594          246           1         245
parallel query stats                 1,191          167          86          92
resmgr:free threads list             9,576          120          69          60
sequence cache                   1,510,566           97           1          96
session state list latch            17,034           55           3          52
parallel query alloc buffe          10,064           49           1          48
FOB s.o list latch                 368,326           40          11          34
qmn task queue latch                 1,572           35           6          29
kokc descriptor allocation          97,640           24           6          18
user lock                           12,874           23          16           7
space background task latc           5,636           12           5           7
checkpoint queue latch           1,103,984           11           1          10
LGWR NS Write                      141,954           10           4           6
KWQMN job cache list latch             125            4           2           2
process allocation                   4,417            4           4           0
archive process latch                3,194            2           2           0
Consistent RBA                      71,683            1           1           0
          -------------------------------------------------------------


Result_cache blocking

Had a result_cache problem today.

If you didn’t know it already, DBA_HIST_ACTIVE_SESS_HISTORY is a real boon for getting a very good idea of a) when the problem started and b) how wide the impact was.

300 session were backing up on a latch free wait. Turns out the latch was the “Result Cache: Latch”.

The blocking session was doing a select from a view that used some result_cache function lookups.

The blocking session having been killed and given a couple of minutes to clean up, the blockage cleared in a instant.

Still trying to get to the bottom of the result cache issue – is there a serious result_cache flaw or have I just implemented it poorly?

Related info:

Using function result_cache for timed caching*

*Or “can I use result_cache to cache for 1 minute/day/hour/day/week/month”

There is already a plethora of excellent resources on the new 11g result_cache functionality, notably:

Including a couple of interesting angles on things here:

Now one of my first tasks now that we’re on 11g and EE (having upgraded from 9i SE) is to identify new features to implement from a performance perspective.

Having read some of the above resources, it won’t surprise you to know that you can’t just point anything at the result_cache and expect a dramatic improvement – quite the contrary sometimes. As Adrian Billington notes in his article, if you’re already doing session memory caching using pl/sql structures, you’re unlikely to see any saving in time – the opposite in fact – but the advantages of the result cache are “cross-session availability, managed SGA memory usage and protected data integrity”. Of course, depending on what you’re doing, you could even choose to use pl/sql caching on top of the result cache.

So, if you’ve got a result_cache target in mind – make sure you test it.

One of the things I’m currently looking at is whether to implement a function result_cache lookup for time sensitive information. The sort of thing I mean is information that changes daily or hourly or weekly independently of the underlying data changing.

For example, fund prices and valuation dates. A fund might have a scheduled set of valuation dates from which a certain price applies. And on any given day, you might be in a different valuation period.

Exactly the sort of thing you might cache using whatever caching method you might choose. And exactly the sort of thing that you could use function result_cache functionality for.

If the underlying data changes, the cache will be refreshed (having used the RELIES_ON clause).

If the timing point changes (the day/week/hour/minute/whatever), a new set of data is cached.

Here is a simple example of what I mean.

- Create a function that will cache by the minute. We will do this by creating a function with a single parameter that defaults to the current date truncated to the current minute and by calling it without specifying a parameter:


CREATE OR REPLACE FUNCTION f_test_minute_result_cache (
i_today IN DATE DEFAULT TRUNC(SYSDATE,'MI')
)
RETURN DATE
RESULT_CACHE
AS
BEGIN
RETURN SYSDATE;
END f_test_minute_result_cache;
/

Then call it:


dominic@11gTest>l
1 select to_char(sysdate,'DD-MON-YYYY HH24:MI:SS') now
2 ,to_char(trunc(sysdate,'MI'),'DD-MON-YYYY HH24:MI:SS') this_minute
3 ,to_char(f_test_minute_result_cache,'DD-MON-YYYY HH24:MI:SS') cached_result
4* from dual
dominic@11gTest>/

NOW THIS_MINUTE CACHED_RESULT
-------------------- -------------------- --------------------
17-JUN-2008 10:16:02 17-JUN-2008 10:16:00 17-JUN-2008 10:16:02

Elapsed: 00:00:00.00

Call it again, in the same minute, but a few seconds later:


dominic@11gTest>l
1 select to_char(sysdate,'DD-MON-YYYY HH24:MI:SS') now
2 ,to_char(trunc(sysdate,'MI'),'DD-MON-YYYY HH24:MI:SS') this_minute
3 ,to_char(f_test_minute_result_cache,'DD-MON-YYYY HH24:MI:SS') cached_result
4* from dual
dominic@11gTest>/

NOW THIS_MINUTE CACHED_RESULT
-------------------- -------------------- --------------------
17-JUN-2008 10:16:06 17-JUN-2008 10:16:00 17-JUN-2008 10:16:02

Elapsed: 00:00:00.00

You can see from “Now” that time has inevitably moved on, but as the default in parameter has not changed, the result has come from the cache.

Then, run the statement again a bit later:


dominic@11gTest>l
1 select to_char(sysdate,'DD-MON-YYYY HH24:MI:SS') now
2 ,to_char(trunc(sysdate,'MI'),'DD-MON-YYYY HH24:MI:SS') this_minute
3 ,to_char(f_test_minute_result_cache,'DD-MON-YYYY HH24:MI:SS') cached_result
4* from dual
dominic@11gTest>/

NOW THIS_MINUTE CACHED_RESULT
-------------------- -------------------- --------------------
17-JUN-2008 10:55:29 17-JUN-2008 10:55:00 17-JUN-2008 10:55:29

Elapsed: 00:00:00.00

Time has moved on, the default in parameter has moved on, a new result is generated and cached.

So, just to show that you could also use result_cache in this way. Doesn’t necessarily mean that you should though.

Why isn’t my /*+ result_cache */ working?

As I mentioned just now, I’ve got Oracle 11g up and running on my apology of a laptop but I’ve not yet got to the juicy result cache stuff that I wanted to get to.

First thing I want to do is to set up some result cache demos.

It’s getting late and I’m getting tired, distracted now by Have I Got News For You, I’m making silly mistakes and jumping to conclusions.

I thought I was going to be blogging about the result_cache initialisation parameters result_cache_max_size and result_cache_max_result and why these were preventing the efficacy of my demos.

But from my observations, actually the problem seems to be that if you’re silly enough to log in as sysdba, you won’t user the result_cache.

Witness:


SQL*Plus: Release 11.1.0.6.0 - Production on Mon Dec 10 23:20:01 2007

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

Enter user-name: dom
Enter password:

Connected to:
Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL> set lines 120 pages 9999 autotrace on timing on
SQL> drop table table_c
2 /

Table dropped.

Elapsed: 00:00:01.76
SQL> create table table_c as select object_id from all_objects where rownum select /*+ result_cache */
2 *
3 from table_c;

OBJECT_ID
----------
20
46
28
15
29
3
25
41
54

9 rows selected.

Elapsed: 00:00:00.01

Execution Plan
----------------------------------------------------------
Plan hash value: 4211580995

-------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 9 | 117 | 3 (0)| 00:00:01 |
| 1 | RESULT CACHE | bamn0a75f25nx8rd4zwa55md30 | | | | |
| 2 | TABLE ACCESS FULL| TABLE_C | 9 | 117 | 3 (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------

Result Cache Information (identified by operation id):
------------------------------------------------------

1 - column-count=1; dependencies=(DOM.TABLE_C); name="select /*+ result_cache */
*
from table_c"

Note
-----
- dynamic sampling used for this statement

Statistics
----------------------------------------------------------
28 recursive calls
0 db block gets
10 consistent gets
1 physical reads
0 redo size
514 bytes sent via SQL*Net to client
420 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
9 rows processed

SQL>

That should have got it in the cache. A subsequent call should have no consistent gets:


SQL> l
1 select /*+ result_cache */
2 *
3* from table_c
SQL> /

OBJECT_ID
----------
20
46
28
15
29
3
25
41
54

9 rows selected.

Elapsed: 00:00:00.00

Execution Plan
----------------------------------------------------------
Plan hash value: 4211580995

-------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 9 | 117 | 3 (0)| 00:00:01 |
| 1 | RESULT CACHE | bamn0a75f25nx8rd4zwa55md30 | | | | |
| 2 | TABLE ACCESS FULL| TABLE_C | 9 | 117 | 3 (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------

Result Cache Information (identified by operation id):
------------------------------------------------------

1 - column-count=1; dependencies=(DOM.TABLE_C); name="select /*+ result_cache */
*
from table_c"

Note
-----
- dynamic sampling used for this statement

Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
0 consistent gets
0 physical reads
0 redo size
514 bytes sent via SQL*Net to client
420 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
9 rows processed

SQL>

Log on as sysdba and watch it not use the result_cache


SQL>
SQL> conn dom as sysdba
Enter password:
Connected.
SQL> set lines 120 pages 9999 autotrace on timing on
SQL> l
1 select /*+ result_cache */
2 *
3* from table_c
SQL> /

OBJECT_ID
----------
20
46
28
15
29
3
25
41
54

9 rows selected.

Elapsed: 00:00:00.00

Execution Plan
----------------------------------------------------------
Plan hash value: 4211580995

-----------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 9 | 117 | 2 (0)| 00:00:01 |
| 1 | TABLE ACCESS FULL| TABLE_C | 9 | 117 | 2 (0)| 00:00:01 |
-----------------------------------------------------------------------------

Note
-----
- dynamic sampling used for this statement

Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
4 consistent gets
0 physical reads
0 redo size
521 bytes sent via SQL*Net to client
420 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
9 rows processed

SQL> show user
USER is "SYS"

Follow

Get every new post delivered to your Inbox.

Join 62 other followers