Monday, March 27, 2017

Blog List

Oracle 12c PL/SQL Function in the WITH Clause: wrong result

In order to make PL/SQL Function run faster in SQL, Oracle 12c introduced a new feature to integrate PL/SQL Function in the SQL WITH Clause to eliminate SQL-PLSQL context switching.

This Blog is trying to demonstrate that the outcome of this new feature is varied with "ORDER BY" clause.

Note: Tested in Oracle 12.1.0.2.0 on AIX, Solaris, Linux.


1. Build Test



drop table base_tab cascade constraints;

create table base_tab
(
  id    number(12) not null,
  seq   number(9)                    
);

create index base_tab#ix_1 on base_tab (seq, id);

create index base_tab#ix_2 on base_tab (id);

drop table date_tab cascade constraints;

create table date_tab
(
  id          number(12),
  base_id     number(12),
  come_date   date      ,
  constraint date_tab#pk primary key (base_id, come_date) enable validate
) organization index;

insert into base_tab (id, seq) values (1, 11111);
insert into base_tab (id, seq) values (2, 22222);
insert into base_tab (id, seq) values (3, 33333);
insert into base_tab (id, seq) values (4, 4444);

insert into date_tab (id, base_id, come_date) values (11, 1, to_date('2010-01-11', 'yyyy-mm-dd'));
insert into date_tab (id, base_id, come_date) values (33, 3, to_date('2030-03-13', 'yyyy-mm-dd'));
insert into date_tab (id, base_id, come_date) values (44, 4, to_date('2040-04-14', 'yyyy-mm-dd'));

commit;


2. Run Test



--*** test 1: returns 2 rows without order by *** --

with 
  function get_max_date_sqlwith (p_id in number) return date is
    l_date date;
  begin
    select come_date into l_date from (
      select come_date from date_tab where base_id = p_id
       order by come_date desc
       ) where rownum = 1;
    return l_date;
  end;
select b.id
     ,(select get_max_date_sqlwith(b.id) from dual) cdate
  from base_tab b
 where rownum <= 2
--  order by b.id
/

 ID CDATE
--- -----------
  4 14-APR-2040
  1 11-JAN-2010


--*** test 2: returns only 1 row with order by *** --

with 
  function get_max_date_sqlwith (p_id in number) return date is
    l_date date;
  begin
    select come_date into l_date from (
      select come_date from date_tab where base_id = p_id
       order by come_date desc
       ) where rownum = 1;
    return l_date;
  end;
select b.id
     ,(select get_max_date_sqlwith(b.id) from dual) cdate
  from base_tab b
 where rownum <= 2
 order by b.id
/

 ID CDATE
--- -----------
  1 11-JAN-2010

--*** test 3 with_plsql hint: returns 2 rows without order by *** --

select /*+ with_plsql */ * from 
(with 
  function get_max_date_sqlwith (p_id in number) return date is
    l_date date;
  begin
     select come_date into l_date from (
      select come_date from date_tab t where t.base_id = p_id
       order by come_date desc
       ) where rownum = 1;
    return l_date;
  end;
select b.id, get_max_date_sqlwith(b.id) cdate 
  from base_tab b) x
 where rownum <= 2
--  order by x.id
/

 ID CDATE
--- -----------
  4 14-APR-2040
  1 11-JAN-2010

--*** test 4 with_plsql hint: returns only 1 row with order by *** --

select /*+ with_plsql */ * from 
(with 
  function get_max_date_sqlwith (p_id in number) return date is
    l_date date;
  begin
     select come_date into l_date from (
      select come_date from date_tab t where t.base_id = p_id
       order by come_date desc
       ) where rownum = 1;
    return l_date;
  end;
select b.id, get_max_date_sqlwith(b.id) cdate 
  from base_tab b) x
 where rownum <= 2
 order by x.id
/

 ID CDATE
--- -----------
  1 11-JAN-2010


3. Standalone PL/SQL function



--*** test 5: returns 2 rows without order by *** --

create or replace function get_max_date (p_id in number) return date is
  l_date date;
begin
  select come_date into l_date from (
    select come_date from date_tab where base_id = p_id
     order by come_date desc
     ) where rownum = 1;
  return l_date;
end;
/

select b.id
     ,(select get_max_date(b.id) from dual) cdate
  from base_tab b
 where rownum <= 2
--  order by b.id
/

 ID CDATE
--- -----------
  4 14-APR-2040
  1 11-JAN-2010

--*** test 6: returns 2 rows with order by *** --

select b.id
     ,(select get_max_date(b.id) from dual) cdate
  from base_tab b
 where rownum <= 2
 order by b.id
/

 ID CDATE
--- -----------
  1 11-JAN-2010
  2


4. 12c UDF Pragma PL/SQL function



--*** test 7: returns 2 rows without order by *** --

create or replace function get_max_date_UDF (p_id in number) return date is
  l_date date;
  PRAGMA UDF;
begin
  select come_date into l_date from (
    select come_date from date_tab where base_id = p_id
     order by come_date desc
     ) where rownum = 1;
  return l_date;
end;
/

select b.id
     ,(select get_max_date_UDF(b.id) from dual) cdate
  from base_tab b
 where rownum <= 2
--  order by b.id
/

 ID CDATE
--- -----------
  4 14-APR-2040
  1 11-JAN-2010
  
--*** test 8: returns 2 rows with order by *** --

select b.id
     ,(select get_max_date_UDF(b.id) from dual) cdate
  from base_tab b
 where rownum <= 2
 order by b.id
/

 ID CDATE
--- -----------
  1 11-JAN-2010
  2

Monday, March 20, 2017

Oracle abstract_lob Memory Leak

Oracle MOS:
    Bug 14521799 : XMLTYPE.GETCLOBVAL IN AN ANONYMOUS BLOCK VIA EXECUTE IMMEDIATE AND USING LEAKS
reveals a CLOB memory leak.

This Blog will try to demonstrate that it is an abstract_lob Memory Leak.

In Oracle 10g, "What's New in Large Objects?" wrote:
    A new column named 'ABSTRACT_LOBS' has been added to the V$TEMPORARY_LOBS table.
    This column displays the number of abstract LOBs accumulated in the current session.
    Abstract LOBs are temporary lobs returned from queries involving XMLType columns.

Note: all tests are done in Oracle 12.1.0.2.0. See appended Test Code. Case C1 is from MOS Bug 14521799.


1. Run following 3 Tests, each time in a new SQL Session.



SQL (111) > exec test_run_all(1024, 2);

PGA_MEM(MB): Used=7, Alloc=8, Max=11   --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=0
------ TestCase ------ C1
PGA_MEM(MB): Used=15, Alloc=16, Max=16 --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=1024
------ TestCase ------ C2
PGA_MEM(MB): Used=24, Alloc=25, Max=25 --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=2048
------ TestCase ------ C3
PGA_MEM(MB): Used=24, Alloc=25, Max=25 --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=2049
------ TestCase ------ C4
PGA_MEM(MB): Used=24, Alloc=26, Max=26 --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=2049
------ TestCase ------ C5
PGA_MEM(MB): Used=24, Alloc=26, Max=26 --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=2049


SQL (222) > exec test_run_all(1024, 1024);

PGA_MEM(MB): Used=7, Alloc=8, Max=11   --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=0
------ TestCase ------ C1
PGA_MEM(MB): Used=15, Alloc=16, Max=16 --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=1024
------ TestCase ------ C2
PGA_MEM(MB): Used=24, Alloc=25, Max=25 --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=2048
------ TestCase ------ C3
PGA_MEM(MB): Used=24, Alloc=26, Max=26 --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=2049
------ TestCase ------ C4
PGA_MEM(MB): Used=24, Alloc=26, Max=26 --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=2049
------ TestCase ------ C5
PGA_MEM(MB): Used=24, Alloc=26, Max=26 --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=2049


SQL (333) > exec test_run_all(1024, 1024*16);

PGA_MEM(MB): Used=7, Alloc=8, Max=11   --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=0
------ TestCase ------ C1
PGA_MEM(MB): Used=49, Alloc=50, Max=50 --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=1024
------ TestCase ------ C2
PGA_MEM(MB): Used=92, Alloc=93, Max=93 --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=2048
------ TestCase ------ C3
PGA_MEM(MB): Used=92, Alloc=93, Max=93 --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=2049
------ TestCase ------ C4
PGA_MEM(MB): Used=92, Alloc=93, Max=93 --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=2049
------ TestCase ------ C5
PGA_MEM(MB): Used=92, Alloc=93, Max=93 --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=2049

In Case C1 and C2, PGA_MEM is inflated, hence PGA memory leak; Augmented ABSTRACT_LOBS indicates that the leak is located in abstract_lobs, whereas in Case C3, C4 and C5, PGA_MEM and ABSTRACT_LOBS are constant.

Furthermore, LOB length 2 and 1024 consumes the same amount of memory, so there is certain minimum size for each ABSTRACT_LOB.


2. Open a new SQL Session, Run Case C1:



prompt -------- 1st Block --------

begin
 test_run(1, 2, 'C1');
 test_run(100, 2, 'C1');
 test_run(10000, 2, 'C1');
end;
/

prompt -------- 2nd Block --------

begin
 test_run(1, 2, 'C1');
 test_run(100, 2, 'C1');
 test_run(10000, 2, 'C1');
end;
/

-------- 1st Block --------

PGA_MEM(MB): Used=7, Alloc=8, Max=11   --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=1
PGA_MEM(MB): Used=7, Alloc=8, Max=11   --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=101
PGA_MEM(MB): Used=95, Alloc=96, Max=96 --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=10101

-------- 2nd Block --------

PGA_MEM(MB): Used=95, Alloc=96, Max=96 --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=1
PGA_MEM(MB): Used=95, Alloc=96, Max=96 --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=101
PGA_MEM(MB): Used=95, Alloc=96, Max=96 --- TEMPORARY_LOBS: CACHE_LOBS=0, NOCACHE_LOBS=0, ABSTRACT_LOBS=10101

The output shows that the PGA_MEM is not released (leak) between two Blocks, however ABSTRACT_LOBS count is reset.That means once the call if terminated, abstract_lobs in v$temporary_lobs is reset to 0, none abstract_lobs is exposed any more in this view, however their PGA memory is not released.


3. Test till ORA-04030


This test is trying to allocate more than 32GB PGA, and it will take about half hour till hitting ORA-04030 ERROR.

During the test, open another new SQL session, sample PGA memory by:

SQL(555) > exec pga_sampling(777, 3600);

See Blog: dbms_session.get_package_memory_utilization and limitations

Open one more new SQL session, and watch sampling result by (only partial result are shown):

SQL(666) > select * from process_memory_detail_v order by timestamp desc, bytes desc; 

CATEGORY  NAME                  HEAP_NAME         BYTES            ALLOCATION_COUNT 
-------   ---------------       ---------------   --------------   ---------------- 
                                                  
Other     permanent memory      kokltcr: creat    31,680,073,912       8,579,890
Other     free memory           kokltcr: creat       648,951,096       6,239,915
Other     free memory           session heap         616,868,032         445,136
Other     kokltcr: create clob  koh dur heap d       299,515,712       1,559,980

Open a new SQL Session, Run Case C1 and it will raise ORA-04030:
        
SQL(777) > exec test_run(1024*1024*2, 1024*16, 'C1');
------ TestCase ------ C1
BEGIN test_run(1024*1024*2, 1024*16, 'C1'); END;

*
ERROR at line 1:
ORA-04030: out of process memory when trying to allocate 4040 bytes (kokltcr: creat,kghsseg: kolaslCreateCtx)
ORA-06512: at "S.CRE_CLOB", line 10

The incident file looks like:

ORA-04030: out of process memory when trying to allocate 169040 bytes (pga heap,kgh stack)
ORA-04030: out of process memory when trying to allocate 4040 bytes (kokltcr: creat,kghsseg: kolaslCreateCtx)

========= Dump for incident 22642 (ORA 4030) ========
----- Beginning of Customized Incident Dump(s) -----
=======================================
TOP 10 MEMORY USES FOR THIS PROCESS
---------------------------------------

*** 2017-03-17 22:06:16.101
95%   30 GB, 8600973 chunks: "permanent memory          "  
         kokltcr: creat  ds=fffffd77ec09d628  dsprt=fffffd7ffbebb900
 2%  620 MB, 6255235 chunks: "free memory               "  
         kokltcr: creat  ds=fffffd77ec09d628  dsprt=fffffd7ffbebb900
 2%  590 MB, 446319 chunks: "free memory               "  
         session heap    ds=fffffd7ffc02d728  dsprt=fffffd7ffc358350
 1%  286 MB, 1563814 chunks: "kokltcr: create clob      "  
         koh dur heap d  ds=fffffd7ffbebb900  dsprt=fffffd7ffc02d728
 0%   62 MB, 781909 chunks: "kolraloc-1                "  
         kolr heap ds i  ds=fffffd7ffc048488  dsprt=fffffd7ffc02d728
 0%   61 MB, 3850 chunks: "kolrde_alloc              "  
         koh-kghu sessi  ds=fffffd7ffc05edd8  dsprt=fffffd7ffc02d728
 0%   48 MB, 781907 chunks: "kolrarfc:lobloc_kolrhte   "  
         kolr heap ds i  ds=fffffd7ffc048488  dsprt=fffffd7ffc02d728
 0%   27 MB, 195483 chunks: "free memory               "  
         koh dur heap d  ds=fffffd7ffbebb900  dsprt=fffffd7ffc02d728
 0%  828 KB, 17329 chunks: "free memory               "  
         kolr heap ds i  ds=fffffd7ffc048488  dsprt=fffffd7ffc02d728
 0%  505 KB,  34 chunks: "permanent memory          "  
         pga heap        ds=fffffd7ffc345640  dsprt=0

We can see that "30 GB, 8600973 chunks" are allocated as "permanent memory", that probably explains why it is not reclaimable and hence a memory leak.


4. Test Code



create or replace function cre_clob(p_clob_len number) return clob as
  l_clob clob;
  --l_blob blob;                    -- BLOB has similar behaviour
  --l_raw  raw(100) := '4b53554e';
begin
  --l_blob := l_raw;
  --return l_blob;
  
  l_clob := lpad('a', p_clob_len, 'b');
  return l_clob;
end;
/

create or replace type t_clob as object(c clob);
/

create or replace type t_clob_tab as table of clob;
/

create or replace procedure print_lob_and_mem as
 l_ret varchar2(400); 
 l_sid number := sys.dbms_support.mysid;
 l_mb  number := 1024*1024;
begin
  select 'PGA_MEM(MB): '||'Used='||round(p.pga_used_mem/l_mb)||', Alloc='||round(p.pga_alloc_mem/l_mb)||', Max='||round(p.pga_max_mem/l_mb)||
        ' --- TEMPORARY_LOBS: '||'CACHE_LOBS='||cache_lobs||', NOCACHE_LOBS='||nocache_lobs||', ABSTRACT_LOBS='||abstract_lobs
   into l_ret
   from v$process p, v$session s, v$temporary_lobs l
 where p.addr=s.paddr and s.sid = l.sid and s.sid = l_sid;
 dbms_output.put_line(l_ret);
end;
/

--exec print_lob_and_mem;

create or replace procedure test_run(p_cnt number, p_clob_len number, p_case varchar2) as
  l_stmt_var_c1 varchar2(100); 
  l_stmt_var_c2 varchar2(100); 
  l_stmt_var_c3 varchar2(100);
  l_stmt_var_c4 varchar2(100);
  l_clob        clob; 
  l_clob_t      t_clob     := t_clob(null);
  l_clob_tab    t_clob_tab := t_clob_tab();
begin 
  l_stmt_var_c1 := 'begin select cre_clob('||p_clob_len||') into :c1 from dual; end;';
  l_stmt_var_c2 := 'begin select cre_clob('||p_clob_len||') into :c1 from dual; end;'; 
  l_stmt_var_c3 := 'begin select t_clob(cre_clob('||p_clob_len||')) into :c1 from dual; end;';  
  l_stmt_var_c4 := 'begin select cre_clob('||p_clob_len||') bulk collect into :c1 from dual connect by level <= 1; end;'; 
  
  dbms_output.put_line('------ TestCase ------ '||p_case);
  
  for i in 1..p_cnt loop 
   case p_case
    when 'C1' then
      execute immediate l_stmt_var_c1 using out l_clob;          -- abstrace_lob increasing
        --dbms_lob.freetemporary(l_clob);           -- no help
        --dbms_session.free_unused_user_memory();   -- no help
      when 'C2' then
        execute immediate l_stmt_var_c2 using out l_clob_t.c;    -- abstrace_lob increasing
        l_clob := l_clob_t.c;
      when 'C3' then
        execute immediate l_stmt_var_c3 using out l_clob_t;      -- abstrace_lob constant
        l_clob := l_clob_t.c;
      when 'C4' then
        execute immediate l_stmt_var_c4 using out l_clob_tab;    -- abstrace_lob constant
        l_clob := l_clob_tab(1);
      when 'C5' then
         l_clob := cre_clob(p_clob_len);                         -- abstrace_lob constant
    end case;
  end loop; 
  
  print_lob_and_mem;
end; 
/

--exec test_run(100, 1024, 'C1');

create or replace procedure test_run_all(p_cnt number, p_clob_len number) as
begin
 print_lob_and_mem;
 test_run(p_cnt, p_clob_len, 'C1');
 test_run(p_cnt, p_clob_len, 'C2');
 test_run(p_cnt, p_clob_len, 'C3');
 test_run(p_cnt, p_clob_len, 'C4');
 test_run(p_cnt, p_clob_len, 'C5');
end;
/

PL/SQL Function Result Cache Invalidation

Oracle PL/SQL Function Result Cache is a global cross-session cached associative array, mapping from base data sources to function result, and stored in shared pool:

SQL(64) > select * from v$sgastat where name like '%Result Cache%';

POOL         NAME                            BYTES
------------ -------------------------- ----------
shared pool  Result Cache: Cache Mgr           256
shared pool  Result Cache: Memory Mgr          208
shared pool  Result Cache: State Objs        69920
shared pool  Result Cache                   159880

If changes to any of data sources are committed, the cached result becomes invalid by the DML session, and get rebuilt by the user session which is accessing the function. All build, invalidate and access are synchronized by a single latch:

SQL(854) > select * from v$latch where name = 'Result Cache: RC Latch';

Note: all tests are done in Oracle 12.1.0.2.0. See appended Test Code.

1. Build


Run:

SQL(64) > exec dbms_result_cache.flush;
SQL(64) > exec run_test;

List Result Cache:

SQL(64) > select id, type, status, name, namespace, cache_key
            from v$result_cache_objects ro;

Display dependencies:

SQL(64) > select count(*) from v$result_cache_dependency;

 COUNT(*)
---------
       51

SQL(64) > select distinct
                 ro.name,
                 dodep.object_name AS dep_object_name,
                 dodep.object_type AS object_type
            from v$result_cache_dependency rd,
                 v$result_cache_objects ro,
                 v$result_cache_objects rodep,
                 dba_objects dodep
           where     rd.result_id = ro.id
                 and rd.object_no = dodep.object_id
                 and rd.depend_id = rodep.id;


2. Invalidate



SQL(64) > update rc_tab_dep set dval=33 where did = 3;

SQL(64) > select s.sid, t.used_urec from v$transaction t, v$session s 
           where t.ses_addr=s.saddr and s.sid=sys.dbms_support.mysid;      
 
 SID  USED_UREC
---- ----------
  64          1 

SQL(64) > select * from v$result_cache_statistics
            where lower(name) like '%invalid%'; 

 ID NAME                   VALUE
--- ---------------------- -----
  8 Invalidation Count     0
  9 Delete Count Invalid   0

SQL(64) > select count(*) from v$result_cache_dependency;

 COUNT(*)
---------
       51

SQL(64) > commit;

SQL(64) > select * from v$result_cache_statistics
            where lower(name) like '%invalid%'; 

 ID NAME                   VALUE
--- ---------------------- -----
  8 Invalidation Count     17
  9 Delete Count Invalid   0
  
SQL(64) > select count(*) from v$result_cache_dependency;

 COUNT(*)
---------
       0  

The granularity of invalidation seems in table unit, even only one single row is updated, all result cache entries depending on that table are invalidate. Above test shows that "Invalidation Count" is increased from 0 to 17 (17 "GET_VAL" result cache entries).

3. Invalidate: select for update


Rebuild Cache, and then run a "select for update" for one row:

SQL(64) > exec dbms_result_cache.flush;
SQL(64) > exec run_test;

SQL(64) > select * from rc_tab_dep where did = 3 for update;

SQL(64) > select s.sid, t.used_urec from v$transaction t, v$session s 
           where t.ses_addr=s.saddr and s.sid=sys.dbms_support.mysid;      
 
 SID  USED_UREC
---- ----------
  64          1 

Get spid 13699 of test session (SID 64), open a Solaris window, run command:

$ dtrace -w -n 'pid$target::qesrcRO_Invalidate:entry {@[pid, ustack(10, 0)] = count(); stop(); exit(0);}' -p 13699 

Back to SQL Window, run:

SQL(64) > commit;

Session is hanging.

Solaris window prints out Stack Trace:

    oracle`qesrcRO_Invalidate
    oracle`qesrcDO_Invalidate+0x9c8
    oracle`qesrcCM_PreCmt_+0xd81
    oracle`ktcCommitTxn_new+0x2a7
    oracle`ktcCommitTxn+0x59
    oracle`ktdcmt+0x8b
    oracle`k2lcom+0x94
    oracle`k2send+0x4f3
    oracle`xctctl+0x62
    oracle`xctCommitTxn+0x2b8

Open a second SQL Window, build Result Cache for function get_val_2, which is irrelevant to function get_val:

SQL(512) > exec run_test_2;

It hangs on Result Cache: RC Latch.

On a third SQL Window, watch the blocking:

SQL(1024) > select sid, blocker_sid, blocker_is_valid, wait_event_text, p2 from v$wait_chains;

  SID BLOCKER_SID BLOCK WAIT_EVENT_TEXT    P2
----- ----------- ----- --------------- -----
  512          64 TRUE  latch free        559
   64             FALSE

SQL(1024) > select * from v$latchholder;

 PID  SID LADDR            NAME                       GETS
---- ---- ---------------- ---------------------- --------
  25   64 00000000600572B0 Result Cache: RC Latch  15564353

On a fourth SQL Window, make select for update on another row:

SQL(768) > select * from rc_tab_dep where did = 5 for update;

       DID       DVAL
---------- ----------
         5         50
1 row selected.

SQL(768) > commit;

The commit is also hanging on "latch free" of 'Result Cache: RC Latch'.

And all other sessions which are accessing or updating Result Cache are waiting for the same latch free (ksl_get_shared_latch).

In this test, we started one transaction by "select for update", but did not update any row, however, "commit" triggered a call to "qesrcRO_Invalidate", hence held "RC Latch". Any other later session which requires this latch is waiting for "latch free".

Furthermore, query on any one of
  v$result_cache_objects
  v$result_cache_dependency
  v$result_cache_statistics

is also pending on "RC Latch" "latch free".

The above Stack Trace shows that the transaction user session takes a detour to visit Result Cache along the commit code path in order to perform the invalidation before publishing the news to the world. Therefore, Function Result Cache is not free of charge. It demands the resources to maintain the database wide consistence, and thus PL/SQL Function Result Cache (in Oracle Database PL/SQL Language Reference) said:

Oracle Database automatically detects all data sources (tables and views) that are queried while a result-cached function is running. If changes to any of these data sources are committed, the cached result becomes invalid and must be recomputed. The best candidates for result-caching are functions that are invoked frequently but depend on information that changes infrequently or never.

4. Result Cache Hidden Parameters


There are 5 hidden parameters:
  _result_cache_auto_time_distance (default 300)
  _result_cache_auto_dml_monitoring_slots (default 4)
  _result_cache_auto_dml_monitoring_duration (default 15)
  _result_cache_auto_dml_threshold (default 16)
  _result_cache_auto_dml_trend_threshold (default 20)

In verbatim text, they sound like something to regulate the refresh of Result Cache or its Dynamic Performance Views. But it is not clear how to make the test cases to detect their usage.

5. Test Code



drop table rc_tab;

drop table rc_tab_dep;

drop table rc_tab_2;

create table rc_tab (id number, val number);

create table rc_tab_dep (did number, dval number);

create table rc_tab_2 (id number, val number);

insert into rc_tab select level, level*10 from dual connect by level <= 17;

insert into rc_tab_dep select level, level*10 from dual connect by level <= 17;

insert into rc_tab_2 select level, level*10 from dual connect by level <= 13;

commit;

create or replace function get_val_dep (p_did number) return number as
  l_dval_dep number;
begin
  select dval into l_dval_dep from rc_tab_dep where did = p_did;
  return l_dval_dep;
end;
/

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

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

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

create or replace procedure run_test_2 as
  l_val number;
begin
  for i in 1 .. 13 loop
    l_val := get_val_2(i);
  end loop;
end;
/

Friday, February 3, 2017

Oracle JVM Java OutOfMemoryError and lazy GC

Java Stored Procedure running in Oracle RDBMS embedded JVM can throw OutOfMemoryError in connection with lazy GC.
All tests are done in Oracle 12.1.0.2.0.


1. Test Setup



create or replace java source named S."OracleJavaOOM512" as
public class OracleJavaOOM512 {
  // final static byte[] SB = new byte[1024*1024*500];  // workaround
  public static void createBuffer(int bufferSize) {
    // OracleRuntime.setMaxRunspaceSize(1024*1024*1024) // set 1GB, no help
    byte[] SB = new byte[bufferSize];
  }
}
/

alter JAVA CLASS S."OracleJavaOOM512" COMPILE;

create or replace procedure createBuffer512(p_buffer_size in number) is language java
name 'OracleJavaOOM512.createBuffer(int)';
/

create or replace procedure createBuffer512_loop 
  (p_cnt number, p_start number, p_delta number, p_sleep_seconds number := 0) as
  l_size number := p_start;
begin
  for i in 1..p_cnt loop
    dbms_lock.sleep(p_sleep_seconds);
    dbms_output.put_line('Buffer Size (MB) = '||l_size);
    createBuffer512(1024*1024*l_size);
    l_size := l_size + p_delta;
  end loop;
end;
/


2. Tests


Run first test to allocate 511MB:

Sqlplus > exec createBuffer512(1024*1024*511);
    PL/SQL procedure successfully completed

succeeded without Error.

Run second test for 512MB:

Sqlplus > exec createBuffer512(1024*1024*512);
    ORA-29532: Java call terminated by uncaught Java exception: java.lang.OutOfMemoryError
    ORA-06512: at "S.CREATEBUFFER512", line 1

It hits java.lang.OutOfMemoryError, which probably indicates that the JVM is limited by 512MB.

Calling OracleRuntime.setMaxRunspaceSize(1024*1024*1024) to set MaxRunspaceSize to 1GB does not help.

If interested, make a 29532 event trace:

Sqlplus > alter session set max_dump_file_size = UNLIMITED;
Sqlplus > alter session set tracefile_identifier='OOM512_29532'; 
Sqlplus > alter session set events '29532 trace name errorstack level 3'; 
Sqlplus > exec createBuffer512(1024*1024*512);
    ORA-29532: Java call terminated by uncaught Java exception: java.lang.OutOfMemoryError

Open a new Oracle session, run third test case, which gradually allocates memory from 1MB to 511MB, each time increases 1MB per call.

Sqlplus > exec createBuffer512_loop(511, 1, 1);

    Buffer Size (MB) = 1
    Buffer Size (MB) = 2
    ...
    Buffer Size (MB) = 265
    Buffer Size (MB) = 266
    BEGIN createBuffer512_loop(511); END;
    
    ERROR at line 1:
    ORA-29532: Java call terminated by uncaught Java exception: java.lang.OutOfMemoryError
    ORA-04030: out of process memory when trying to allocate 283285584 bytes (joxu pga heap,f:OldSpace)
    ORA-06512: at "S.CREATEBUFFER512", line 1
    ORA-06512: at "S.CREATEBUFFER512_LOOP", line 5

It throws OutOfMemoryError when allocating 266MB (the number can be varied, but before reaching 511), and generates trace file and incident file.


3. Oracle JVM Garbage Collection


Oracle 12c Document: Database Java Developer's Guide Chapter 1 Introduction to Java in Oracle Database, Section Memory Spaces Management depicts a 3-Layer Java memory Management:
  1.  New Space in Call space
  2.  Old Space in Call space
  3.  Session Memory in Session space
and 3 corresponding garbage collection algorithms:
  1.  Generational scavenging for short-lived objects
  2.  Mark and lazy sweep collection for objects that exist for the life of a single call
  3.  Copying collector for long-lived objects, that is, objects that live across calls within a session
It also mentions that Oracle JVM Garbage collection uses Oracle Database scheduling facilities.

Book: Oracle Database Programming using Java and Web Services (Kuassi Mensah) Section 2.2 Java Memory Management (Page 41-51) reveals internal GC mechanisms (probably written for Oracle 10g).

Garbage Collection Techniques
  The OracleJVM memory manager uses a set of GC techniques for its various memory structures (listed in Table 2.1), including the generational GC, mark-sweep GC, and copy GC.

These 3 GC techniques in Oracle 10g look similar to GC algorithms in 12c.

Mark-sweep GC
  A mark-sweep GC consists of two phases: (1) the mark phase (garbage detection) and the (2) sweep phase (Garbage Collection). The sweep phase places the “garbaged” memory on the freelists. The allocation is serviced out of the freelists. Lazy sweeping is a variation technique that marks objects normally, but, in the sweep phase, leaves it up to the allocation phase to determine whether the marked objects are live (no need to reclaim) or not (can be reclaimed), rather than sweeping the object memory at that time.

Java Memory Areas
  Oldspace is an object memory used for holding long-lived or large objects (i.e., larger than 1-K Bytes) for the duration of a call. It is cleaned up using Marksweep GC (described earlier) for large objects; it uses a variation of “lazy sweeping” for small objects.

Looking up Table 2.1 "Summary of OracleJVM Memory Structure" (Page 50), since our test allocation is more than 1-K Bytes, it should be allocated into Old-space using Buddy memory allocation, and garbage collected by Mark-Sweep.


4. Reasoning


The error message in Sqlplus Window indicates that memory problem is caused by:
    joxu pga heap,f:OldSpace
which also appears in trace file.

An excerpt of incident file looks like:

=======================================
TOP 10 MEMORY USES FOR THIS PROCESS
---------------------------------------
84%   91 MB,  17 chunks: "f:OldSpace                "  JAVA
         joxu pga heap   ds=fffffd7ffbe8bcc8  dsprt=fffffd7ffc0a9078
 2% 2432 KB,  92 chunks: "free memory               "  
         pga heap        ds=fffffd7ffc345640  dsprt=0
 2% 1767 KB, 437 chunks: "free memory               "  
         session heap    ds=fffffd7ffc02d728  dsprt=fffffd7ffc358350
 1% 1064 KB,   2 chunks: "permanent memory          "  JAVA
         joxu pga heap   ds=fffffd7ffbe8bcc8  dsprt=fffffd7ffc0a9078
...
=======================================
PRIVATE MEMORY SUMMARY FOR THIS PROCESS
---------------------------------------
******************************************************
PRIVATE HEAP SUMMARY DUMP
108 MB total:
   104 MB commented, 519 KB permanent
  4125 KB free (0 KB in empty extents),
      97 MB,   1 heap:    "joxp heap      "            2315 KB free held
    8894 KB,   1 heap:    "session heap   "            679 KB free held
------------------------------------------------------
Summary of subheaps at depth 1
104 MB total:
   101 MB commented, 952 KB permanent
  1814 KB free (25 KB in empty extents),
      94 MB,   1 heap:    "joxu pga heap  "           
------------------------------------------------------
Summary of subheaps at depth 2
99 MB total:
    97 MB commented, 1408 KB permanent
   272 KB free (0 KB in empty extents),
      91 MB,  17 chunks:  "f:OldSpace                "

=========================================
REAL-FREE ALLOCATOR DUMP FOR THIS PROCESS
-----------------------------------------
 
Dump of Real-Free Memory Allocator Heap [0xfffffd7ffbfed000]
mag=0xfefe0001 flg=0x5000003 fds=0x0 blksz=65536
blkdstbl=0xfffffd7ffbfed010, iniblk=523264 maxblk=524288 numsegs=255
In-use num=133 siz=112984064, Freeable num=224 siz=2914910208, Free num=15 siz=21889024

...
-------------------------
Top 10 processes:
-------------------------
(percentage is of 27 GB total allocated memory)
99% pid 66: 105 MB used of 27 GB allocated (27 GB freeable) <= CURRENT PROC
 0% pid 11: 7792 KB used of 8294 KB allocated 
...
======================================================
ESTIMATED MEMORY USES FOR ALL PROCESSES
------------------------------------------------------
(from 1 snapshot out of 67 processes)
99%     27 GB,   66 processes: "unsnapshotted               "   
 1%    172 MB,    1 process  : "free memory                 "   
           pga heap             95 chunks
 0%     93 MB,    1 process  : "f:OldSpace                  "  JAVA
...

******************* Dumping process map ****************
    Start addr     -      End addr       Size    PgSz       Shmid    Perms  Object name
------------------ -  ----------------- -------  ----     ---------- ------------------------------
...
        0x80000000 -        0x1af000000 4964352K    4K     0x40000039 rwxs-  [ anon ] osm 
...
0xfffffd792326d000 - 0xfffffd79333bd000 263488K    4K     0xffffffff rw---  [ anon ] 
0xfffffd793355d000 - 0xfffffd794365d000 263168K    4K     0xffffffff rw---  [ anon ] 
0xfffffd794374d000 - 0xfffffd795374d000 262144K    4K     0xffffffff rw---  [ anon ] 
0xfffffd795377d000 - 0xfffffd796293d000 247552K    4K     0xffffffff rw---  [ anon ] 
0xfffffd7962aad000 - 0xfffffd7971b6d000 246528K    4K     0xffffffff rw---  [ anon ]
...

There are about 30GB segments are marked as:
   rw--- [ anon ]
which are session's PGA.

Above output shows:
   105 MB used of 27 GB allocated (27 GB freeable) <= CURRENT PROC
among 27 GB allocated, almost all of which is freeable.

However due to Oracle JVM lazy GC, they are not immediately released, and eventually leads to:
   ORA-04030: out of process memory when trying to allocate 283285584 bytes (joxu pga heap,f:OldSpace)

(By the way, biggest chunk 4964352K is SGA, created with Optimized Shared Memory (OSM) available since Oracle 12c when sga_max_size is not configured, or is set greater than the computed value.
See ISM, DISM in Oracle 11g Blog: PGA, SGA space usage watching from UNIX)

Concerning the freeable memory, V$PROCESS_MEMORY documentation said:

    For the "Freeable" category, Column ALLOCATED is the amount of free PGA memory eligible to be released to the operating system.

Note that OutOfMemoryError process still holds the "Freeable" memory and does not immediately put them back to freelists since the process is still alive. It takes time for GC to reclaim them gradually. If the process (Oracle session) terminated (disconnected), it is immediately reusable by other processes.

You can query V$PROCESS_MEMORY or V$PROCESS to monitor it.

Crosschecking with Solaris pmap output:

oracle@test$ pmap -x 1122
1122:  testdb (LOCAL=NO)
         Address     Kbytes        RSS       Anon     Locked Mode   Mapped File
...         
0000000080000000    4964352    4964352          -    4964352 rwxs-    [ osm shmid=0x40000039 ]
...
FFFFFD785FC1D000     306816     306812     306812          - rw---    [ anon ]
FFFFFD787296D000     305792     305788     305788          - rw---    [ anon ]
FFFFFD78854BD000     297472     297452     297452          - rw---    [ anon ]
FFFFFD7897F1D000     296448     296412     296412          - rw---    [ anon ]
FFFFFD78AA76D000     295424     295420     295420          - rw---    [ anon ]
FFFFFD78BCECD000     294336     294332     294332          - rw---    [ anon ]
...
---------------- ---------- ---------- ---------- ----------
        total Kb   31990020   31933340   26615772    4982784

(you can even use Solaris MDB Formatting Dcmds to display content at one above virtual address space)

Incident file and pmap output show that the majority of memory are allocated as "anon" pages, but not removed from the mappings, which means that there are more mmap than munmap.

We can see this un-matching mmap and munmap with:

oracle@test$ truss -cp -t mmap,munmap 1122

syscall               seconds   calls  errors
mmap                     .056    1014
munmap                  6.447      68

The output shows that munmap is 1716 (=(6.447/68)/(0.056/1014)) times expensive. That is probably one reason why the GC strategy is lazy delayed.

or watch the details by:

oracle@test$ truss -p -t mmap,munmap 1122  

...
mmap(0xFFFFFD7C6E8ED000, 202375168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANON, 4294967295, 0) = 0xFFFFFD7C6E8ED000
mmap(0xFFFFFD7C625ED000, 203423744, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANON, 4294967295, 0) = 0xFFFFFD7C625ED000
mmap(0xFFFFFD7C561FD000, 204537856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANON, 4294967295, 0) = 0xFFFFFD7C561FD000
...
mmap(0xFFFFFD7A43ACD000, 243924992, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANON, 4294967295, 0) = 0xFFFFFD7A43ACD000
mmap(0xFFFFFD7A34F7D000, 244973568, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANON, 4294967295, 0) = 0xFFFFFD7A34F7D000
mmap(0xFFFFFD7A2632D000, 246022144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANON, 4294967295, 0) = 0xFFFFFD7A2632D000
mmap(0xFFFFFD7A175DD000, 247136256, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANON, 4294967295, 0) = 0xFFFFFD7A175DD000
munmap(0xFFFFFD7A2632D000, 246022144)           = 0
munmap(0xFFFFFD7A34F7D000, 244973568)           = 0
munmap(0xFFFFFD7A43ACD000, 243924992)           = 0
...

It shows that not all mapped chunks are un-mapped, and unmapping occurs in reverse order (last mapping is first unmapped).

With Solaris dtrace, we can count number of mmap and munmap, as well as sum of their amount (in MB). The large difference between mmap and munmap is probably pointing to the leaked memory.

oracle@test$ dtrace -n 'syscall::mmap:entry,syscall::munmap:entry/pid==1122 && arg0 != 0x0/
{
 @CNT[probefunc] = count();
 @SUM[probefunc] = sum(arg1/1024/1024);
}
END
{
 printf("\n%10s %10s  %10s\n",  "NAME", "COUNT", "SUM(MB)");
 printa(  "%10s %10@d %10@d\n",         @CNT,   @SUM);
}'

------------ output -------------
      NAME      COUNT     SUM(MB)
    munmap         44       3987
      mmap        404      32400

There are 360 (404-44) more mmap, 32400 MB allocated, but only 3987 MB de-allocated. which results in 28413 (32400-3987) MB un-released allocation.

Other dtrace commands can help us understand largeobj (oldSpace) allocation and GC activity.

oracle@test$ dtrace -n 'pid$target::eoa_new_largeobj:entry {@[pid, ustack(40, 0)] = count(); }' -p 1122

oracle@test$ dtrace -n 'pid$target::eoa_oldspace_gc_scan_xt:entry {@[pid, ustack(40, 0)] = count(); }' -p 1122

Two tests below have no problem:

Sqlplus > exec createBuffer512_loop(511, 511, -1);

Sqlplus > exec createBuffer512_loop(511, 511, 0);

Both above tests propose us a quick workaround by introducing a class (static) variable and setting it to a enough big value as follows:
    final static byte[] SB = new byte[1024*1024*500];
Note that java class variable in Java Stored Procedure is stateful object, which survives across Java calls in the same RDBMS session (like PL/SQL Package variable), and can be reset by dbms_java.endsession (dbms_session.reset_package).


5. Oracle Performance Views


Query GC statistics by:

select s.program, s.sid, n.name p_name, t.value, round(t.value/1e6, 2) mb
from v$session s, v$sesstat t, v$statname n 
where 1=1
  and s.sid=t.sid 
  and n.statistic# = t.statistic# 
  and name = 'java call heap gc count'
  and s.sid in (920);

Populate v$process_memory_detail by:
(see dbms_session.get_package_memory_utilization and limitations)

Sqlplus > exec pga_sampling(920, 120, 1);

and then run query:

select round(bytes/1024/1024, 2) mb, v.* from  process_memory_detail_v v
where 1=1
  and name in ('f:OldSpace', 'free memory')
  and round(bytes/1024/1024, 2) > 10
order by timestamp;

Oracle performance views v$process, v$process_memory reports "freeable" memory, whereas view:
   v$sesstat, v$active_session_history, dba_hist_active_sess_history
seem having difficult to record the real figures, probably due to "freeable" memory (27GB) which is signaled by the 27 GB "unsnapshotted" line in the incident file:
   99% 27 GB, 66 processes: "unsnapshotted "


6. Linux Test


All above tests are performed on Solaris. Repeat the same test on a Linux with 24GB of total usable memory.

Sqlplus > exec createBuffer512_loop(511, 1, 1);

    ORA-03113: end-of-file on communication channel
    Process ID: 32251

There are no trace file or incident file generated. Checking dmesg out, it looks like that process is killed by PSP0 (call oom-killer) when reaching system limit of 24GB, but before reaching 32GB PGA limit.

[08:07:36] ora_psp0_td invoked oom-killer: gfp_mask=0x201da, order=0, oom_adj=0, oom_score_adj=0
[08:07:36] ora_psp0_td cpuset=/ mems_allowed=0
[08:07:36] Pid: 23201, comm: ora_psp0_td Not tainted 2.6.32-642.6.2.el6.x86_64 #1
[08:07:36] Call Trace:
[08:07:36] [] ? dump_header+0x90/0x1b0
[08:07:36] [] ? security_real_capable_noaudit+0x3c/0x70
[08:07:36] [] ? oom_kill_process+0x82/0x2a0
[08:07:36] [] ? select_bad_process+0xe1/0x120
[08:07:36] [] ? out_of_memory+0x220/0x3c0
[08:07:36] [] ? __alloc_pages_nodemask+0x93c/0x950
[08:07:36] [] ? alloc_pages_current+0xaa/0x110
[08:07:36] [] ? __page_cache_alloc+0x87/0x90
[08:07:36] [] ? find_get_page+0x1e/0xa0
[08:07:36] [] ? filemap_fault+0x1a7/0x500
[08:07:36] [] ? __do_fault+0x54/0x530
[08:07:36] [] ? handle_pte_fault+0xf7/0xb20
[08:07:36] [] ? sem_lock+0x6c/0x130
[08:07:36] [] ? sys_semtimedop+0x338/0xae0
[08:07:36] [] ? handle_mm_fault+0x299/0x3d0
[08:07:36] [] ? __do_page_fault+0x146/0x500
[08:07:36] [] ? wait_consider_task+0x7e6/0xb20
[08:07:36] [] ? read_tsc+0x9/0x10
[08:07:36] [] ? ktime_get_ts+0xbf/0x100
[08:07:36] [] ? poll_select_copy_remaining+0xf8/0x150
[08:07:36] [] ? do_page_fault+0x3e/0xa0
[08:07:36] [] ? page_fault+0x25/0x30
...
[08:07:36] Out of memory: Kill process 32251 (oracle_32251_td) score 619 or sacrifice child
[08:07:36] Killed process 32251, UID 100, (oracle_32251_td) total-vm:20111724kB, anon-rss:15083248kB, file-rss:215188kB
[08:07:36] oracle_32251_td: page allocation failure. order:0, mode:0x280da
[08:07:36] Pid: 32251, comm: oracle_32251_td Not tainted 2.6.32-642.6.2.el6.x86_64 #1

Note Buddy memory request "order=0", and oom-killer reason: "score 619"


References


1. Database Java Developer's Guide Chapter 1 Introduction to Java in Oracle Database, Section Memory Spaces Management (Old Space)

2.Oracle Database Programming using Java and Web Services (Kuassi Mensah) Section 2.2 Java Memory Management (Page 41-49)

3. dbms_session.get_package_memory_utilization and limitations

4.Oracle Java OutOfMemoryError (11g Blog, no more reproducible in 12c)

5. PGA, SGA space usage watching from UNIX

Monday, January 23, 2017

ORA-600 [4156] SAVEPOINT and PL/SQL Exception Handling

Oracle MOS (RDBMS 10.2.0.4)
     Bug 9471070 : ORA-600 [4156] GENERATED WITH EXECUTE IMMEDIATE AND SAVEPOINT
contains a TEST CASE:

create table t(id number, label varchar2(10));
insert into t(id, label) values(1, 'label');
commit;

-- ORIGINAL --
begin
  savepoint sp;
  update t set label = label where id = 1;
  execute immediate '
    begin
      raise_application_error(-20000, ''error-sp'');
    exception
      when others then
        rollback to savepoint sp;
        update t set label = label where id = 1;
        raise;
    end;';
end;
/

which outputs the Error:

ORA-00600: internal error code, arguments: [4156], [], [], [], [], [], [], [], [], [], [], []

and DIAGNOSTIC ANALYSIS wrote:

The ORA-600[4156] error means that we are checking the savepoint undo block address while rolling back the transaction. The savepoint does not currently belong to this transaction. So the operation in this testcase does not seem supported, but there is no documentation on this behavior.

In this Blog, we will try to deduce 4 further Variants which all generate the same error, and demonstrate that neither Exception Handler nor Execute Immediate is a necessary condition of such error.

In the original Test Case,

raise_application_error(-20000, ''error-sp''); 

is only to transfer code flow to exception handler, remove it, we get:

-- VARIANT-1 --
begin
  savepoint sp;
  update t set label = label where id = 1;
  execute immediate '
    begin
      rollback to savepoint sp;
      update t set label = label where id = 1;
      raise_application_error(-20000, ''error-sp'');
    end;';
end;
/

Unshelling EXECUTE IMMEDIATE, it is a derived Test Case:

-- VARIANT-2 --
savepoint sp;
update t set label = label where id = 1;           
begin
  rollback to savepoint sp;
  update t set label = label where id = 1;
  raise_application_error(-20000, 'error-sp');
end;
/

all generate the same ORA-600 [4156].

Applying the equivalent transformation to factor out:

raise_application_error(-20000, 'error-sp'); 

(See Book Expert Oracle Database Architecture (3rd Edition, Thomas Kyte, Darl Kuhn) - Chapter 8, Section: Atomicity (Page 277-283))

Savepoint sp;
statement;
If error then rollback to sp;

We render the Test Case as:

-- VARIANT-3 --
savepoint sp;
update t set label = label where id = 1;   
savepoint spx;        
begin
  rollback to savepoint sp;
  update t set label = label where id = 1;
  rollback to savepoint spx;    -- spx cleared away by "rollback to savepoint sp;"
  dbms_output.put_line('error-sp');
end;
/

it results in the same error:

ORA-00600: internal error code, arguments: [4156], [], [], [], [], [], [], [], [], [], [], []
ORA-01086: savepoint 'SPX' never established in this session or is invalid

which contains a second line indicating that the error is related to savepoint 'SPX'.

None of Exception Handler and Execute Immediate is involved in the above Test Code.

All above Test Cases generate the similar incident dumps as follows:

kturRollbackToSavepoint perm undokturRollbackToSavepoint savepoint uba: 0x00c0525c.0708.30 xid: 0x0051.021.00002fcd
kturRollbackToSavepoint current call savepoint: ksucaspt num: 1737  uba: 0x00c0525c.0708.30


Reasoning


Looking at the last transformed code,
  "rollback to savepoint sp"
jumps back to line
  "savepoint sp"
and hence scopes out line "savepoint spx" and make savepoint 'SPX' invisible. When running to the line "rollback to savepoint spx", 'SPX' is not able to find, and therefore the error: never established.

The graphic below depicts the partial intersection of savepoints' pair, which erases the 'savepoint spx' with runtime "goto" logic and makes it never reachable. A savepoints' pair is valid if they are pairwise disjoint, or one is a proper subset of another.

|------> savepoint sp;
|        update t set label = label where id = 1;   
|  |---> savepoint spx;        
|  |     begin
|--|---->  rollback to savepoint sp;
   |       update t set label = label where id = 1;
   |--->   rollback to savepoint spx; 
         end;

With the aid of above deliberate code transformations, we obtained 4 versions of code which produced the same error. It is not clear if they are all semantically equivalent, and internally identical.

Referring back to DIAGNOSTIC ANALYSIS again, it said:
   So the operation in this testcase does not seem supported, but there is no documentation on this behavior.

All tests are done in Oracle 11.2.0.4.0 and 12.1.0.2.0.

Implicit Savepoint and Execute immediate 


When unshelling EXECUTE IMMEDIATE in the second transformation, outermost BEGIN END is intentionally removed.

Without removing it, the equivalent code looks like:

savepoint spx;
begin
  savepoint sp;
  update t set label = label where id = 1;           
  begin
    rollback to savepoint sp;
    update t set label = label where id = 1;
    rollback to savepoint spx; 
    dbms_output.put_line('error-sp');
  end;
end;
/
--If error then rollback to spx;

It runs without error since there does not exist savepoint partially overlapping ('SP' is proper subset of 'SPX').

It seems that Oracle sets an implicit savepoint before EXECUTE IMMEDIATE to perform the dynamic statement parsing and executing. Factoring out EXECUTE IMMEDIATE by the same principle, we get a fourth variant which hits the same error:

-- VARIANT-4 --
begin
  savepoint sp;
  update t set label = label where id = 1;
  savepoint spx;
  execute immediate '
    begin
        rollback to savepoint sp;
        update t set label = label where id = 1;
        rollback to savepoint spx;
        dbms_output.put_line(''error-sp'');
    end;';
end;
/
--If error then rollback to spx;

Oracle Statement-Level Rollbacks said:
   Before executing any SQL statement, Oracle marks an implicit savepoint (not available to you).

ORA-01086


One ORA-01086 can be simply reproduced by:

SQL> rollback to savepoint spy;
  ORA-01086: savepoint 'SPY' never established in this session or is invalid


Savepoint Watching


Savepoint is probably implemented as Stack push and pop operations.

Looking ORA-600 [4156] trace and incident dumps, stack trace shows that subroutine psdtsv calls xctsav to set Savepoint, ksupop to popup Savepoint and xctrsp to rollback savepoint..

One can also run code below,

begin
  for i in 1..1000000 loop
    dbms_transaction.savepoint('sp'||i);
    dbms_transaction.rollback_savepoint('sp'||i);
  end loop;
end;
/

and print process stack trace by UNIX command, for example, Solaris, pstack.

References

1. Expert Oracle Database Architecture(Page 277-283)
2. Oracle Statement-Level Rollbacks
3. SQL DML Exceptions, Rollbacks and PL/SQL Exception Handlers

Tuesday, November 1, 2016

"library cache: mutex X" and Application Context

Heavy Event: "library cache: mutex X" is observed when Application Context is frequently changed. The application is using Oracle Virtual Private Database to regulate data access with driving application context, which determines which policy group is in effect for each use case.

Run the appended Test Code by launching 4 Jobs:
  exec ctx_set_jobs(4);

Monitor Job sessions:

select sid, program, event, p1text, p1, p2text, p2, p3text, p3
  from v$session where program like '%(J%';

  SID PROGRAM              EVENT                     P1TEXT          P1 P2TEXT             P2 P3TEXT                P3
----- -------------------- ------------------------- ------ ----------- ------ -------------- ------ -----------------
   38 oracle@testdb (J003) library cache: mutex X    idn     1317011825 value   3968549781504 where   9041305591414788
  890 oracle@testdb (J000) library cache: mutex X    idn     1317011825 value    163208757248 where   9041305591414874
  924 oracle@testdb (J001) library cache: mutex X    idn     1317011825 value   4556960301056 where   9041305591414874
 1061 oracle@testdb (J002) library cache: mutex X    idn     1317011825 value   3968549781504 where   9041305591414879

Pick idn (P1): 1317011825, and query v$db_object_cache:

select name, namespace, type, hash_value, locks, pins, locked_total, pinned_total
from v$db_object_cache where hash_value in (1317011825);

NAME       NAMESPACE       TYPE             HASH_VALUE       LOCKS        PINS LOCKED_TOTAL PINNED_TOTAL
---------- --------------- --------------- ----------- ----------- ----------- ------------ ------------
TEST_CTX   APP CONTEXT     APP CONTEXT      1317011825           4           0            4    257802287

It shows that "library cache: mutex X" is on application context: TEST_CTX, and PINNED_TOTAL is probably increased for each access.
Although TEST_CTX is a local context and its values is stored in the User Global Area (UGA), the content of "library cache: mutex X" is globally on its definition.

select namespace, package, type from dba_context where namespace = 'TEST_CTX';

NAMESPACE  PACKAGE       TYPE
---------- ------------  ----------------
TEST_CTX   TEST_CTX_PKG  ACCESSED LOCALLY

After test, clean-up all jobs by:
  exec clean_jobs;

Test Code


create or replace context test_ctx using test_ctx_pkg;

create or replace package test_ctx_pkg is 
  procedure set_val (val number);
 end;
/

create or replace package body test_ctx_pkg is
  procedure set_val (val number) as
  begin
    dbms_session.set_context('test_ctx', 'attr', val);
  end;
end;
/

create or replace procedure ctx_set(p_cnt number, val number) as
begin
 for i in 1..p_cnt loop
  test_ctx_pkg.set_val(val);    -- 'library cache: mutex X' on TEST_CTX
 end loop;
end;
/

create or replace procedure ctx_set_jobs(p_job_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 ctx_set(100000, '||i||'); 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;
/


/**
exec ctx_set_jobs(4);

exec clean_jobs;

column program format a20
column event format a25
column p1text format a6
column p1 format 9999999999
column p2text format a6
column p2 format 9999999999999
column p3text format a6
column p3 format 9999999999999999

select sid, program, event, p1text, p1, p2text, p2, p3text, p3
  from v$session where program like '%(J%';

  SID PROGRAM              EVENT                     P1TEXT          P1 P2TEXT             P2 P3TEXT                P3
----- -------------------- ------------------------- ------ ----------- ------ -------------- ------ -----------------
   38 oracle@testdb (J003) library cache: mutex X    idn     1317011825 value   3968549781504 where   9041305591414788
  890 oracle@testdb (J000) library cache: mutex X    idn     1317011825 value    163208757248 where   9041305591414874
  924 oracle@testdb (J001) library cache: mutex X    idn     1317011825 value   4556960301056 where   9041305591414874
 1061 oracle@testdb (J002) library cache: mutex X    idn     1317011825 value   3968549781504 where   9041305591414879

  
column name format a10
column namespace format a15
column type format a15
set numformat 9999999999
  
select name, namespace, type, hash_value, locks, pins, locked_total, pinned_total
from v$db_object_cache where hash_value in (1317011825);

NAME       NAMESPACE       TYPE             HASH_VALUE       LOCKS        PINS LOCKED_TOTAL PINNED_TOTAL
---------- --------------- --------------- ----------- ----------- ----------- ------------ ------------
TEST_CTX   APP CONTEXT     APP CONTEXT      1317011825           4           0            4    257802287

**/