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.

Oracle9i Docu: Temporary LOB Performance Guidelines in Oracle9i Application Developer's Guide - Large Objects (LOBs) has a Note:

Temporary LOBs created using a session locator are not cleaned up automatically at the end of function or procedure calls. The temporary LOB should be explicitly freed by calling DBMS_LOB.FREETEMPORARY().

which talks about "session locator", and there is nowhere mentioned "abstract_lob". It is not clear how both are related.

But since Oracle 10g, we can't find this Note any more.

Here is the new link of Oracle 12.2: Temporary LOB Performance Guidelines SecureFiles and Large Objects Developer's Guide.

It contains details about Temporary LOB usage and shows how to get LOB Access Statistics in dynamic performance views.


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. Temporary LOBs: CACHE_LOBS, NOCACHE_LOBS, ABSTRACT_LOBS


Here a small test of Temporary LOBs: CACHE_LOBS, NOCACHE_LOBS, ABSTRACT_LOBS, and their space usage (tested in Oracle 12cR1 and 12cR2).

------------------------------ SetUp -------------------------------
create or replace package lob_cache_test_pkg as
 g_CACHE_LOBS    clob;
 g_NOCACHE_LOBS  clob;
 g_ABSTRACT_LOBS clob;
end;
/

create or replace procedure lob_cache_test_CACHE_LOBS (p_cnt number) as 
 l_txt varchar2(10) := '0123456789';
begin
  for i in 1..p_cnt loop
    dbms_lob.createtemporary(
      lob_loc => lob_cache_test_pkg.g_CACHE_LOBS, cache => true, dur => dbms_lob.call);
    -- without assignment, or with "dbms_lob.writeappend" create CACHE_LOBS. 
    dbms_lob.writeappend(lob_loc => lob_cache_test_pkg.g_CACHE_LOBS, amount => 10, buffer => l_txt);
  end loop;
end;
/

create or replace procedure lob_cache_test_NOCACHE_LOBS (p_cnt number) as 
 l_txt varchar2(10) := '0123456789';
begin
  for i in 1..p_cnt loop
    dbms_lob.createtemporary(
      lob_loc => lob_cache_test_pkg.g_NOCACHE_LOBS, cache => false, dur => dbms_lob.call);
    -- without assignment, or with "dbms_lob.writeappend" create NOCACHE_LOBS. 
    dbms_lob.writeappend(lob_loc => lob_cache_test_pkg.g_NOCACHE_LOBS, amount => 10, buffer => l_txt);
  end loop;
end;
/

-- 12cR1 not reported space (BLOCKs) usage of ABSTRACT_LOBS in v$tempseg_usage. 
-- But 12cR2 Reported, and put them into CACHE_LOBS.
create or replace procedure lob_cache_test_ABSTRACT_LOBS (p_cnt number) as 
 l_txt varchar2(10) := '0123456789';
begin
  for i in 1..p_cnt loop
    dbms_lob.createtemporary(
      lob_loc => lob_cache_test_pkg.g_ABSTRACT_LOBS, cache => true, dur => dbms_lob.call);
    -- with direct text assignment create ABSTRACT_LOBS. 
    lob_cache_test_pkg.g_ABSTRACT_LOBS := l_txt;
  end loop;
end;
/
Run test and show the output:

--------------------------- Test on 12cR2 ---------------------------
-- It takes hours with "dbms_session.reset_package" to free created temporary LOBs 
-- if their number is high (more than 1,000,000). 
-- LOB Subroutine Callstack: kdlt_freetemp -> kdl_destroy -> kdlclose -> memcmp
--
-- ALTER SYSTEM KILL SESSION 'sid,serial#' releases memory immediately.

exec dbms_session.reset_package; 

select l.*, t.blocks  --t.* 
from v$session s, v$temporary_lobs l, v$tempseg_usage t
where s.sid = l.sid and s.saddr = t.session_addr;

exec lob_cache_test_CACHE_LOBS(1122);

select l.*, t.blocks  --t.* 
from v$session s, v$temporary_lobs l, v$tempseg_usage t
where s.sid = l.sid and s.saddr = t.session_addr;

exec lob_cache_test_NOCACHE_LOBS(1133);

select l.*, t.blocks  --t.* 
from v$session s, v$temporary_lobs l, v$tempseg_usage t
where s.sid = l.sid and s.saddr = t.session_addr;

exec lob_cache_test_ABSTRACT_LOBS(1144);

select l.*, t.blocks  --t.* 
from v$session s, v$temporary_lobs l, v$tempseg_usage t
where s.sid = l.sid and s.saddr = t.session_addr;

--------------------------- Test Result on 12cR2 ---------------------------
   SID CACHE_LOBS NOCACHE_LOBS ABSTRACT_LOBS     CON_ID     BLOCKS
  ---- ---------- ------------ ------------- ---------- ----------
   738          0            0             0          0          0

SQL > exec lob_cache_test_CACHE_LOBS(1122);

   SID CACHE_LOBS NOCACHE_LOBS ABSTRACT_LOBS     CON_ID     BLOCKS
  ---- ---------- ------------ ------------- ---------- ----------
   738       1122            0             0          0       1280
      
SQL > exec lob_cache_test_NOCACHE_LOBS(1133);

   SID CACHE_LOBS NOCACHE_LOBS ABSTRACT_LOBS     CON_ID     BLOCKS
  ---- ---------- ------------ ------------- ---------- ----------
   738       1122         1133             0          0       2304

SQL > exec lob_cache_test_ABSTRACT_LOBS(1144);

   SID CACHE_LOBS NOCACHE_LOBS ABSTRACT_LOBS     CON_ID     BLOCKS
  ---- ---------- ------------ ------------- ---------- ----------
   738       2266         1133          1144          0       3584


5. Test Code



create or replace function cre_clob(p_clob_len number) return clob as
  --l_text varchar2(1024) := lpad('a', 1024, 'b');
  l_clob clob;
  --l_blob blob;                    -- BLOB has similar behaviour
  --l_raw  raw(100) := '4b53554e';
  l_text  varchar2(32767);
begin
  --x := 'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa';
  --dbms_lob.createtemporary(l_clob, true, dbms_lob.session);
  --for i in 1..1024 loop
  -- dbms_lob.writeappend(l_clob, length(l_text) , l_text);
  --end loop;
  --l_blob := l_raw;
  --return l_blob;
  
  l_text := lpad('a', p_clob_len, 'b');
  
  l_clob := l_text;
  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;
/