Oracle memory troubleshooting, Part 3: Automatic top subheap dumping with heapdump

If you haven’t read them – here are the previous articles in Oracle memory troubleshooting series: Part 1, Part 2

In Oracle, the HEAPDUMP dump event in Oracle allows you to dump various heap contents to tracefile. With adding the “level” parameter to this dump event, you can specify which heaps to dump.

Julian Dyke has documented most of the levels here.

There are two little known, but useful level bits for heapdumps – bit 0x10000000 and 0x20000000. These allow Oracle to dump top-5 biggest subheaps in a heap recursively.

When bit 0x10000000 is enabled then Oracle dumps the top-5 subheaps inside any heap its instructed to dump.
When bit 0x20000000 is enabled then Oracle dumps the top-5 subheaps as mentioned above, but in addition Oracle recursively dumps top-5 subheaps inside any subheaps automatically dumped above. So instead of dumping 1 level of subheaps, Oracle recursively dumps 2 levels if such sub-sub-heaps exist.

This reduces the amount of manual work – as Oracle can drill down towards the root cause automatically and dump the relevant information.

Here’s a little test case:

I set the serverout buffer unlimited (Oracle 10.2+) so that Oracle would buffer unlimited amount of dbms_output data in UGA (this is also a “good” way for using up all the memory in your server so you use “unlimited” with care).

SQL> set serverout on size unlimited
SQL>
SQL> exec for i in 1..1000000 loop dbms_output.put_line(lpad('x',10,'x')); end loop;

Without the recursive top subheap dumping we would see output like this (after processing the tracefile with heapdump_analyzer):

This is the usual way for dumping a target process private heap:

SQL> oradebug setorapid 35
Oracle pid: 35, Unix process pid: 26457, image: oracle@linux03
SQL> oradebug dump heapdump 1     <-- level 1 dumps all top level private heaps (top-level PGA,UGA and call heap)
Statement processed.
SQL>

And the output is:

[oracle@linux03 trace]$ heapdump_analyzer LIN11G_ora_26486.trc

  -- Heapdump Analyzer v1.00 by Tanel Poder ( http://www.tanelpoder.com )

  Total_size #Chunks  Chunk_size,        From_heap,       Chunk_type,  Alloc_reason
  ---------- ------- ------------ ----------------- ----------------- -----------------
    55065316     841      65476 ,     top uga heap,         freeable,  session heap          <-- session heap is allocated from top uga heap
    41218392    2517      16376 ,     session heap,         freeable,  koh-kghu sessi      <-- koh-kghu session heap is allocated from session heap
    13650208     836      16328 ,     session heap,             free,
       65520       1      65520 ,         pga heap,             free,
       65476       1      65476 ,     top uga heap,         recreate,  session heap
       57736      14       4124 ,     session heap,         freeable,  kxsFrame4kPage
...

We would see that most of the uga memory (roughly 41MB of 55MB) is allocated for for some reason “koh-kghu sessi”. This is a session heap where from allocations for various objects like PL/SQL variables, records and collections are done. So when we’d want to drill down and see inside that heap we could use the HEAPDUMP_ADDR dump with that heap descriptors address as parameter to look inside it.

However with these extra bits mentioned above, Oracle can automatically dump us the contents of biggest subheaps inside the heaps we asked it to dump:

SQL> oradebug setorapid 35
Oracle pid: 35, Unix process pid: 26457, image: oracle@linux03
SQL> oradebug dump heapdump 536870913     <-- 536870913 = 0x20000001 which means private memory dump + 2 levels of subheap dump recursion
Statement processed.
SQL>

The heapdump analyzer output will be more detailed in this case:

[oracle@linux03 trace]$ heapdump_analyzer LIN11G_ora_26486.trc

  -- Heapdump Analyzer v1.00 by Tanel Poder ( http://www.tanelpoder.com )

  Total_size #Chunks  Chunk_size,        From_heap,       Chunk_type,  Alloc_reason
  ---------- ------- ------------ ----------------- ----------------- -----------------
    55065316     841      65476 ,     top uga heap,         freeable,  session heap          <-- session heap is allocated from top uga heap
    41218392    2517      16376 ,     session heap,         freeable,  koh-kghu sessi      <-- koh-kghu session heap is allocated from session heap
    32106828    1963      16356 ,   koh-kghu sessi,         freeable,  pl/sql vc2           <-- pl/sql vc2 (varchar2) collection is allocated from koh-kghu session heap
    13650208     836      16328 ,     session heap,             free,
     9044868     553      16356 ,   koh-kghu sessi,         freeable,  pmucalm coll
       65520       1      65520 ,         pga heap,             free,
       65476       1      65476 ,     top uga heap,         recreate,  session heap
       57736      14       4124 ,     session heap,         freeable,  kxsFrame4kPage
...

As you see above, Oracle has dug a level deeper and figured out that a major part of koh-kghu session heap contains allocations for “pl/sql vc2″ reasons (vc2=varchar2).

When you look in a raw heapdump trace you would see “FIVE LARGEST SUB HEAPS” sections, the example below dumps the top-5 subheaps inside a session heap:

FIVE LARGEST SUB HEAPS for heap name="session heap"   desc=0xd66f7c
  Subheap ds=0xd9c600  heap name=  koh-kghu sessi  size=        41217520
   owner=(nil)  latch=(nil)
  Subheap ds=0x74e1b54  heap name=  koh-kghu sessi  size=           17448
   owner=(nil)  latch=(nil)
  Subheap ds=0xd7c4ec  heap name=  koh-kghu sessi  size=            5200
   owner=(nil)  latch=(nil)
  Subheap ds=0xd7ea48  heap name=      PLS SGA hp  size=            4192
   owner=(nil)  latch=(nil)
  Subheap ds=0xd7bc04  heap name=  Alloc environm  size=            4144
   owner=(nil)  latch=(nil)
SUBHEAP 1: desc=0xd9c600
******************************************************
HEAP DUMP heap name="koh-kghu sessi"  desc=0xd9c600
 extent sz=0x224 alt=32767 het=32767 rec=0 flg=2 opc=2
 parent=0xd66f7c owner=(nil) nex=(nil) xsz=0x3fec heap=(nil)
 fl2=0x20, nex=(nil)
EXTENT 0 addr=0x74fd014
  Chunk  74fd01c sz=    16356    freeable  "pl/sql vc2     "
EXTENT 1 addr=0x74e5024
  Chunk  74e502c sz=    16356    freeable  "pl/sql vc2     "
EXTENT 2 addr=0x74e901c
  Chunk  74e9024 sz=    16356    freeable  "pl/sql vc2     "
EXTENT 3 addr=0x74ed014
  Chunk  74ed01c sz=    16356    freeable  "pl/sql vc2     "
EXTENT 4 addr=0x74d5024
  Chunk  74d502c sz=    16356    freeable  "pmucalm coll   "
EXTENT 5 addr=0x74d901c
  Chunk  74d9024 sz=    16356    freeable  "pl/sql vc2     "

If you want to get a little terser overview of the heap/subheap details you can use the following command below:

[oracle@linux03 trace]$ egrep "HEAP DUMP|FIVE LARGEST|^SUBHEAP|Subheap|^Total" LIN11G_ora_26486.trc
[...snip...]
HEAP DUMP heap name="top uga heap"  desc=0xfaa4540 <-- heap which we are dumping
Total heap size    = 55171208
Total free space   =    40416
FIVE LARGEST SUB HEAPS for heap name="top uga heap"   desc=0xfaa4540
  Subheap ds=0xd66f7c  heap name=    session heap  size=        55130792  <-- the first of top-5 subheaps is a session heap
SUBHEAP 1: desc=0xd66f7c
HEAP DUMP heap name="session heap"  desc=0xd66f7c <-- lets dump it
Total heap size    = 55113936
Total free space   = 13704108
FIVE LARGEST SUB HEAPS for heap name="session heap"   desc=0xd66f7c <-- this is a top-5 subheap dump at level 2 (under the session heap found at previous level)
  Subheap ds=0xd9c600  heap name=  koh-kghu sessi  size=        41217520 <-- we've found top-5 biggest subheaps and will dump them below
  Subheap ds=0x74e1b54  heap name=  koh-kghu sessi  size=           17448
  Subheap ds=0xd7c4ec  heap name=  koh-kghu sessi  size=            5200
  Subheap ds=0xd7ea48  heap name=      PLS SGA hp  size=            4192
  Subheap ds=0xd7bc04  heap name=  Alloc environm  size=            4144
SUBHEAP 1: desc=0xd9c600
HEAP DUMP heap name="koh-kghu sessi"  desc=0xd9c600
Total heap size    = 41167104
Total free space   =        0
FIVE LARGEST SUB HEAPS for heap name="koh-kghu sessi"   desc=0xd9c600
SUBHEAP 2: desc=0x74e1b54
HEAP DUMP heap name="koh-kghu sessi"  desc=0x74e1b54
Total heap size    =    17392
Total free space   =    17392
FIVE LARGEST SUB HEAPS for heap name="koh-kghu sessi"   desc=0x74e1b54
SUBHEAP 3: desc=0xd7c4ec
HEAP DUMP heap name="koh-kghu sessi"  desc=0xd7c4ec
Total heap size    =     5144
Total free space   =        0
FIVE LARGEST SUB HEAPS for heap name="koh-kghu sessi"   desc=0xd7c4ec
SUBHEAP 4: desc=0xd7ea48
HEAP DUMP heap name="PLS SGA hp"  desc=0xd7ea48
Total heap size    =     4136
Total free space   =      640
FIVE LARGEST SUB HEAPS for heap name="PLS SGA hp"   desc=0xd7ea48
SUBHEAP 5: desc=0xd7bc04
HEAP DUMP heap name="Alloc environm"  desc=0xd7bc04
Total heap size    =     4108
Total free space   =        0
FIVE LARGEST SUB HEAPS for heap name="Alloc environm"   desc=0xd7bc04

These dumping bits work for shared pool dumps as well by the way (when using level 0x20000002 for example). Remember that shared pool heapdumps are dangerous though as they can hang your instance for the dump duration so that even sysdba can’t log on (that’s why shared pool heapdumps should be used as a last resort when diagnosing memory shortage and leaks).

This entry was posted in Oracle and tagged , . Bookmark the permalink.

5 Responses to Oracle memory troubleshooting, Part 3: Automatic top subheap dumping with heapdump

  1. Martin says:

    Hello Tanel,
    thank you for your post.
    I’ve tried your way to reproduce an issue with very large UGA size (> 1 GB), it works fine.
    However your testcase makes (on 10.2.0.4/AIX/dedicated server) both statistics ‘session pga memory’ and ‘session uga memory’ to show the large memory consumption.
    Do you know a simple testcase which makes just ‘session uga memory consumption’ grow?
    Greetings from Austria,
    Martin

  2. Tanel Poder says:

    Hi Martin,

    It’s a bit longer story – Oracle’s v$sesstat memory stats are not entirely correct in regard to what really happens with private memory allocation. They mimic the old-fashioned situation where UGA was physically INSIDE PGA heap, but its not like that anymore.

    Nowadays, with realfree private memory management, PGA, UGA and Callheaps are completely separate top-level heaps (allocated separately from OS using mmap) and UGA is not physically inside PGA anymore.

    A heapdump can easily confirm this, but in v$sesstat UGA is still reported inside PGA, so it’s probably impossible to create a situation where UGA is bigger than PGA in v$sesstat (unless you hit a bug or there’s some change which I’m not aware of)

  3. Dion Cho says:

    Tanel, this is a little but very convenient unknown extension!

    Anyway, instead of
    oradebug dump heapdump 536870913
    I would use
    oradebug dump heapdump 0x20000001.

  4. Tanel Poder says:

    Yep, that’s a better understandable format for the parameter. Actually pretty much every numeric value in the event synax can be either in hex or decimal (I’ve shown one example with alter session here: http://blog.tanelpoder.com/2009/03/03/the-full-power-of-oracles-diagnostic-events-part-1-syntax-for-ksd-debug-event-handling/ )

    For some reason it didnt seem to work with oradebug (but worked with alter session) when I tried – BUT now when I try again it works, so I must have done something wrong. Thanks for pointing this out to me!!!

  5. Miladin says:

    This is just funny.I got my post on the same topic just ready to publish and did last check using google and found your post.

    I found this event looking at Oracle bug Doc ID: 784804.1

    Miladin

Leave a Reply

Your email address will not be published. Required fields are marked *

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>