Friday, February 3, 2017

Blog List

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

**/

Monday, September 12, 2016

PL/SQL Multidimensional Collection Memory Usage and Performance

PL/SQL multidimensional collections are modeled by creating a collection whose elements are also collections.

We found that the memory usage and performance of Multidimensional Collections are dependent on the total number of branch nodes, which are determined by the data characteristics and the subscript indices ordering.

This Blog will try to demonstrate the findings with appended Test Code.

1. Know Your Data


At first, run two queries to understand the test data (see the Test Code):

SQL> select round(num_rows*avg_row_len/1024/1024) mb from dba_tables where table_name = 'MEM_TAB';

46 MB

SQL> select * 
  from (
  select count(distinct id) id, count(distinct name) name
        ,count(distinct num_1) num_1, count(distinct num_2) num_2
        ,count(distinct txt_1) txt_1, count(distinct txt_2) txt_2
        ,count(distinct num_1||'.'||num_2) num_1_2, count(distinct txt_1||'.'||txt_2) txt_1_2
    from mem_tab)
unpivot (distinct_count for count_name in
        (id as 'count(distinct id)', name as 'count(distinct name)'
        ,num_1 as 'count(distinct num_1)', num_2 as 'count(distinct num_2)'
        ,txt_1 as 'count(distinct txt_1)', txt_2 as 'count(distinct txt_2)' 
        ,num_1_2 as 'count(distinct num_1.num_2)'
        ,txt_1_2 as 'count(distinct txt_1.txt_2)'
        ));

COUNT_NAME                  DISTINCT_COUNT
--------------------------- --------------
count(distinct id)               1,000,000
count(distinct name)             1,000,000
count(distinct num_1)              500,000
count(distinct num_2)               50,000
count(distinct txt_1)              500,000
count(distinct txt_2)               50,000
count(distinct num_1.num_2)      1,000,000
count(distinct txt_1.txt_2)      1,000,000

Test table mem_tab is composed of 6 columns, contains 1,000,000 rows, and theoretical size is about 46 MB.
  • It has 2 unique columns (id and name), and two composite unique columns ((num_1.num_2), (txt_1.txt_2)).
  • num_1 and txt_1 have 500,000 distinct values each, branching factor = 2, hence 500,000 branch nodes when storing as array(num_1)(num_2);
  • num_2 and txt_2 have 50,000 distinct values each, branching factor = 20, hence 50,000 branch nodes when storing as array(num_2)(num_1).

2. Create Test


Run command:

SQL> exec test_collection_dimm_mem.run(1000000);

0  Dimension 1 array(id)  , pga_used(MB) =   411, Elapsed(Second)= 5.44
1  Dimension 1 array(name), pga_used(MB) =   459, Elapsed(Second)= 6.21
2  Dimension 2 array(num_1)(num_2), pga_used(MB) =  2227, Elapsed(Second)= 8.54
3  Dimension 2 array(num_2)(num_1), pga_used(MB) =   536, Elapsed(Second)= 5.44
4  Dimension 2 array(txt_1)(txt_2), pga_used(MB) =  2739, Elapsed(Second)= 7.79
5  Dimension 2 array(txt_2)(txt_1), pga_used(MB) =   628, Elapsed(Second)= 5.96
6  Dimension 2 array(num_1)(txt_2), pga_used(MB) =  2719, Elapsed(Second)= 6.53
7  Dimension 2 array(num_2)(txt_1), pga_used(MB) =   626, Elapsed(Second)= 5.62
8  Dimension 2 array(txt_1)(num_2), pga_used(MB) =  2251, Elapsed(Second)= 9.12
9  Dimension 2 array(txt_2)(num_1), pga_used(MB) =   539, Elapsed(Second)= 6.07
   
10 Dimension 1 table(id), pga_used(MB) =   411, Elapsed(Second)= 6.25
11 Dimension 2 table(num_1)(num_2), pga_used(MB) =   889, Elapsed(Second)= 9.78
12 Dimension 2 table(num_2)(num_1), pga_used(MB) =   443, Elapsed(Second)= 7.86  

The above output shows:
  1. One dimensional associative array has a factor 10 more memory usage compared to disk table size (46MB).
  2. Comparing RUN 4 and RUN 5, two dimensional can have a factor 60 more memory usage (2739/46) when organized with 500,000 branch nodes in array(txt_1)(txt_2); but factor 14 (628/46) when organized with 50,000 branch nodes in array(txt_2)(txt_1) by simply exchanging the subscripts;
    More than a factor 4 of difference when exchanging the order of subscripts.
    Each branch node takes about 5KB to 13KB.
    (imagine the cases of organizations with 50% vs. 5% employees being managers)
  3. One dimensional nested table and associative array are comparable.
  4. Two dimensional nested tables have a factor of 19 (888/46), and 10 (443/46).
  5. The performance is proportional to the memory usage.

3. Lookup Test


Once the data is stored in array/table, they can be used for in-memory search.
For example, in Test Code: test_collection_dimm_mem.run, reactivate the lookup snippet code:

    ---- lookup example ----
    l_start_time := dbms_utility.get_time;
    for c in (select id, name, num_1, num_2, txt_1, txt_2 from mem_tab where rownum <= p_cnt) loop
      l_node_rec := l_array_d2nn(c.num_1)(c.num_2);
    end loop;

Test output below shows that the performance difference is less than 30% among associative arrays.
But nested table is a factor 3 to 5 faster.

0  Dimension 1 array(id)  , pga_used(MB) =   411, Elapsed(Second)= 2.27
1  Dimension 1 array(name), pga_used(MB) =   459, Elapsed(Second)= 2.88
2  Dimension 2 array(num_1)(num_2), pga_used(MB) =  2227, Elapsed(Second)= 2.85
3  Dimension 2 array(num_2)(num_1), pga_used(MB) =   536, Elapsed(Second)= 2.51
4  Dimension 2 array(txt_1)(txt_2), pga_used(MB) =  2739, Elapsed(Second)= 3.3
5  Dimension 2 array(txt_2)(txt_1), pga_used(MB) =   628, Elapsed(Second)= 2.95
6  Dimension 2 array(num_1)(txt_2), pga_used(MB) =  2719, Elapsed(Second)= 2.77
7  Dimension 2 array(num_2)(txt_1), pga_used(MB) =   626, Elapsed(Second)= 2.58
8  Dimension 2 array(txt_1)(num_2), pga_used(MB) =  2251, Elapsed(Second)= 3.4
9  Dimension 2 array(txt_2)(num_1), pga_used(MB) =   539, Elapsed(Second)= 2.93
   
10 Dimension 1 table(id), pga_used(MB) =   411, Elapsed(Second)= .45
11 Dimension 2 table(num_1)(num_2), pga_used(MB) =   889, Elapsed(Second)= 1.09
12 Dimension 2 table(num_2)(num_1), pga_used(MB) =   443, Elapsed(Second)= .8


4. Heapdump Dump


Make heapdump for 3 Cases:
  1. Dimension 1 array(id) in RUN 0
  2. Dimension 2 array(num_1)(num_2) in RUN 2
  3. Dimension 2 array(num_2)(num_1) in RUN 3
by:

alter session set events 'immediate trace name heapdump level 16';

respective "top uga heap" displays the main memory usage:

--- Dimension 1 array(id) ---
 HEAP DUMP heap name="top uga heap"  desc=0x7f4b2d56ada0
 Total heap size    =427532128
 
--- Dimension 2 array(num_1)(num_2) ---
 HEAP DUMP heap name="top uga heap"  desc=0x7f94fddf3da0
 Total heap size    =2331900936

--- Dimension 2 array(num_2)(num_1) ---
 HEAP DUMP heap name="top uga heap"  desc=0x7fb10cf26da0
 Total heap size    =558883712  


5. PGA Dump


Further make pga_detail_dump by:

alter session set events 'immediate trace name pga_detail_dump level 27';

which reveals corresponding details by categories:
(note 27 is Oracle process number (PID), only top categories are listed)

--- Dimension 1 array(id) ---
  220672920 bytes,13515 chunks: "pmuccst: adt/record       "  PL/SQL
            koh-kghu sessi  ds=0x7f4b27f791b8  dsprt=0x7f4b28eed740
  182716608 bytes,11196 chunks: "pl/sql vc2                "  PL/SQL
            koh-kghu sessi  ds=0x7f4b27f791b8  dsprt=0x7f4b28eed740
   18667040 bytes,1144 chunks: "pmucalm coll              "  PL/SQL
            koh-kghu sessi  ds=0x7f4b27f791b8  dsprt=0x7f4b28eed740
     973992 bytes,  66 chunks: "static frame of inst      "  PL/SQL
            koh-kghu sessi  ds=0x7f4b282a8580  dsprt=0x7f4b28eed740
  
--- Dimension 2 array(num_1)(num_2) ---        
  1633408272 bytes,100038 chunks: "pmucalm coll              "  PL/SQL
            koh-kghu sessi  ds=0x7f94f88121b8  dsprt=0x7f94f977d740
  282131512 bytes,17279 chunks: "pmuccst: adt/record       "  PL/SQL
            koh-kghu sessi  ds=0x7f94f88121b8  dsprt=0x7f94f977d740
  187843616 bytes,11510 chunks: "pl/sql vc2                "  PL/SQL
            koh-kghu sessi  ds=0x7f94f88121b8  dsprt=0x7f94f977d740
  117545272 bytes,7199 chunks: "pmucpcon: ipm             "  PL/SQL
            koh-kghu sessi  ds=0x7f94f88121b8  dsprt=0x7f94f977d740
   57776680 bytes,3539 chunks: "pmucpcon: tds             "  PL/SQL
            koh-kghu sessi  ds=0x7f94f88121b8  dsprt=0x7f94f977d740
   41783352 bytes,2559 chunks: "pmucpcon: cds             "  PL/SQL
            koh-kghu sessi  ds=0x7f94f88121b8  dsprt=0x7f94f977d740          
  
--- Dimension 2 array(num_2)(num_1) ---
  243923992 bytes,14939 chunks: "pmuccst: adt/record       "  PL/SQL
            koh-kghu sessi  ds=0x7fb1079451b8  dsprt=0x7fb1088ad740
  160771776 bytes,9852 chunks: "pl/sql vc2                "  PL/SQL
            koh-kghu sessi  ds=0x7fb1079451b8  dsprt=0x7fb1088ad740
  127166584 bytes,7789 chunks: "pmucalm coll              "  PL/SQL
            koh-kghu sessi  ds=0x7fb1079451b8  dsprt=0x7fb1088ad740
   10956088 bytes, 671 chunks: "pmucpcon: ipm             "  PL/SQL
            koh-kghu sessi  ds=0x7fb1079451b8  dsprt=0x7fb1088ad740
    5747456 bytes, 352 chunks: "pmucpcon: cds             "  PL/SQL
            koh-kghu sessi  ds=0x7fb1079451b8  dsprt=0x7fb1088ad740
    4416776 bytes, 271 chunks: "pmucpcon: tds             "  PL/SQL
            koh-kghu sessi  ds=0x7fb1079451b8  dsprt=0x7fb1088ad740   

In the above 3 Cases, "pmuccst: adt/record" and "pl/sql vc2" are almost similar, but "pmucalm coll" makes the difference.
  1. "pl/sql vc2" are all involved varchar2 strings.
  2. "pmuccst: adt/record" (ADT: Abstract Data Type) stores all the PL/SQL records, in this test, it is 1,000,000.
  3. "pmucalm coll" looks like all the allocated collections, which represent the branch nodes. array(num_1)(num_2) takes 1,633,408,272 Bytes, whereas array(num_2)(num_1) 127,166,584 since the first one has 500,000 branch nodes, whereas second 50,000.
In Oracle applications, PL/SQL collections are often the cause of ORA-04030 when storing large number of elements (same type). Determining the categories helps pinpoint the main memory consumption.
  • "pmuccst: adt/record" stands for leaf nodes, that is the number of elements.
  • "pmucalm coll" represents branch nodes, that is the number of collections.
BTW, the abbreviation ds and dsprt are the shortcuts of "heap_descriptor" and "parent_heap_descriptor".

6. Populate process_memory_detail


Dump process_memory_detail into process_memory_detail_v by setting event PGA_DETAIL_GET, then query the result with:

column run_name format A40
column "NAME(MB, ALLOC_COUNT) List" format A200
column name format A30

select run, run_name, pid, round(sum(bytes)/1024/1024) mb, sum(allocation_count) allocation_count
from process_memory_detail_v 
group by run, run_name, pid 
order by run;

 RUN RUN_NAME                          PID      MB ALLOCATION_COUNT
---- -------------------------------- ---- ------- ----------------
   0 Dimension 1 array(id)              27     409           29,676
   1 Dimension 1 array(name)            27     458           32,824
   2 Dimension 2 array(num_1)(num_2)    27   2,220          145,969
   3 Dimension 2 array(num_2)(num_1)    27     534           37,721
   4 Dimension 2 array(txt_1)(txt_2)    27   2,730          178,767
   5 Dimension 2 array(txt_2)(txt_1)    27     626           43,632
   6 Dimension 2 array(num_1)(txt_2)    27   2,711          177,517
   7 Dimension 2 array(num_2)(txt_1)    27     624           43,511
   8 Dimension 2 array(txt_1)(num_2)    27   2,244          147,554
   9 Dimension 2 array(txt_2)(num_1)    27     537           37,895
  10 Dimension 1 table(id)              27     411           29,745
  11 Dimension 2 table(num_1)(num_2)    27     886           60,281
  12 Dimension 2 table(num_2)(num_1)    27     443           31,829
-------------------------------------------------------------------  

select run, run_name, pid, round(sum(bytes)/1024/1024) mb,
       (select listagg(rpad(name||'('||round(bytes/1024/1024)||', '||allocation_count||')', 40, chr(32)), '; ') 
               within group (order by bytes desc) agg
          from (select * from process_memory_detail_v c 
                 where c.run = v.run and c.pid = v.pid and bytes > 0
                 order by bytes desc) c 
         where rownum <= 3
         ) "NAME(MB, ALLOC_COUNT) List"
from process_memory_detail_v v
group by run, run_name, pid
order by run, run_name, pid;

RUN RUN_NAME                         PID     MB NAME(MB, ALLOC_COUNT) List
--- ------------------------------- ---- ------ ---------------------------------------------------------------------------------------------------
  0 Dimension 1 array(id)             27    409 pmuccst: adt/record(225, 14456) ; pl/sql vc2(161, 10311)                  ; pmucalm coll(17, 1084)
  1 Dimension 1 array(name)           27    458 pl/sql vc2(196, 12561)          ; pmuccst: adt/record(190, 12220)         ; pmucalm coll(65, 4196)
  2 Dimension 2 array(num_1)(num_2)   27  2,220 pmucalm coll(1560, 100167)      ; pmuccst: adt/record(271, 17379)         ; pl/sql vc2(179, 11488)
  3 Dimension 2 array(num_2)(num_1)   27    534 pmuccst: adt/record(231, 14827) ; pl/sql vc2(153, 9836)                   ; pmucalm coll(123, 7902)
  4 Dimension 2 array(txt_1)(txt_2)   27  2,730 pmucalm coll(2699, 173350)      ; pmuccst: adt/record(14, 882)            ; pl/sql vc2(10, 675)
  5 Dimension 2 array(txt_2)(txt_1)   27    626 pmucalm coll(229, 14676)        ; pmuccst: adt/record(207, 13302)         ; pl/sql vc2(176, 11272)
  6 Dimension 2 array(num_1)(txt_2)   27  2,711 pmucalm coll(2596, 166684)      ; pmuccst: adt/record(62, 3975)           ; pl/sql vc2(47, 2993)
  7 Dimension 2 array(num_2)(txt_1)   27    624 pmucalm coll(222, 14238)        ; pmuccst: adt/record(221, 14194)         ; pl/sql vc2(167, 10739)
  8 Dimension 2 array(txt_1)(num_2)   27  2,244 pmucalm coll(1570, 100838)      ; pmuccst: adt/record(273, 17546)         ; pl/sql vc2(185, 11904)
  9 Dimension 2 array(txt_2)(num_1)   27    537 pmuccst: adt/record(232, 14931) ; pl/sql vc2(155, 9946)                   ; pmucalm coll(123, 7870)
 10 Dimension 1 table(id)             27    411 pmuccst: adt/record(222, 14276) ; pl/sql vc2(163, 10488)                  ; pmucalm coll(17, 1089)
 11 Dimension 2 table(num_1)(num_2)   27    886 pmucalm coll(286, 18381)        ; pmuccst: adt/record(248, 15936)         ; pl/sql vc2(144, 9229)
 12 Dimension 2 table(num_2)(num_1)   27    443 pmuccst: adt/record(229, 14680) ; pl/sql vc2(155, 9951)                   ; pmucalm coll(30, 1905)
----------------------------------------------------------------------------------------------------------

select run, run_name, pid, category, name, heap_name, round(bytes/1024/1024) mb
      ,allocation_count, round(bytes/allocation_count) bytes_per_cnt
from process_memory_detail_v 
where name = 'pmucalm coll'
order by pid, category, name, heap_name, run, timestamp;

RUN RUN_NAME                         PID  CATEGORY  NAME           HEAP_NAME        MB      ALLOCATION_COUNT   BYTES_PER_CNT
--- ------------------------------- ---- ---------- ------------- ---------------- ------  -----------------  --------------
  0 Dimension 1 array(id)             27  PL/SQL    pmucalm coll   koh-kghu sessi      17              1,084          16,317
  1 Dimension 1 array(name)           27  PL/SQL    pmucalm coll   koh-kghu sessi      65              4,196          16,325
  2 Dimension 2 array(num_1)(num_2)   27  PL/SQL    pmucalm coll   koh-kghu sessi   1,560            100,167          16,328
  3 Dimension 2 array(num_2)(num_1)   27  PL/SQL    pmucalm coll   koh-kghu sessi     123              7,902          16,326
  4 Dimension 2 array(txt_1)(txt_2)   27  PL/SQL    pmucalm coll   koh-kghu sessi   2,699            173,350          16,328
  5 Dimension 2 array(txt_2)(txt_1)   27  PL/SQL    pmucalm coll   koh-kghu sessi     229             14,676          16,327
  6 Dimension 2 array(num_1)(txt_2)   27  PL/SQL    pmucalm coll   koh-kghu sessi   2,596            166,684          16,328
  7 Dimension 2 array(num_2)(txt_1)   27  PL/SQL    pmucalm coll   koh-kghu sessi     222             14,238          16,327
  8 Dimension 2 array(txt_1)(num_2)   27  PL/SQL    pmucalm coll   koh-kghu sessi   1,570            100,838          16,328
  9 Dimension 2 array(txt_2)(num_1)   27  PL/SQL    pmucalm coll   koh-kghu sessi     123              7,870          16,326
 10 Dimension 1 table(id)             27  PL/SQL    pmucalm coll   koh-kghu sessi      17              1,089          16,317
 11 Dimension 2 table(num_1)(num_2)   27  PL/SQL    pmucalm coll   koh-kghu sessi     286             18,381          16,327
 12 Dimension 2 table(num_2)(num_1)   27  PL/SQL    pmucalm coll   koh-kghu sessi      30              1,905          16,322

  • The first query shows the memory usage per run.
  • The second query lists the memory allocations of top 3 Heaps for each run.
  • The third query reveals Heap "pmucalm coll" statistics of memory and allocation_count.
    The top 4 RUNs (2, 4, 6, 8) have 500,000 branch nodes, and hence more memory and allocation_count.
    Computing the average bytes per allocation, BYTES_PER_CNT shows almost a constant value of 16K.
    Probably generous reserving 16K (2x8K-Blocks) for each "pmucalm coll" conforms to the design strategy of preventing expensive branch node splitting.

7. Test Code



set numformat 999,999,999

drop table mem_tab;

create table mem_tab(id number, name varchar2(10) 
                    ,num_1 number, num_2 number 
                    ,txt_1 varchar2(10), txt_2 varchar2(10));

insert into mem_tab 
select level id, rpad(level, 10, 'X') name
   ,level num_1, ceil(level/20) num_2 
   ,rpad(level, 10, 'X') txt_1, rpad(ceil(level/20), 10, 'X') txt_2 
  from dual connect by level <= 500000
union all
select (level + 500000) id, rpad((level + 500000), 10, 'X') name
   ,level num_1, -ceil(level/20) num_2 
   ,rpad(level, 10, 'X') txt_1, rpad(-ceil(level/20), 10, 'X') txt_2 
  from dual connect by level <= 500000;

commit;

exec dbms_stats.gather_table_stats(null, 'MEM_TAB');

select round(num_rows*avg_row_len/1024/1024) mb from dba_tables where table_name = 'MEM_TAB';
-- 46 MB

select * 
  from (
  select count(distinct id) id, count(distinct name) name
        ,count(distinct num_1) num_1, count(distinct num_2) num_2
        ,count(distinct txt_1) txt_1, count(distinct txt_2) txt_2
        ,count(distinct num_1||'.'||num_2) num_1_2, count(distinct txt_1||'.'||txt_2) txt_1_2
    from mem_tab)
unpivot (distinct_count for count_name in
        (id as 'count(distinct id)', name as 'count(distinct name)'
        ,num_1 as 'count(distinct num_1)', num_2 as 'count(distinct num_2)'
        ,txt_1 as 'count(distinct txt_1)', txt_2 as 'count(distinct txt_2)' 
        ,num_1_2 as 'count(distinct num_1.num_2)'
        ,txt_1_2 as 'count(distinct txt_1.txt_2)'
        ));

create or replace package test_collection_dimm_mem as
  procedure run (p_cnt number := 1000000);
end;
/

drop table process_memory_detail_v;

create table process_memory_detail_v as 
  select 123 run, rpad('A', 40, 'X') run_name, timestamp'1998-02-17 11:22:00' timestamp
        ,234 session_id, 345 session_serial#, v.* 
  from v$process_memory_detail v where 1=2;

create or replace package body test_collection_dimm_mem as
  type t_rec is record (
    id            number
   ,name          varchar2(10)
   ,num_1         number
   ,num_2         number
   ,txt_1         varchar2(10)
   ,txt_2         varchar2(10)
  );
  type t_array_d1n  is table of t_rec      index by pls_integer;    -- array(number)
  type t_array_d1t  is table of t_rec      index by varchar2(30);    -- array(text)
  
  type t_array_d2nn is table of t_array_d1n index by pls_integer;    -- array(number)(number)
  type t_array_d2tt is table of t_array_d1t index by varchar2(30);   -- array(text)(text)
  
  type t_array_d2nt is table of t_array_d1t index by pls_integer;    -- array(number)(text)
  type t_array_d2tn is table of t_array_d1n index by varchar2(30);   -- array(text)(number)
  
  type t_nesttab_d1 is table of t_rec;
  type t_nesttab_d2 is table of t_nesttab_d1;
     
  l_node_rec       t_rec;
  l_array_d1n      t_array_d1n;                        -- array(number)
  l_array_d1t      t_array_d1t;                        -- array(text)
  l_array_d2nn     t_array_d2nn;                        -- array(number)(number)
  l_array_d2tt     t_array_d2tt;                        -- array(text)(text)
  l_array_d2nt     t_array_d2nt;                        -- array(number)(text)
  l_array_d2tn     t_array_d2tn;                        -- array(text)(number)
  l_nesttab_d1     t_nesttab_d1 := new t_nesttab_d1(); -- nested Table (number)
  l_nesttab_d2     t_nesttab_d2 := new t_nesttab_d2(); -- nested Table (number)(number)
  l_node_map_sep   varchar2(1) := '.';
  l_start_time     number;
  l_mb             varchar2(10);
  l_last_num       number;
  l_pid            number;
  l_sid            number;
  l_serial#        number;
  l_run            number := 0;
  l_pga_status     varchar2(10) := 'NOT';
  
  procedure reset as
  begin
    l_array_d1n.delete;
    l_array_d1t.delete;
    l_array_d2nn.delete;
    l_array_d2tt.delete;
    l_array_d2nt.delete;
    l_array_d2tn.delete;
    l_nesttab_d1.delete;
    l_nesttab_d2.delete;
    dbms_session.free_unused_user_memory;
    l_start_time := dbms_utility.get_time;
  end;

  procedure prt_and_reset_mem(p_name varchar2) as
  begin
    select lpad(round(pga_used_mem/1024/1024), 5, ' '), pid, s.sid, s.serial#
      into l_mb, l_pid, l_sid, l_serial#
      from v$process p, v$session s
     where p.addr = s.paddr and s.sid = sys.dbms_support.mysid and rownum = 1;
    dbms_output.put_line(rpad(l_run, 3, ' ')||p_name||', pga_used(MB) = '||l_mb||
             ', Elapsed(Second)= '||round((dbms_utility.get_time - l_start_time)/100, 2));
             
    execute immediate q'[alter session set events 'immediate trace name PGA_DETAIL_GET level ]'||l_pid||q'[']'; 
    -- wait status = COMPLETE when status = SCANNING
    while (true) loop
     select status into l_pga_status from v$process_memory_detail_prog where pid = l_pid;
     exit when l_pga_status = 'COMPLETE';
     dbms_lock.sleep(0.1);
    end loop;
    delete from process_memory_detail_v 
     where pid = l_pid and session_id = l_sid and session_serial# = l_serial# and run = l_run;
    insert into process_memory_detail_v select l_run, p_name, systimestamp, l_sid, l_serial#, v.* 
      from v$process_memory_detail v where pid = l_pid;
    -- outcomment to keep last PGA_DETAIL
    -- execute immediate q'[alter session set events 'immediate trace name PGA_DETAIL_CANCEL level ]'||l_pid||q'[']';  
    commit; 
    
    l_run := l_run + 1;
    reset;
  end;
  
  function rec(id number, name varchar2, num_1 number, num_2 number, txt_1 varchar2, txt_2 varchar2) 
    return t_rec as
  begin
    l_node_rec.id        := id;
    l_node_rec.name      := name;
    l_node_rec.num_1     := num_1;
    l_node_rec.num_2     := num_2;
    l_node_rec.txt_1     := txt_1;
    l_node_rec.txt_2     := txt_2;
    return l_node_rec;
  end;
    
  procedure run (p_cnt number := 1000000) as
  begin
    reset;
    for c in (select id, name, num_1, num_2, txt_1, txt_2 from mem_tab where rownum <= p_cnt) loop
      l_array_d1n(c.id) := rec(c.id, c.name, c.num_1, c.num_2, c.txt_1, c.txt_2);
    end loop;
    prt_and_reset_mem('Dimension 1 array(id)  ');
    
    for c in (select id, name, num_1, num_2, txt_1, txt_2 from mem_tab where rownum <= p_cnt) loop
      l_array_d1t(c.name) := rec(c.id, c.name, c.num_1, c.num_2, c.txt_1, c.txt_2);
    end loop;
    prt_and_reset_mem('Dimension 1 array(name)');
    
    for c in (select id, name, num_1, num_2, txt_1, txt_2 from mem_tab where rownum <= p_cnt) loop
      l_array_d2nn(c.num_1)(c.num_2) := rec(c.id, c.name, c.num_1, c.num_2, c.txt_1, c.txt_2);
    end loop;

    ---- lookup example ----
    --l_start_time := dbms_utility.get_time;
    --for c in (select id, name, num_1, num_2, txt_1, txt_2 from mem_tab where rownum <= p_cnt) loop
    --  l_node_rec := l_array_d2nn(c.num_1)(c.num_2);
    --end loop;

    prt_and_reset_mem('Dimension 2 array(num_1)(num_2)');
    
    for c in (select id, name, num_1, num_2, txt_1, txt_2 from mem_tab where rownum <= p_cnt) loop
      l_array_d2nn(c.num_2)(c.num_1) := rec(c.id, c.name, c.num_1, c.num_2, c.txt_1, c.txt_2);
    end loop;
    prt_and_reset_mem('Dimension 2 array(num_2)(num_1)');
    
    for c in (select id, name, num_1, num_2, txt_1, txt_2 from mem_tab where rownum <= p_cnt) loop
      l_array_d2tt(c.txt_1)(c.txt_2) := rec(c.id, c.name, c.num_1, c.num_2, c.txt_1, c.txt_2);
    end loop;
    prt_and_reset_mem('Dimension 2 array(txt_1)(txt_2)');   
    
    for c in (select id, name, num_1, num_2, txt_1, txt_2 from mem_tab where rownum <= p_cnt) loop
      l_array_d2tt(c.txt_2)(c.txt_1) := rec(c.id, c.name, c.num_1, c.num_2, c.txt_1, c.txt_2);
    end loop;
    prt_and_reset_mem('Dimension 2 array(txt_2)(txt_1)');
    
    for c in (select id, name, num_1, num_2, txt_1, txt_2 from mem_tab where rownum <= p_cnt) loop
      l_array_d2nt(c.num_1)(c.txt_2) := rec(c.id, c.name, c.num_1, c.num_2, c.txt_1, c.txt_2);
    end loop;
    prt_and_reset_mem('Dimension 2 array(num_1)(txt_2)');
    
    for c in (select id, name, num_1, num_2, txt_1, txt_2 from mem_tab where rownum <= p_cnt) loop
      l_array_d2nt(c.num_2)(c.txt_1) := rec(c.id, c.name, c.num_1, c.num_2, c.txt_1, c.txt_2);
    end loop;
    prt_and_reset_mem('Dimension 2 array(num_2)(txt_1)');
    
    for c in (select id, name, num_1, num_2, txt_1, txt_2 from mem_tab where rownum <= p_cnt) loop
      l_array_d2tn(c.txt_1)(c.num_2) := rec(c.id, c.name, c.num_1, c.num_2, c.txt_1, c.txt_2);
    end loop;
    prt_and_reset_mem('Dimension 2 array(txt_1)(num_2)');
    
    for c in (select id, name, num_1, num_2, txt_1, txt_2 from mem_tab where rownum <= p_cnt) loop
      l_array_d2tn(c.txt_2)(c.num_1) := rec(c.id, c.name, c.num_1, c.num_2, c.txt_1, c.txt_2);
    end loop;
    prt_and_reset_mem('Dimension 2 array(txt_2)(num_1)');
    
    --- nested table. Note: specify p_cnt = 1000000 to select all rows for test ---
    dbms_output.put_line('');
    
    for c in (select id, name, num_1, num_2, txt_1, txt_2 from mem_tab 
               where rownum <= p_cnt order by id) loop
     l_nesttab_d1.extend;
     l_nesttab_d1(l_nesttab_d1.last) := rec(c.id, c.name, c.num_1, c.num_2, c.txt_1, c.txt_2);
    end loop;
    prt_and_reset_mem('Dimension 1 table(id)');
    
    for c in (select id, name, num_1, num_2, txt_1, txt_2 from mem_tab 
               where rownum <= p_cnt order by num_1, num_2) loop
     if (c.num_1 != l_last_num) then
      l_nesttab_d2.extend;
      l_nesttab_d2(l_nesttab_d2.last) := l_nesttab_d1;
      l_nesttab_d1 := new t_nesttab_d1();
     end if;
     l_nesttab_d1.extend;
     l_nesttab_d1(l_nesttab_d1.last) := rec(c.id, c.name, c.num_1, c.num_2, c.txt_1, c.txt_2);
     l_last_num := c.num_1;
    end loop;
    l_nesttab_d2.extend;
    l_nesttab_d2(l_nesttab_d2.last) := l_nesttab_d1;

    ---- lookup example ----
    --l_start_time := dbms_utility.get_time;
    --for i in 1..l_nesttab_d2.count loop
    -- l_nesttab_d1 := l_nesttab_d2(i);
    -- for j in 1..l_nesttab_d1.count loop
    --   l_node_rec := l_nesttab_d1(j);
    -- end loop;
    --end loop;

    prt_and_reset_mem('Dimension 2 table(num_1)(num_2)');
    
    for c in (select id, name, num_1, num_2, txt_1, txt_2 from mem_tab 
               where rownum <= p_cnt order by num_2, num_1) loop
     if (c.num_2 != l_last_num) then
      l_nesttab_d2.extend;
      l_nesttab_d2(l_nesttab_d2.last) := l_nesttab_d1;
      l_nesttab_d1 := new t_nesttab_d1();
     end if;
     l_nesttab_d1.extend;
     l_nesttab_d1(l_nesttab_d1.last) := rec(c.id, c.name, c.num_1, c.num_2, c.txt_1, c.txt_2);
     l_last_num := c.num_2;
    end loop;
    l_nesttab_d2.extend;
    l_nesttab_d2(l_nesttab_d2.last) := l_nesttab_d1;
    prt_and_reset_mem('Dimension 2 table(num_2)(num_1)');    
  end;     
end;
/

-- set serveroutput on
-- exec test_collection_dimm_mem.run(1000000);

Thursday, September 8, 2016

dbms_session.get_package_memory_utilization and limitations

Oracle 11g Release 2 extends dbms_session Package by introducing a new Procedure:
    get_package_memory_utilization
and 11.2.0.4.0 further enhanced with a second overloaded procedure to augment the measure from 2**31-1 up to 10**38.

It describes memory usage of PL/SQL package declare variables in either specification or body. but not memory usage of locally declared variables within functions, procedures, or anonymous blocks.

Oracle Documentation said:
    These procedures describe static package memory usage.
    The output collections describe memory usage in each instantiated package.

Probably "static package memory usage" stands for memory usage of package declared variables.

The second restriction is that it is bound to caller's session, and does not disclose heap allocation details.

This Blog till try to demonstrate such limitations.

See appended Test Code 1, 2 and its used dump_mem_usage in the Reference 3.

1. Test


SQL > exec pkg_mem_test.run_1(1000*1000);

-------- 1. PKG_MEM_TEST.run_1 START --------
v$process: (SID=854)Used/Alloc/Freeable/Max=6/8/1/11
v$process_memory: Category/Alloc/Used/Max=SQL/0/0/7,PL/SQL/3/3/3,Other/3//3,Freeable/1/0/,
[Owner; Unit; Type; Used; Free; sum_abs_mb(1)]
S; PKG_MEM_TEST; 9  (package); 0; 0; 0
S; PKG_MEM_TEST; 11 (package body); 0; 0; 0

-------- 2. PKG_MEM_TEST.run_1 spec_rec_tab ALLOCATED --------
v$process: (SID=854)Used/Alloc/Freeable/Max=1282/1283/0/1283
v$process_memory: Category/Alloc/Used/Max=SQL/0/0/47,PL/SQL/1215/1211/1215,Other/68//68,
[Owner; Unit; Type; Used; Free; sum_abs_mb(1207)]
S; PKG_MEM_TEST; 9  (package); 1177; 28; 1206
S; PKG_MEM_TEST; 11 (package body); 0; 0; 0

-------- 3. PKG_MEM_TEST.run_1 body_rec_tab ALLOCATED --------
v$process: (SID=854)Used/Alloc/Freeable/Max=2496/2497/0/2497
v$process_memory: Category/Alloc/Used/Max=SQL/0/0/47,PL/SQL/2426/2420/2426,Other/71//71,
[Owner; Unit; Type; Used; Free; sum_abs_mb(2412)]
S; PKG_MEM_TEST; 11 (package body); 1177; 28; 1206
S; PKG_MEM_TEST; 9  (package); 1177; 28; 1206

-------- 4. PKG_MEM_TEST.run_1 local_rec_tab ALLOCATED --------
v$process: (SID=854)Used/Alloc/Freeable/Max=3710/3712/0/3712
v$process_memory: Category/Alloc/Used/Max=SQL/0/0/47,PL/SQL/3638/3629/3638,Other/73//73,
[Owner; Unit; Type; Used; Free; sum_abs_mb(2412)]
S; PKG_MEM_TEST; 11 (package body); 1177; 28; 1206
S; PKG_MEM_TEST; 9  (package); 1177; 28; 1206

-------- 5. PROC_MEM_TEST START --------
v$process: (SID=854)Used/Alloc/Freeable/Max=3710/3712/0/3712
v$process_memory: Category/Alloc/Used/Max=SQL/0/0/47,PL/SQL/3638/3629/3638,Other/73//73,
[Owner; Unit; Type; Used; Free; sum_abs_mb(2412)]
S; PKG_MEM_TEST; 11 (package body); 1177; 28; 1206
S; PKG_MEM_TEST; 9  (package); 1177; 28; 1206

-------- 6. PROC_MEM_TEST local_rec_tab ALLOCATED --------
v$process: (SID=854)Used/Alloc/Freeable/Max=4924/4926/0/4926
v$process_memory: Category/Alloc/Used/Max=SQL/0/0/47,PL/SQL/4850/4838/4850,Other/76//76,
[Owner; Unit; Type; Used; Free; sum_abs_mb(2412)]
S; PKG_MEM_TEST; 11 (package body); 1177; 28; 1206
S; PKG_MEM_TEST; 9  (package); 1177; 28; 1206

-------- 7. PKG_MEM_TEST.run_2 START --------
v$process: (SID=854)Used/Alloc/Freeable/Max=4924/4926/0/4926
v$process_memory: Category/Alloc/Used/Max=SQL/0/0/47,PL/SQL/4850/4838/4850,Other/76//76,
[Owner; Unit; Type; Used; Free; sum_abs_mb(2412)]
S; PKG_MEM_TEST; 11 (package body); 1177; 28; 1206
S; PKG_MEM_TEST; 9  (package); 1177; 28; 1206

-------- 8. PKG_MEM_TEST.run_2 local_rec_tab ALLOCATED --------
v$process: (SID=854)Used/Alloc/Freeable/Max=6138/6141/0/6141
v$process_memory: Category/Alloc/Used/Max=SQL/0/0/47,PL/SQL/6062/6047/6062,Other/78//78,
[Owner; Unit; Type; Used; Free; sum_abs_mb(2412)]
S; PKG_MEM_TEST; 11 (package body); 1177; 28; 1206
S; PKG_MEM_TEST; 9  (package); 1177; 28; 1206

-------- 9. PROC_MEM_TEST END --------
v$process: (SID=854)Used/Alloc/Freeable/Max=4924/6141/0/6141
v$process_memory: Category/Alloc/Used/Max=SQL/0/0/47,PL/SQL/4850/4838/6062,Other/1291//1291,
[Owner; Unit; Type; Used; Free; sum_abs_mb(2412)]
S; PKG_MEM_TEST; 11 (package body); 1177; 28; 1206
S; PKG_MEM_TEST; 9  (package); 1177; 28; 1206

-------- 10. PKG_MEM_TEST.run_1 END --------
v$process: (SID=854)Used/Alloc/Freeable/Max=3710/6141/0/6141
v$process_memory: Category/Alloc/Used/Max=SQL/0/0/47,PL/SQL/3638/3629/6062,Other/2503//2503,
[Owner; Unit; Type; Used; Free; sum_abs_mb(2412)]
S; PKG_MEM_TEST; 11 (package body); 1177; 28; 1206
S; PKG_MEM_TEST; 9  (package); 1177; 28; 1206

In Step 8, the total used memory is;
     6138 MB
but only 2412 from
    PKG_MEM_TEST; 11 (package body); 1177
  PKG_MEM_TEST; 9  (package); 1177
are listed.

The 3 local allocations in Steps:
  4. PKG_MEM_TEST.run_1 local_rec_tab
  6. PROC_MEM_TEST local_rec_tab
  8. PKG_MEM_TEST.run_2 local_rec_tab
are not reported.

2. Populate process_memory_detail


dbms_session.get_package_memory_utilization is restricted to report memory usage of caller's session, aggregated by each package (spec and body) name, which is a point of view in applications, and does not point out the details of allocated heap details.

V$PROCESS_MEMORY_DETAIL (Oracle 10.2 introduced) lists PGA memory usage by category, heap_name, and component name for each Oracle process, and summarized in V$PROCESS_MEMORY by category. They expose memory usage in the dimension of heap components, a point of view in program code.

Test Code 2 provides a V$PROCESS_MEMORY_DETAIL sampling tool to collect and monitor memory changes.

Run:

exec pga_sampling(p_sid => 234);

Query memory usage per sampling and display memory deviation by:

select v.*, mb - lag(mb) over(order by run) mb_delta 
  from(
    select run, timestamp, session_id, session_serial#, pid
          ,round(sum(bytes)/1024/1024) mb
          ,sum(allocation_count) allocation_count
    from process_memory_detail_v 
    group by run, timestamp, session_id, session_serial#, pid) v
order by run;     

List top 3 heap memory usages for each sampling by:

select run, timestamp, session_id, pid, round(sum(bytes)/1024/1024) mb,
       (select listagg(rpad(name||'('||round(bytes/1024/1024)||', '||allocation_count||')', 40, chr(32)), '; ') 
               within group (order by bytes desc) agg
          from (select * from process_memory_detail_v c 
                 where c.run = v.run and c.pid = v.pid and bytes > 0
                 order by bytes desc) c 
         where rownum <= 3
         ) "NAME(MB, ALLOC_COUNT) List"
from process_memory_detail_v v
group by run, timestamp, session_id, pid
order by run, timestamp, session_id, pid;

Join above query with v$active_session_history (or dba_hist_active_sess_history), one can approximately locate the memory usage related to PL/SQL program unit. Starting from this PL/SQL program unit, one can use 12c UTL_CALL_STACK (or BMS_UTILITY.FORMAT_CALL_STACK) to backtrace all call_stack involved units.

with sq as (
  select run, timestamp, v.session_id, session_serial#, pid, round(sum(bytes)/1024/1024) mb
        ,(select listagg(rpad(name||'('||round(bytes/1024/1024)||', '||allocation_count||')', 40, chr(32)), '; ') 
                 within group (order by bytes desc) agg
            from (select * from process_memory_detail_v c 
                   where c.run = v.run and c.pid = v.pid and bytes > 0
                   order by bytes desc) c 
           where rownum <= 3
           ) "NAME(MB, ALLOC_COUNT) List"
  from process_memory_detail_v v
  group by run, timestamp, v.session_id, session_serial#, pid)
select p.*
      ,(select owner||'.'||object_name||
               case when procedure_name is not null then '.' || procedure_name end
         from dba_procedures
        where object_id = s.plsql_entry_object_id and subprogram_id = s.plsql_entry_subprogram_id)
       plsql_entry
      ,s.sample_time, round(s.pga_allocated/1024/1024) pga_allocated_mb
  from sq p, v$active_session_history s
where p.session_id = s.session_id
  and p.session_serial# = s.session_serial#
  and p.timestamp between s.sample_time and s.sample_time + interval'1' second
 order by run, timestamp, p.session_id, p.session_serial#, pid, s.sample_time;


3. PGA memory internals


Look output of the first query in above Section, pick one RUN with some peak memory usage, for example, 4, Run query:

select run, category, name, heap_name, depth, path
      ,round(sum(bytes/1024)) kb, sum(allocation_count) alloc_count
      ,heap_descriptor, parent_heap_descriptor, cycle
from (
  select v.*, (level-1) depth
        ,sys_connect_by_path('('||category||' , '||name||' , '||heap_name||')', ' -> ') path
        ,connect_by_iscycle as cycle
  from process_memory_detail_v v
  where lower(name) like '%recursive addr reg file%'
  start with parent_heap_descriptor = '00' and run = 4
  connect by nocycle prior heap_descriptor = parent_heap_descriptor and prior run = run
) 
--where lower(name) like '%recursive addr reg file%'
group by run, category, name, heap_name, heap_descriptor, parent_heap_descriptor, depth, path, cycle
--having sum(bytes/1024) > 1024
order by run, category, name, heap_name, depth, kb;

  • It depicts the PGA heap tree structure by connecting heap_descriptor with parent_heap_descriptor.
  • We can observe that only "Other" Category has depth 0 (root) nodes, and all other Categories are subtrees to "Other".
    (One exception is when CATEGORY = 'PL/SQL' and NAME='miscellaneous', both heap_descriptor and parent_heap_descriptor equal to '00', causing cycle)
  • One time we noticed certain high PGA memory consumptions. By running above query, it turns out that the main contribution is due to "recursive addr reg file". Further searching Oracle MOS, it is documented as something related to PLSQL anonymous blocks.
    (MOS Bug 9478199 - Memory corruption / ORA-600 from PLSQL anonymous blocks (Doc ID 9478199.8)).
  • dbms_session.get_package_memory_utilization is hard to inject into existing code, let alone Oracle background processes. However, populating process_memory_detail opens a tiny door to peer Oracle internals, even for background processes, for example, PMON, DBWx, CJQ0, MMON.

4. Test Code 1


create or replace package pkg_mem_test is
  type t_rec        is record (id number, text varchar2(1000));
  type t_rec_tab    is table of t_rec index by pls_integer;
  spec_rec_tab      t_rec_tab;
  
  procedure run_1(p_cnt number);
  procedure run_2(p_cnt number);
end;
/

create or replace procedure proc_mem_test(p_cnt number) as
  type t_rec      is record (id number, text varchar2(1000));
  type t_rec_tab  is table of t_rec index by pls_integer;
  local_rec_tab   t_rec_tab;
begin
  dump_mem_usage.run('PROC_MEM_TEST START');

  select level id, rpad('ABC', 1000, 'X') text 
  bulk collect into local_rec_tab
  from dual connect by level <= p_cnt;
  
  dump_mem_usage.run('PROC_MEM_TEST local_rec_tab ALLOCATED');
  
  pkg_mem_test.run_2(p_cnt);
  
  dump_mem_usage.run('PROC_MEM_TEST END');
end;
/

create or replace package body pkg_mem_test is
  body_rec_tab      t_rec_tab;
  
  procedure run_1(p_cnt number) as
    local_rec_tab   t_rec_tab;
  begin
    dump_mem_usage.run('PKG_MEM_TEST.run_1 START');
  
    select level id, rpad('ABC', 1000, 'X') text 
    bulk collect into spec_rec_tab
    from dual connect by level <= p_cnt;
  
    dump_mem_usage.run('PKG_MEM_TEST.run_1 spec_rec_tab ALLOCATED');
    
    select level id, rpad('ABC', 1000, 'X') text 
    bulk collect into body_rec_tab
    from dual connect by level <= p_cnt;
  
    dump_mem_usage.run('PKG_MEM_TEST.run_1 body_rec_tab ALLOCATED');
    
    select level id, rpad('ABC', 1000, 'X') text 
    bulk collect into local_rec_tab
    from dual connect by level <= p_cnt;
  
    dump_mem_usage.run('PKG_MEM_TEST.run_1 local_rec_tab ALLOCATED');
    
    proc_mem_test(p_cnt);
    
    dump_mem_usage.run('PKG_MEM_TEST.run_1 END');
  end;
  
  procedure run_2(p_cnt number) as
    local_rec_tab    t_rec_tab;
  begin
    dump_mem_usage.run('PKG_MEM_TEST.run_2 START');
  
    select level id, rpad('ABC', 1000, 'X') text 
    bulk collect into local_rec_tab
    from dual connect by level <= p_cnt;
  
    dump_mem_usage.run('PKG_MEM_TEST.run_2 local_rec_tab ALLOCATED');  
    end;
end;
/

-- exec pkg_mem_test.run_1(1000*1000);

5. Test Code 2


drop table process_memory_detail_v;

create table process_memory_detail_v as 
  select 123 run, rpad('A', 40, 'X') run_name, timestamp'1998-02-17 11:22:00' timestamp
        ,234 session_id, 345 session_serial#, v.* 
  from v$process_memory_detail v where 1=2;
  
-- sampling for p_dur seconds in p_interval seconds interval.
create or replace procedure pga_sampling(p_sid number, p_dur number := 120, p_interval number := 1) as
  l_start_time     number := dbms_utility.get_time;
  l_sample_time    number;
  l_sleep_time     number;
  l_pid            number;
  l_sid            number;
  l_serial#        number;
  l_run            number := 0;
  l_pga_status     varchar2(10) := 'NOT';
  l_run_name       varchar2(40) := 'PGA Sampling('||p_sid||', '||p_dur||', '||p_interval||')';
begin
  select pid, s.sid, s.serial#
    into l_pid, l_sid, l_serial#
    from v$process p, v$session s
   where p.addr = s.paddr and s.sid = p_sid and rownum = 1;  
               
  l_sample_time := dbms_utility.get_time;
  while ((l_sample_time - l_start_time)/100 < p_dur) loop 
    execute immediate q'[alter session set events 'immediate trace name PGA_DETAIL_GET level ]'||l_pid||q'[']'; 
    -- wait status = COMPLETE when status = SCANNING, or ENABLED but elapsed time is over duration
    while (true) loop
     select status into l_pga_status from v$process_memory_detail_prog where pid = l_pid;
     exit when l_pga_status = 'COMPLETE' or ((dbms_utility.get_time - l_start_time)/100 > p_dur);
     dbms_lock.sleep(0.1);
    end loop;
    delete from process_memory_detail_v 
     where pid = l_pid and session_id = l_sid and session_serial# = l_serial# and run = l_run;
    insert into process_memory_detail_v select l_run, l_run_name, systimestamp, l_sid, l_serial#, v.* 
      from v$process_memory_detail v where pid = l_pid;
    -- outcomment to keep last PGA_DETAIL
    -- execute immediate q'[alter session set events 'immediate trace name PGA_DETAIL_CANCEL level ]'||l_pid||q'[']';  
    commit; 
    l_run := l_run + 1;    
    l_sleep_time := p_interval - (dbms_utility.get_time - l_sample_time)/100;
    if l_sleep_time > 0 then
     dbms_lock.sleep(l_sleep_time);
    end if;
    l_sample_time := dbms_utility.get_time;
  end loop;
end;
/
    
-- exec pga_sampling(p_sid => 234);

References

  1. Oracle MOS Notes: How To Find Where The Memory Is Growing For A Process (Doc ID 822527.1)
  2. Oracle Memory Troubleshooting, Part 4: Drilling down into PGA memory usage with V$PROCESS_MEMORY_DETAIL 
  3. dbms_session package_memory_utilization