Tuesday, October 31, 2017

ORA-04025 library object lock on DATABASE Truncate Triggers

In this Blog, we will discuss ORA-04025 Errors caused by DATABASE Truncate Triggers.

Note 1. All tests are done in Oracle 12.1.0.2.0 on AIX, Solaris, Linux.
Note 2. ORA-04025 Maximum Allowed Library Object Lock Allocated is also discussed in Blog:
             ORA-04025 library object lock on AQ queue and SQL cursor


1. DATABASE Truncate Triggers


In Oracle 12c, there exist two DATABASE Triggers:
    XDB_PI_TRIG
    AW_TRUNC_TRG
They can be discovered by:

create or replace function getlong(p_trigger_name varchar2) return varchar2 as 
  l_data long; 
begin 
  select trigger_body into l_data from dba_triggers where trigger_name = p_trigger_name; 
  return substr(l_data, 1, 4000);
end; 
/

column owner format            a6
column trigger_name format     a12
column trigger_type format     a12
column triggering_event format a15
column status format           a8
column description format      a40
set wrap off

SQL> select owner, trigger_name, trigger_type, triggering_event, status, description 
         --,getlong(trigger_name) trigger_body
     from dba_triggers where triggering_event like '%TRUNCATE%';

  OWNER  TRIGGER_NAME TRIGGER_TYPE TRIGGERING_EVEN STATUS   DESCRIPTION
  ------ ------------ ------------ --------------- -------- ----------------------------------------
  SYS    XDB_PI_TRIG  BEFORE EVENT DROP OR TRUNCAT ENABLED  sys.xdb_pi_trig
  SYS    AW_TRUNC_TRG AFTER EVENT  TRUNCATE        ENABLED  aw_trunc_trg AFTER TRUNCATE ON DATABASE


set wrap on

SQL> select getlong(trigger_name) trigger_body from dba_triggers where trigger_name = 'XDB_PI_TRIG';

BEGIN
  BEGIN
    IF (sys.is_vpd_enabled(sys.dictionary_obj_owner, sys.dictionary_obj_name, xdb.DBMS_XDBZ.IS_ENABLED_CONTENTS)) THEN
      xdb.XDB_PITRIG_PKG.pitrig_truncate(sys.dictionary_obj_owner, sys.dictionary_obj_name);
    ELSIF (sys.is_vpd_enabled(sys.dictionary_obj_owner, sys.dictionary_obj_name, xdb.DBMS_XDBZ.IS_ENABLED_RESMETADATA)) THEN
      xdb.XDB_PITRIG_PKG.pitrig_dropmetadata(sys.dictionary_obj_owner, sys.dictionary_obj_name);
    END IF;
  EXCEPTION
    WHEN OTHERS THEN
     null;
  END;
END;

SQL> select getlong(trigger_name) trigger_body from dba_triggers where trigger_name = 'AW_TRUNC_TRG';

BEGIN
  aw_trunc_proc(ora_dict_obj_type, ora_dict_obj_name, ora_dict_obj_owner);
END;


Note: ora_dict_obj_owner, ora_dict_obj_name, ora_dict_obj_type are published Attributes (public synonyms) of System Events.
      (replacing functions of earlier releases: sys.dictionary_obj_owner, sys.dictionary_obj_name, sys.dictionary_obj_type 
       defined in dbms_standard).


2. Test


Run following test (see appended Test Code):

alter system set session_cached_cursors=2000 scope=spfile;
alter system set processes=1100 scope=spfile;
alter system set job_queue_processes=1000 scope=spfile;
alter system set "_session_cached_instantiations"=1001 scope=spfile;

-- restart DB
SQL> startup force

-- start Test by launching 66 Jobs (66 > floor(65535/1000)=65)
SQL> exec gtt_truncate_job(66, 1e9);

--after Test, clean jobs
-- exec clean_jobs;
During test, monitor v$db_object_cache.LOCKS for both triggers, we can see their increasing:

column name format a80
set wrap off

SQL> select hash_value, locks, pins, locked_total, pinned_total, name  --v.*
       from v$db_object_cache v
      where locks > 1000
        and (hash_value in (2219505151, 679830350) 
         or (name like '%xdb.DBMS_XDBZ.%' or name like '%aw_trunc_proc%')); 

  HASH_VALUE  LOCKS  PINS LOCKED_TOTAL PINNED_TOTAL NAME
  ---------- ------ ----- ------------ ------------ --------------------------------------------------------------------------------
  2219505151  64141     0      1164253      1164234 BEGIN   BEGIN     IF (sys.is_vpd_enabled(sys.dictionary_obj_owner, sys.dictionar
  2219505151  64238     0      1164365            1 BEGIN   BEGIN     IF (sys.is_vpd_enabled(sys.dictionary_obj_owner, sys.dictionar
   679830350  64506     0      1164192      1164167 BEGIN   aw_trunc_proc(ora_dict_obj_type, ora_dict_obj_name, ora_dict_obj_owner);
   679830350  64602     0      1164289            1 BEGIN   aw_trunc_proc(ora_dict_obj_type, ora_dict_obj_name, ora_dict_obj_owner);
After about 10 minutes, LOCKS increased closing to 65535 (66 sessions, each of which allocated about 1000 LOCKS).

database alert.log shows ORA-04025 Errors caused by two triggers:

ORA-04025: maximum allowed library object lock allocated for BEGIN
  aw_trunc_proc(ora_dict_obj_type, ora_dict_obj_name, ora_dict_obj_owner);
END;

ORA-04025: maximum allowed library object lock allocated for BEGIN
  BEGIN
    IF (sys.is_vpd_enabled(sys.dictionary_obj_owner, sys.dictionary_obj_name, xdb.DBMS_XDBZ.IS_ENABLED_CONTENTS)) THEN
      xdb.XDB_PITRIG_PKG.pitrig_truncate(sys.dictionary_obj_owner, sys.dictionary_obj_name);
    ELSIF (sys.is_vpd_enabled(sys.dictionary_obj_owner, sys.dictionary_obj_name, xdb.DBMS_XDBZ.IS_ENABLED_RESMETADATA)) THEN
      xdb.XDB_PITRIG_PKG.pitrig_dropmetadata(sys.dictionary_obj_owner, sys.dictionary_obj_name);
    END IF;
  EXCEPTION
    WHEN OTHERS THEN
     null;
  END;
END;
Both cursors can also be found by:

column sql_text format a100
set wrap off

SQL > select sql_id, hash_value, executions, parse_calls, sql_text from v$sqlarea v 
      where sql_id in ('ct6c4h224pxgz', 'gx87sann8asuf') or hash_value in (2219505151, 679830350);

  SQL_ID        HASH_VALUE EXECUTIONS PARSE_CALLS SQL_TEXT
  ------------- ---------- ---------- ----------- --------------------------------------------------
  ct6c4h224pxgz 2219505151   13537973    13623969 BEGIN   BEGIN     IF (sys.is_vpd_enabled(sys.dicti
  gx87sann8asuf  679830350   13649026    13603140 BEGIN   aw_trunc_proc(ora_dict_obj_type, ora_dict_
Blog: ORA-04025 library object lock on AQ queue and SQL cursor showed that Maximum Allowed Library Object Lock is hard limited to 65535. That is why at least 66 Jobs (66 > floor(65535/1000)=65) have to be launched to provoke ORA-04025 Error.

Note that in the above test, we set
  session_cached_cursors=2000
because of two DATABASE Truncate Triggers, each of both can acquire about 1000 LOCKs.

As a justification, even we start one single session, LOCK_CNT is around 1000.

SQL > exec clean_jobs;
 
SQL > exec gtt_truncate_job(1, 1e9);

SQL > with sq as
        (select /*+ materialize */ sid, program, saddr, event
            ,to_char(p1, 'xxxxxxxxxxxxxxx') p1, p1text
            ,to_char(p2, 'xxxxxxxxxxxxxxx') p2, p2text
            ,to_char(p3, 'xxxxxxxxxxxxxxx') p3, p3text
         from v$session
        where program like '%(J%')
      select o.kglnahsh, s.sid, holding_user_session, object_handle, l.type, mode_held, mode_requested,
             count(*) lock_cnt     -- it goes up to about 1000
        from v$libcache_locks l, x$kglob o, sq s
       where 1= 1
         and o.kglnahsh in (2219505151, 679830350)     
         and l.object_handle = o.kglhdadr
         and l.holding_user_session = s.saddr
      group by o.kglnahsh, s.sid, holding_user_session, object_handle, l.type, mode_held, mode_requested
      order by lock_cnt desc, s.sid, holding_user_session, l.type, mode_held, mode_requested;
  
    KGLNAHSH  SID HOLDING_USER_SES OBJECT_HANDLE    TYPE  MODE_HELD MODE_REQUESTED   LOCK_CNT
  ---------- ---- ---------------- ---------------- ---- ---------- -------------- ----------
  2219505151  152 070001010D31BD08 07000100EDC018C8 LOCK          1              0       1012
  2219505151  152 070001010D31BD08 07000100ED2F4110 LOCK          1              0       1011
   679830350  152 070001010D31BD08 07000100ECDBA460 LOCK          1              0       1009
   679830350  152 070001010D31BD08 07000100ECDBBF28 LOCK          1              0       1009


3. "library cache: mutex X" and "cursor: pin X"


During test, heavy "library cache: mutex X" and "cursor: pin X" are observed on GTT truncate statement:

truncate table my_gtt
 
SQL > select mutex_identifier, mutex_type, count(*) cnt from v$mutex_sleep_history 
      group by mutex_identifier, mutex_type 
      order by cnt desc;

  MUTEX_IDENTIFIER MUTEX_TYPE      CNT
  ---------------- -------------- ----
         167539573 Library Cache   278
         167539573 Cursor Pin       81
   
SQL > select hash_value, locks, pins, locked_total, pinned_total, invalidations, name 
      from v$db_object_cache where hash_value in (167539573);

  HASH_VALUE  LOCKS  PINS LOCKED_TOTAL PINNED_TOTAL INVALIDATIONS NAME
  ---------- ------ ----- ------------ ------------ ------------- ---------------------
   167539573      1     0        14295        26690         13002 truncate table my_gtt
   167539573      2     0        14309        26510         13026 truncate table my_gtt
   167539573      1     0        14134        26218         12874 truncate table my_gtt
   ......
 
SQL > select sql_id, hash_value, executions, parse_calls, invalidations, sql_text 
      from v$sqlarea v where sql_id in ('1jh104s4zswvp') or hash_value in (167539573); 
 
  SQL_ID        HASH_VALUE EXECUTIONS PARSE_CALLS INVALIDATIONS SQL_TEXT
  ------------- ---------- ---------- ----------- ------------- ---------------------
  1jh104s4zswvp  167539573         86          90       1325129 truncate table my_gtt
It seems that "library cache: mutex X" is caused by dynamic SQL statement "EXECUTE IMMEDIATE" because GTT truncate is executed by:
    execute immediate 'truncate table my_gtt'
and both above DATABASE Truncate Triggers are probably also called by "EXECUTE IMMEDIATE" since v$db_object_cache.NAME and v$sqlarea.SQL_TEXT are formatted in lower and upper mixed cases.

See Blogs:
    Divide and conquer the true mutex contention
    "library cache: mutex X" and Application Context
for more discussions.


4. XDB_PI_TRIG Trigger Components and Cost


Run GTT truncate with SQL Trace 10046:

alter trigger sys.AW_TRUNC_TRG disable;
alter trigger sys.XDB_PI_TRIG enable;

SQL > alter system flush shared_pool; 
SQL > alter session set events '10046 trace name context forever, level 12';
SQL > exec gtt_truncate(1);
SQL > alter session set events '10046 trace name context off';
We can see all the TOP statements:

--SQL_ID: 86kwhy1f0bttn 
SELECT /*+ ALL_ROWS */
      COUNT (*)
  FROM DBA_POLICIES V
 WHERE     V.OBJECT_OWNER = :B3
       AND V.OBJECT_NAME = :B2
       AND (V.POLICY_NAME LIKE '%xdbrls%' OR V.POLICY_NAME LIKE '%$xd_%')
       AND V.FUNCTION = :B1
       
--SQL_ID: 1jh104s4zswvp 
truncate table my_gtt
       
--SQL_ID: 1u4r80k42x8jj 
select count(FA#) from SYS_FBA_TRACKEDTABLES where OBJ# = 1001511 and bitand(FLAGS, 128)=0

--SQL_ID: au7qd3c3yuk1u 
LOCK TABLE "MY_GTT" IN EXCLUSIVE MODE WAIT 5

--SQL_ID: 9ff116syaf279 
SELECT TO_NUMBER(XS_SYS_CONTEXT('XS$SESSION', 'SESSION_XS_USER_GUID')) FROM DUAL

--SQL_ID: au7qd3c3yuk1u 
LOCK TABLE "MY_GTT" IN EXCLUSIVE MODE WAIT 5
In fact, our GTT table: my_gtt is irrelevant to XDB:

SELECT /*+ ALL_ROWS */
      *
  FROM DBA_POLICIES V
 WHERE     V.OBJECT_OWNER = 'XDB'
     --AND V.OBJECT_NAME = 'MY_GTT'
       AND (V.POLICY_NAME LIKE '%xdbrls%' OR V.POLICY_NAME LIKE '%$xd_%')
       AND V.FUNCTION in ('CHECKPRIVRLS_SELECTPF', 'CHECKPRIVRLS_SELECTPROPF');         


5. Query against SYS_FBA_TRACKEDTABLES


We also noticed one query on SYS_FBA_TRACKEDTABLES having TOP Executions and Parse Calls. Both number are very close, which means that each Execution requires a Parse Call.

SQL > select sql_id, hash_value, executions, parse_calls, sql_text from v$sqlarea v 
where sql_id in ('1u4r80k42x8jj') or hash_value in (2284757553);

  SQL_ID        HASH_VALUE EXECUTIONS PARSE_CALLS SQL_TEXT
  ------------- ---------- ---------- ----------- -------------------------------------------------------------------------------------------
  1u4r80k42x8jj 2284757553   35663414    35536924 select count(FA#) from SYS_FBA_TRACKEDTABLES where OBJ# = 1001511 and bitand(FLAGS, 128)=0

-- where 1001511 is MY_GT

SQL > select object_name, object_id, object_type from dba_objects where object_id = 1001511;

  OBJECT_NAME   OBJECT_ID  OBJECT_TYPE
  -----------  ---------- ------------
  MY_GTT          1001511        TABLE
Searching in Oracle MOS, it looks like:
     Bug 15931756 - ORA-4031 / Queries against SYS_FBA_TRACKEDTABLES not shared (do not use binds) (Doc ID 15931756.8)


6. Disable/Drop Triggers


Trigger XDB_PI_TRIG is applied for Oracle XML Database (XDB), and AW_TRUNC_TRG for OLAP Analytic Workspaces(AW). If they are not installed/used, one can disable/drop them. These can be checked by:

select comp_name, version, status from dba_registry order by 1;
select * from v$option where parameter = 'OLAP';  
select * from dba_feature_usage_statistics where name like '%XDB%' or name like '%OLAP%';
select * from dba_aws;

(Note: XDB_PI_TRIG trigger moved from schema XDB to SYS with PSU 11.1.0.7.16)  
It is not clear why AW_TRUNC_TRG got installed although we do not buy/pay the license. Besides, the table name MY_GTT is not like 'AW$_%'.


7. Boundary Value and Cursor Leak ?


Set session_cached_cursors to Boundary Value: 65535:

alter system set session_cached_cursors=65535 scope=spfile;
alter system set "_session_cached_instantiations"=1001 scope=spfile;
alter system set open_cursors=400 scope=spfile;
alter system set cursor_sharing=exact scope=spfile;

-- enable only one single truncate trigger
alter trigger sys.AW_TRUNC_TRG disable;  
alter trigger sys.XDB_PI_TRIG  enable;

-- Restart DB
--SQL> startup force
Open one Sqlplus session and run (it takes about 10 minutes):

SQL (567) > exec gtt_truncate(65535);
Immediately after its finished, run following queries about Library Cache and Cursor, and look the output:

set lines 400
column name format a50
set wrap off

select hash_value, locks, pins, locked_total, pinned_total, executions, child_latch, name
  from v$db_object_cache v
 where (hash_value in (2219505151) or (name like 'BEGIN%xdb.DBMS_XDBZ.%')) 
   and locks > 100; 
   
  HASH_VALUE  LOCKS  PINS LOCKED_TOTAL PINNED_TOTAL EXECUTIONS CHILD_LATCH NAME
  ---------- ------ ----- ------------ ------------ ---------- ----------- --------------------------------------------------
  2219505151  65532     0       131070       131072      65535           0 BEGIN   BEGIN     IF (sys.is_vpd_enabled(sys.dicti
  2219505151  65533     0       131073            1      65535       62975 BEGIN   BEGIN     IF (sys.is_vpd_enabled(sys.dicti


select hash_value, sql_id, child_number, users_opening, executions, parse_calls, invalidations
from  v$sql v
where (sql_id in ('ct6c4h224pxgz') or hash_value in (2219505151))
  and users_opening > 100;   
  
  HASH_VALUE SQL_ID        CHILD_NUMBER USERS_OPENING EXECUTIONS PARSE_CALLS INVALIDATIONS
  ---------- ------------- ------------ ------------- ---------- ----------- -------------
  2219505151 ct6c4h224pxgz            1         65531      65535       65535             1  


select count(*) from v$open_cursor
where (sql_id in ('ct6c4h224pxgz') or hash_value in (2219505151))
  and sid in (567);
  
   COUNT(*)
  ---------
      65530 
    
select * from v$open_cursor
where (sql_id in ('ct6c4h224pxgz') or hash_value in (2219505151))
  and sid in (567) 
  and rownum <= 3;  

   SID HASH_VALUE SQL_ID        SQL_TEXT                              LAST_SQL SQL_EXEC CURSOR_TYPE                     CHILD_ADDRESS   
  ---- ---------- ------------- ------------------------------------- -------- -------- ------------------------------- ----------------
   567 2219505151 ct6c4h224pxgz BEGIN   BEGIN     IF (sys.is_vpd_enab                   DICTIONARY LOOKUP CURSOR CACHED 000000017636BA68
   567 2219505151 ct6c4h224pxgz BEGIN   BEGIN     IF (sys.is_vpd_enab                   DICTIONARY LOOKUP CURSOR CACHED 000000017636BA68
   567 2219505151 ct6c4h224pxgz BEGIN   BEGIN     IF (sys.is_vpd_enab                   DICTIONARY LOOKUP CURSOR CACHED 000000017636BA68


select s.program, s.sid, n.name p_name, t.value
from v$session s, v$sesstat t, v$statname n 
where s.sid=t.sid and n.statistic# = t.statistic# 
  and name = 'session cursor cache count'
  and s.sid in (567);
  
  PROGRAM       SID  P_NAME                      VALUE
  ------------ ---- --------------------------- ------
  sqlplus.exe   567  session cursor cache count  65535
  
      
select sql_id, child_number from v$sql_shared_cursor
where sql_id in ('ct6c4h224pxgz');

  SQL_ID        CHILD_NUMBER
  ------------- ------------
  ct6c4h224pxgz            0
  ct6c4h224pxgz            1      
The above result shows:
  1. v$db_object_cache.LOCKS is close to 65535
  2. v$sql.USERS_OPENING is close to 65535
  3. v$open_cursor count is close to 65535
  4. 'session cursor cache count' is 65535
Contrary to Blog: ORA-04025 library object lock on AQ queue and SQL cursor
  1. SESSION_CACHED_CURSORS (65535) sets hard limit of LIBRARY OBJECT LOCK, 
     instead of "_session_cached_instantiations".
  2. OPEN_CURSORS has no effect. 
v$open_cursor shows that one single session for one single cursor has 65535 CURSORS (opened and parsed, or cached), all marked with CURSOR_TYPE: "DICTIONARY LOOKUP CURSOR CACHED".
65535 is clearly over open_cursors=400, and according to Oracle Doc:
    OPEN_CURSORS specifies the maximum number of open cursors (handles to private SQL areas) a session can have at once.
It is not clear if this a Cursor Leak.

(MOS: Bug 25477055: INCORRECT CURSOR_TYPE IN V$OPEN_CURSOR FOR SESSION CACHED CURSOR said:
    "DICTIONARY LOOKUP CURSOR CACHED" is misreported, it should be "SESSION CURSOR CACHED").

Immediately after above gtt_truncate(65535) terminated, run following statement in another session, it will raise ORA-04025:

SQL (1124)> exec gtt_truncate(100);

  ORA-04025: maximum allowed library object lock allocated for BEGIN
  BEGIN
  IF (sys.is_vpd_enabled(sys.dictionary_obj_owner, sys.dictionary_obj_name, xdb.DBMS_XDBZ.IS_ENABLED_CONTENTS)) THEN
  xdb.XDB_PITRIG_PKG.pitrig_truncate(sys.dictionary_obj_owner, sys.dictionary_obj_name);
  ELSIF (sys.is_vpd_enabled(sys.dictionary_obj_owner, sys.dictionary_obj_name, xdb.DBMS_XDBZ.IS_ENABLED_RESMETADATA)) THEN
  xdb.XDB_PITRIG_PKG.pitrig_dropmetadata(sys.dictionary_obj_owner, sys.dictionary_obj_name);
  END IF;
  EXCEPTION
  WHEN OTHERS THEN
  null;
  END;
  END;  


8. Simple Truncate Trigger Reproducing


We will use a (almost) empty Truncate Trigger to demonstrate that ORA-04025 is caused by the existence of Truncate Trigger, but irrelevant to its substances.

Disable (or Drop) both Oracle Truncate Triggers:

alter trigger sys.AW_TRUNC_TRG disable;
alter trigger sys.XDB_PI_TRIG  disable;
Create a new trivial Trigger:

create or replace trigger SYS.KSUN_TEST_TRIG
before drop or truncate ON database 
  BEGIN
    IF 1=2 THEN
      null;
    END IF;
  END;
/
Configure session_cached_cursors to maximum value:

alter system set session_cached_cursors=65535 scope=spfile;
alter system set "_session_cached_instantiations"=1001 scope=spfile;
alter system set open_cursors=400 scope=spfile;
alter system set cursor_sharing=exact scope=spfile;
Run test:

SQL> exec gtt_truncate_job(2, 1e9);
Monitor v$db_object_cache.LOCKS:

column name format a80
set wrap off

SQL> select hash_value, locks, pins, locked_total, pinned_total, executions, name  --v.*
       from v$db_object_cache v
      where locks > 1000
        and (name like '%1=2%' or name like '%KSUN_TEST_TRIG%');
        
  HASH_VALUE  LOCKS  PINS LOCKED_TOTAL PINNED_TOTAL EXECUTIONS NAME
  ---------- ------ ----- ------------ ------------ ---------- -----------------------------------------------------
  2564248212  65514     0        65516        65517      65516 BEGIN     IF 1=2 THEN       null;     END IF;   END;
  2564248212  65514     0        65516            1      65515 BEGIN     IF 1=2 THEN       null;     END IF;   END;        
and alert.log shows:
        
ORA-04025: maximum allowed library object lock allocated for BEGIN
    IF 1=2 THEN
      null;
    END IF;
  END;

9. Hidden Parameter: _system_trig_enabled


Oracle provided a hidden Parameter:
   _system_trig_enabled   are system triggers enabled   default: TRUE
to disable system triggers.

If it is deactivated by:

  alter system set "_system_trig_enabled"=false;  
query below returns no more both trigger rows:

 select hash_value, locks, pins, locked_total, pinned_total, name  --v.*
       from v$db_object_cache v
      where locks > 0
        and (hash_value in (2219505151, 679830350) 
         or (name like '%xdb.DBMS_XDBZ.%' or name like '%aw_trunc_proc%'))
Both triggers are listed in following sql:

select a.obj#, a.sys_evts, b.name, a.*, b.*
  from sys.trigger$ a, sys.obj$ b
 where a.sys_evts > 0 and a.obj#=b.obj#
   and name in ('XDB_PI_TRIG', 'AW_TRUNC_TRG');
Hence they are effectively disabled with "_SYSTEM_TRIG_ENABLED=FALSE".
(see MOS Doc ID 244524.1: How to find triggers being disabled with _SYSTEM_TRIG_ENABLED parameter)


10. Test Code



create global temporary table my_gtt (id number) on commit preserve rows;

create or replace procedure gtt_truncate(p_cnt number) is
begin
 for i in 1..p_cnt loop
    execute immediate 'truncate table my_gtt';
    --dbms_lock.sleep(0.01);
  end loop;
end;
/

create or replace procedure gtt_truncate_job(p_job_cnt number, p_cnt number) as
  l_job_id pls_integer;
begin
  for i in 1..p_job_cnt loop
    dbms_job.submit(l_job_id, 'begin while true loop gtt_truncate('||p_cnt||'); end loop; end;');
  end loop;
  commit;
end;    
/

create or replace procedure clean_jobs as
begin
  for c in (select job from dba_jobs) loop
    begin
       dbms_job.remove (c.job);
    exception when others then null;
    end;
    commit;
  end loop;

  for c in (select d.job, d.sid, (select serial# from v$session where sid = d.sid) ser 
              from dba_jobs_running d) loop
    begin
      execute immediate
             'alter system kill session '''|| c.sid|| ',' || c.ser|| ''' immediate';
      dbms_job.remove (c.job);
    exception when others then null;
    end;
    commit;
  end loop;
  
  -- select * from dba_jobs;
  -- select * from dba_jobs_running;
end;
/

Wednesday, October 4, 2017

Result Cache:0 rows updated Invalidations (IV)

We have hit a new case of Result Cache Invalidations, in which result_cache Table has "0 rows updated". If we update another non result_cache Table in the same transaction, Result Cache becomes Invalid.

At the end of this Blog, we also give a Workaround.

This is the 4th case of Result Cache Invalidation, which can cause Result Cache: RC Latch Contention.
1. PL/SQL Function Result Cache Invalidation (I) (DML and Select for Update)
2. Result Cache: RC Latch Contention and RESULT_CACHE_MAX_SIZE (II))
3. Result Cache: RC Latch Contention and PL/SQL Exception Handler (III)
4. Result Cache:0 rows updated Invalidations (IV) 
Note: All tests are done in Oracle 11.2.0.4, 12.1.0.2, 12.2.0.1 on AIX, Solaris, Linux with 6 physical processors.

Update (25-Jan-2018): The reported issue accepted as Bug and public visible.
    Bug 26964029 : RESULT CACHE INVALIDATED EVEN THOUGH UPDATE ZERO ROWS


1. Test Setup



alter session set nls_date_format = 'yyyy-MON-dd hh24:mi:ss';

drop table noise_tab;

create table noise_tab as select level x, rpad('ABC', 100, 'X') y from dual connect by level <= 3; 

drop table rc_tab;

create table rc_tab as select level id, level*10 val from dual connect by level <= 5;

create or replace function get_val (p_id number) return number result_cache as
  l_val     number;
begin
  select val into l_val from rc_tab where id = p_id;
  return l_val;
end;
/

create or replace procedure run_test as
  l_val number;
begin
  for i in 1 .. 5 loop
    l_val := get_val(i);
  end loop;
end;
/


2. Test_1. Pure Test, No Invalid



----------------- Test 1. Pure Test, No Invalid -----------------

exec dbms_result_cache.flush;

exec run_test;

select creation_timestamp, type, status, name from v$result_cache_objects;

update rc_tab set val = val+1 where 1 = 2;

commit;

select creation_timestamp, type, status, name from v$result_cache_objects;


3. Test_2. Noise Test, Invalid



----------------- Test 2. Noise Test, Invalid -----------------

exec dbms_result_cache.flush;

exec run_test;

select creation_timestamp, type, status, name from v$result_cache_objects;

update rc_tab set val = val+1 where 1 = 2;

update noise_tab set y = 'xx' where x = 2;

commit;

select creation_timestamp, type, status, name from v$result_cache_objects;


4. Test Output



--============================= Test Output =============================--

SQL > ----------------- Test 1. Pure Test, No Invalid -----------------
SQL > exec dbms_result_cache.flush;

SQL > exec run_test;

SQL > select creation_timestamp, type, status, name from v$result_cache_objects;

CREATION_TIMESTAMP   TYPE       STATUS    NAME
-------------------- ---------- --------- -------------------------------------------------------------------
2017-OCT-04 13:38:34 Dependency Published K.RC_TAB
2017-OCT-04 13:38:34 Dependency Published K.GET_VAL
2017-OCT-04 13:38:34 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
2017-OCT-04 13:38:34 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
2017-OCT-04 13:38:34 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
2017-OCT-04 13:38:34 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
2017-OCT-04 13:38:34 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1

7 rows selected.

SQL > update rc_tab set val = val+1 where 1 = 2;

0 rows updated.

SQL > commit;

SQL > select creation_timestamp, type, status, name from v$result_cache_objects;

CREATION_TIMESTAMP   TYPE       STATUS    NAME
-------------------- ---------- --------- -------------------------------------------------------------------
2017-OCT-04 13:38:34 Dependency Published K.RC_TAB
2017-OCT-04 13:38:34 Dependency Published K.GET_VAL
2017-OCT-04 13:38:34 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
2017-OCT-04 13:38:34 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
2017-OCT-04 13:38:34 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
2017-OCT-04 13:38:34 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
2017-OCT-04 13:38:34 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1

7 rows selected.

SQL > ----------------- Test 2. Noise Test, Invalid -----------------

SQL > exec dbms_result_cache.flush;

SQL > exec run_test;

SQL > select creation_timestamp, type, status, name from v$result_cache_objects;

CREATION_TIMESTAMP   TYPE       STATUS    NAME
-------------------- ---------- --------- -------------------------------------------------------------------
2017-OCT-04 13:38:34 Dependency Published K.RC_TAB
2017-OCT-04 13:38:34 Dependency Published K.GET_VAL
2017-OCT-04 13:38:34 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
2017-OCT-04 13:38:34 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
2017-OCT-04 13:38:34 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
2017-OCT-04 13:38:34 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
2017-OCT-04 13:38:34 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1

7 rows selected.

SQL > update rc_tab set val = val+1 where 1 = 2;

0 rows updated.

SQL > update noise_tab set y = 'xx' where x = 2;

1 row updated.

SQL > commit;

SQL >
SQL > select creation_timestamp, type, status, name from v$result_cache_objects;

CREATION_TIMESTAMP   TYPE       STATUS    NAME
-------------------- ---------- --------- -------------------------------------------------------------------
2017-OCT-04 13:38:34 Dependency Published K.RC_TAB
2017-OCT-04 13:38:34 Dependency Published K.GET_VAL
2017-OCT-04 13:38:34 Result     Invalid   "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
2017-OCT-04 13:38:34 Result     Invalid   "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
2017-OCT-04 13:38:34 Result     Invalid   "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
2017-OCT-04 13:38:34 Result     Invalid   "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
2017-OCT-04 13:38:34 Result     Invalid   "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1

7 rows selected.


5. Workaround



exec dbms_result_cache.flush;

exec run_test;

select creation_timestamp, type, status, name from v$result_cache_objects;

--lock table rc_tab in ROW EXCLUSIVE mode;
lock table rc_tab in EXCLUSIVE mode;

begin
  if  1 = 2 then
     update rc_tab set val = val+1;
  end if;
end;
/

update noise_tab set y = 'xx' where x = 2;

commit;

select creation_timestamp, type, status, name from v$result_cache_objects;

--============================= Workaround Output =============================--

SQL > exec dbms_result_cache.flush;

SQL > exec run_test;

SQL > select creation_timestamp, type, status, name from v$result_cache_objects;

 CREATION_TI TYPE       STATUS    NAME
 ----------- ---------- --------- ---------------------------------------------------------------------------
 09-OCT-2017 Dependency Published K.RC_TAB
 09-OCT-2017 Dependency Published K.GET_VAL
 09-OCT-2017 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
 09-OCT-2017 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
 09-OCT-2017 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
 09-OCT-2017 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
 09-OCT-2017 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1

 7 rows selected.

SQL > lock table rc_tab in EXCLUSIVE mode;

 Table(s) Locked.

SQL > begin
   2    if  1 = 2 then
   3       update rc_tab set val = val+1;
   4    end if;
   5  end;
   6  /

SQL > update noise_tab set y = 'xx' where x = 2;

 1 row updated.

SQL > commit;

SQL > select creation_timestamp, type, status, name from v$result_cache_objects;

 CREATION_TI TYPE       STATUS    NAME
 ----------- ---------- --------- ---------------------------------------------------------------------------
 09-OCT-2017 Dependency Published K.RC_TAB
 09-OCT-2017 Dependency Published K.GET_VAL
 09-OCT-2017 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
 09-OCT-2017 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
 09-OCT-2017 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
 09-OCT-2017 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
 09-OCT-2017 Result     Published "K"."GET_VAL"::8."GET_VAL"#3048d2af80817a01 #1
 
 7 rows selected.


6. v$result_cache_statistics


V$RESULT_CACHE_STATISTICS contains 3 Rows reporting different kind of Invalidations. To recap all our previous discussion on triggering originals of Result Cache Invalidation, we can try to map those Rows to the originals.

ID 8. Invalidation Count: DML updates caused, see: PL/SQL Function Result Cache Invalidation (I) and Result Cache:0 rows updated Invalidations (IV)

ID 9. Delete Count Invalid:  PL/SQL RC Exception Handler related Result Cache, see: RC Latch Contention and PL/SQL Exception Handler (III)

ID 10. Delete Count Valid: Memory Limit Reached, see: Result Cache: RC Latch Contention and RESULT_CACHE_MAX_SIZE (II)

ID 11. Hash Chain Length:  length of hash chain. When no invalid, it is 1 or a constant number. When invalidate/create, it is a range.

If Result Cache experienced a heavy Invalidations, and got recreated, we can see the difference of "ID 5. Create Count Success" before and after recreated, and that of "ID 9. Delete Count Invalid" are quite close. In such case, if we rebuild the Invalidations by a few parallel sessions, latch free of "Result Cache: RC Latch" will appear at the top wait events. It could be fixed by either to flush Result Cache and rebuild from fresh, or use a single session to recreate them.


Update (18Mar2018)


In Blog: RESULT_CACHE hint expiration options , dependencies test showed one case of Result Cache Invalidation by "0 rows deleted".

drop table DEMO;
create table DEMO as select rownum id from xmltable('1 to 100000');
exec if dbms_result_cache.flush then dbms_output.put_line('Flushed.'); end if;

set autotrace on
select /*+ result_cache */ count(*) from DEMO;

set autotrace off
select * from v$result_cache_dependency;
  --
  --  RESULT_ID  DEPEND_ID  OBJECT_NO     CON_ID
  --  --------- ---------- ---------- ----------
  --          1          0    2305802          0
          
select id,type,status,name,cache_id,invalidations from v$result_cache_objects order by id;
  --  ID TYPE       STATUS    NAME                                          CACHE_ID                   INVALIDATIONS
  --  -- ---------- --------- --------------------------------------------- -------------------------- -------------
  --   0 Dependency Published K.DEMO                                        K.DEMO                                 0
  --   1 Result     Published select /*+ result_cache */ count(*) from DEMO 74s7myvzxca2u8jn4yfkftapdg             0

delete from DEMO where null is not null;
  --  0 rows deleted.
  
commit;

select * from v$result_cache_dependency;
  --  no rows selected
  
select id,type,status,name,cache_id,invalidations from v$result_cache_objects order by id;
  -- ID TYPE       STATUS    NAME                                          CACHE_ID                   INVALIDATIONS
  -- -- ---------- --------- --------------------------------------------- -------------------------- -------------
  --  0 Dependency Published K.DEMO                                        K.DEMO                                 1
  --  1 Result     Invalid   select /*+ result_cache */ count(*) from DEMO 3du8t8wtmx913djt9nvwm561sb             0
As we know, in order to record plan_table, "autotrace on" started a new transaction after first select statement with some DML like:

  DELETE FROM PLAN_TABLE WHERE STATEMENT_ID=:1
  insert into plan_table (statement_id, timestamp, operation ..
We can verify it by:

set autotrace off
commit;

select sum(s.sid), count(*)from v$transaction t, v$session s where t.addr=s.taddr and s.sid = sys.dbms_support.mysid;
  --  SUM(S.SID)   COUNT(*)
  --  ---------- ----------
  --                      0

set autotrace on

select dummy from dual;

select sum(s.sid), count(*)from v$transaction t, v$session s where t.addr=s.taddr and s.sid = sys.dbms_support.mysid;
  --  SUM(S.SID)   COUNT(*)
  --  ---------- ----------
  --         543          1
Removing "set autotrace on" and rerun the above test, there is no more such Invalid.

The original Blog got updated by a new Blog: Result cache invalidation caused by DML locks with deep analysis. Additionally it shows the Invalidation changes triggered by referential integrity in 12c, which needs to be further investigated.