July 1, 2012

diagnose 04030: koh-kghu sessi and large of free space

Recently one of our prod DB repeatly got 04030 error:

ORA-04030: out of process memory when trying allocate 64024 bytes (qmxeventInitCt,qmxeventInitctx:buffer)
ORA-04030: out of process memory when trying allocate 824504 bytes (pga heap,kco buffer)
ORA-04030: out of process memory when trying allocate 16328 bytes (PLSQL Opt Pool,pdz7M04_Create)

ORA-04030: (pga heap,kco buffer) may indiate kco buffer in PGA heap consuming too much space and leading to 04030.

But in our case, each ORA-04030's parameters are different.
It means some other type allocated most of PGA, and left no space for other types PGA request.


Trace file shows the 04031 coming from an daily expdp job:
Below is current SQL:

*** 2012-06-30 22:25:39.959
dbkedDefDump(): Starting incident default dumps (flags=0x2, level=3, mask=0x0)
----- Current SQL Statement for this session (sql_id=b1n2qbfhwsyhb) -----
CREATE TABLE "ET$036AA8ED0002"
   (    "ABSTRACT_ID",
        "FEED_ID",
        "SEC_STATE",
        "IS_ACTIVE",
        "CREATED_BY",
        "CREATED_DATE",
        "UPDATED_BY",
        "UPDATED_DATE",
        "XML_RSS_ABSTRACT",
        "XML_ABSTRACT_SOURCE"
   ) ORGANIZATION EXTERNAL
    ( TYPE ORACLE_DATAPUMP DEFAULT DIRECTORY "DATA_RAD" ACCESS PARAMETERS ( DEBUG = (0 , 0) DATAPUMP INTERNAL TABLE "POCDBA02"."T_NR_ABSTRACT"  JOB ( "SYSTEM
","SYS_EXPORT_FULL_20",1) WORKERID 1 PARALLEL 1 VERSION '11.2.0.2' ENCRYPTPASSWORDISNULL  COMPRESSION DISABLED  ENCRYPTION DISABLED ) LOCATION ('bogus.dat')
)  PARALLEL 1 REJECT LIMIT UNLIMITED
    AS SELECT /*+ PARALLEL(KU$,1) */ "ABSTRACT_ID", "FEED_ID", "SEC_STATE", "IS_ACTIVE", "CREATED_BY", "CREATED_DATE", "UPDATED_BY", "UPDATED_DATE", SYS_XMLT
_2_SC("XML_RSS_ABSTRACT"), SYS_XMLT_2_SC("XML_ABSTRACT_SOURCE")
    FROM RELATIONAL("PXXX02"."T_NR_AXXXCT" NOT XMLTYPE) KU$

Below is the PGA map from trace file, notice red part:
-------------------------
Private memory usage per Oracle process
Top 10 processes:
-------------------------
(percentage is of 4529 MB total allocated memory)
91% pid 62: 4104 MB used of 4107 MB allocated  <= CURRENT PROC
 2% pid 86: 16 MB used of 83 MB allocated (64 MB freeable)
 1% pid 37: 38 MB used of 41 MB allocated (1088 KB freeable)
 1% pid 38: 28 MB used of 29 MB allocated
 0% pid 15: 13 MB used of 13 MB allocated (64 KB freeable)
 0% pid 13: 13 MB used of 13 MB allocated (64 KB freeable)
 0% pid 14: 13 MB used of 13 MB allocated (64 KB freeable)
 0% pid 59: 6482 KB used of 13 MB allocated (6272 KB freeable)
 0% pid 20: 12 MB used of 13 MB allocated
 0% pid 19: 8853 KB used of 13 MB allocated
From current proc we see the expdp consumed 4000+mb PGA and reached the max limit at OS level. By default in 64-bit linux, the max limit for single process PGA is 4GB, controled by below parameter in OS:
vm.max_map_count=65536
And below parameter in DB:
_realfree_heap_pagesize_hint 65536

The easist solution is increasing the limit to allow process to apply more memory, but the best way is to identify why this process consumed so much memory.
Let's check into the trace file:
=======================================
TOP 10 MEMORY USES FOR THIS PROCESS
---------------------------------------
*** 2012-06-30 22:25:39.707
74% 3041 MB, 66260 chunks: "free memory               "
         session heap    ds=0x2b4fb3e26d30  dsprt=0xb7eec80
25% 1010 MB, 64838 chunks: "qmxtgCreateTempLob        "
         koh-kghu sessi  ds=0x2b4fb6638bd0  dsprt=0x2b4fb3e26d30
 0% 8859 KB, 2185 chunks: "kxsFrame4kPage            "
         session heap    ds=0x2b4fb3e26d30  dsprt=0xb7eec80
 0% 6019 KB, 378 chunks: "pmuccst: adt/record       "  PL/SQL
         koh-kghu sessi  ds=0x2b4fb492b110  dsprt=0x2b4fb3e26d30
 0% 5562 KB,  46 chunks: "XVM Storage               "
         XVM subheap of  ds=0x2b4fb498b278  dsprt=0x2b4fb3d89b38
 0% 3300 KB, 207 chunks: "pmucalm coll              "  PL/SQL
         koh-kghu sessi  ds=0x2b4fb48facf8  dsprt=0x2b4fb3e26d30
 0% 2312 KB, 2627 chunks: "permanent memory          "  SQL
         kxs-heap-p      ds=0x2b4fb5d31898  dsprt=0x2b4fb3e26d30
 0% 2281 KB, 185 chunks: "pl/sql vc2                "  PL/SQL
         koh-kghu sessi  ds=0x2b4fb66a8e30  dsprt=0x2b4fb3e26d30
 0% 1319 KB,  85 chunks: "static frame of inst      "  PL/SQL
         koh-kghu sessi  ds=0x2b4fb5bbfa70  dsprt=0x2b4fb3e26d30
 0% 1288 KB, 160 chunks: "kxsFrame8kPage            "
         session heap    ds=0x2b4fb3e26d30  dsprt=0xb7eec80
We can see the first one is belong to session heap(UGA), and type is "free memory", this is very wierd.

I restart the expdp job, and during it is running, the PGA usage keep increasing, and when the PGA allocation size reached 2gb, i made an PGA dump:
news2 >oradebug setospid 11903 
Statement processed. 
news2 >oradebug dump heapdump 536870913 
Statement processed.

Let's check our trace file:
server803.corporate.ge.com[oracle]_news2> cat db2_dw00_11903.trc.2|grep -i "total heap size"
HEAP DUMP heap name="session heap"  desc=0x2b88a22b6d30
Total heap size    =1768309088
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a487cd60
Total heap size    =429703184
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a2db6110
Total heap size    = 10794656
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a239d2b8
Total heap size    =  4149616
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a22de820
Total heap size    =  1272824
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a2da2c48
Total heap size    =  1178344
HEAP DUMP heap name="pga heap"  desc=0xb7e9240
Total heap size    = 11246712
HEAP DUMP heap name="XVMsubheap"  desc=0x2b88a2214b38
Total heap size    =  5709704
HEAP DUMP heap name="XVM subheap of"  desc=0x2b88a2e67d00
Total heap size    =  5708240
HEAP DUMP heap name="qmxdContextEnc"  desc=0x2b88a2e67c00
Total heap size    =     4216
HEAP DUMP heap name="KSFQ heap"  desc=0x2b88a21d7f30
Total heap size    =  1074104
HEAP DUMP heap name="koh-kghu call "  desc=0x2b88a2740010
Total heap size    =   940200
HEAP DUMP heap name="KFK_IO_SUBHEAP"  desc=0x2b88a20684a8
Total heap size    =   476688
HEAP DUMP heap name="PLS PGA hp"  desc=0x2b88a2210bc0
Total heap size    =   135280
HEAP DUMP heap name="top call heap"  desc=0xb7eea60
Total heap size    =   720680
HEAP DUMP heap name="callheap"  desc=0x2b88a2311108
Total heap size    =   285856
HEAP DUMP heap name="qbcqtcHTHeap"  desc=0x2b88a2354b00
Total heap size    =     6400
HEAP DUMP heap name="qcpi4.c.kgght"  desc=0x2b88a2354738
Total heap size    =     3624
HEAP DUMP heap name="kggec.c.kggfa"  desc=0x2b88a2354478
Total heap size    =     1528
HEAP DUMP heap name="PLS CGA hp"  desc=0x2b88a2b83ee8
Total heap size    =     1992
HEAP DUMP heap name="callheap"  desc=0xb7edc18
Total heap size    =   131064
HEAP DUMP heap name="callheap"  desc=0xb7edb60
Total heap size    =    38000
HEAP DUMP heap name="kti call subhe"  desc=0x2b88a220d7e8
Total heap size    =    36968
HEAP DUMP heap name="top uga heap"  desc=0xb7eec80
Total heap size    =1769554808
HEAP DUMP heap name="session heap"  desc=0x2b88a22b6d30
Total heap size    =1768309088
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a487cd60
Total heap size    =429703184
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a2db6110
Total heap size    = 10794656
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a239d2b8
Total heap size    =  4149616
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a22de820
Total heap size    =  1272824
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a2da2c48
Total heap size    =  1178344

Notice outstanding large part, "top uga heap" is big, caused by "session heap". 
Then let's check session heap:
HEAP DUMP heap name="session heap"  desc=0x2b88a22b6d30
...........
Total heap size    =1768309088
Total free space   =1296798672
...........
FIVE LARGEST SUB HEAPS for heap name="session heap"   desc=0x2b88a22b6d30
  Subheap ds=0x2b88a487cd60  heap name=  koh-kghu sessi  size=       430756008
   owner=(nil)  latch=(nil)
  Subheap ds=0x2b88a2db6110  heap name=  koh-kghu sessi  size=        10821000
   owner=(nil)  latch=(nil)
  Subheap ds=0x2b88a239d2b8  heap name=  koh-kghu sessi  size=         4159400
   owner=(nil)  latch=(nil)
  Subheap ds=0x2b88a22de820  heap name=  koh-kghu sessi  size=         1276088
   owner=(nil)  latch=(nil)
  Subheap ds=0x2b88a2da2c48  heap name=  koh-kghu sessi  size=         1181128
   owner=(nil)  latch=(nil)

We can see session heap is 1.7gb big. 0.5gb consumend on "koh-kghu sessi", and all other 1.2gb are free!
Eventhough the space is free, but it only belong to session heap and can't be used by other types in different heaps.

Why “koh-kghu sessi” consumend so much space and why so many free space are allcoated in session heap while it shouldn't be?

After searched on metalink, we may hit two bugs here, one for free memory, one for "koh-kghu sessi":
1.ORA-04030 encountered by a process which allocate large free memory [ID 1439928.1]
2.Bug 10194031 - EXPDP of OR XML leaks memory / runs slow [ID 10194031.8]


0 Comments:

Post a Comment