10205關閉資料庫出現ORA-600(kjccgmb:1)錯誤

在Oracle 10205上發現了這個錯誤資訊。

在alert中詳細錯誤資訊為：

Wed Jan 12 15:36:24 EAT 2011
Shutting down instance (immediate)
Wed Jan 12 15:36:24 EAT 2011
Shutting down instance: further logons disabled
Wed Jan 12 15:36:24 EAT 2011
Stopping background process CJQ0
Wed Jan 12 15:36:24 EAT 2011
Stopping background process QMNC
Wed Jan 12 15:36:26 EAT 2011
Stopping background process MMNL
Wed Jan 12 15:36:27 EAT 2011
Stopping background process MMON
License high water mark = 11
Wed Jan 12 15:36:28 EAT 2011
Job queue slave processes stopped
Wed Jan 12 15:36:30 EAT 2011
ALTER DATABASE CLOSE NORMAL
Wed Jan 12 15:36:30 EAT 2011
SMON: disabling tx recovery
SMON: disabling cache recovery
Wed Jan 12 15:36:33 EAT 2011
Shutting down archive processes
Archiving is disabled
Archive process shutdown avoided: 0 active
Thread 2 closed at log sequence 13854
Successful close of redo thread 2
Wed Jan 12 15:36:36 EAT 2011
Completed: ALTER DATABASE CLOSE NORMAL
Wed Jan 12 15:36:36 EAT 2011
ALTER DATABASE DISMOUNT
Completed: ALTER DATABASE DISMOUNT
ARCH: Archival disabled due to shutdown: 1089
Shutting down archive processes
Archiving is disabled
Archive process shutdown avoided: 0 active
ARCH: Archival disabled due to shutdown: 1089
Shutting down archive processes
Archiving is disabled
Archive process shutdown avoided: 0 active
Wed Jan 12 15:38:05 EAT 2011
OUT OF MEMORY for message buffers
Wed Jan 12 15:38:05 EAT 2011
Errors in file /opt/oracle/db/admin/orcl/bdump/orcl2_lms0_24081.trc:
ORA-00600: internal error code, arguments: [kjccgmb:1], [], [], [], [], [], [], []
Wed Jan 12 15:38:05 EAT 2011
OUT OF MEMORY for message buffers
Wed Jan 12 15:38:05 EAT 2011
Errors in file /opt/oracle/db/admin/orcl/bdump/orcl2_lms1_24083.trc:
ORA-00600: internal error code, arguments: [kjccgmb:1], [], [], [], [], [], [], []
Wed Jan 12 15:38:06 EAT 2011
Trace dumping is performing id=[cdmp_20110112153806]
Wed Jan 12 15:39:32 EAT 2011
Errors in file /opt/oracle/db/admin/orcl/bdump/orcl2_lms0_24081.trc:
ORA-00600: internal error code, arguments: [kjccgmb:1], [], [], [], [], [], [], []
Wed Jan 12 15:39:32 EAT 2011
LMS0: terminating instance due to error 484
Wed Jan 12 15:39:32 EAT 2011
System state dump is made for local instance
System State dumped to trace file /opt/oracle/db/admin/orcl/bdump/orcl2_diag_24073.trc
Wed Jan 12 15:39:32 EAT 2011
Errors in file /opt/oracle/db/admin/orcl/bdump/orcl2_diag_24073.trc:
ORA-00484: LMS* process terminated with error
Wed Jan 12 15:39:32 EAT 2011
Trace dumping is performing id=[cdmp_20110112153932]
Wed Jan 12 15:39:34 EAT 2011
Shutting down instance (abort)
License high water mark = 11
Wed Jan 12 15:39:38 EAT 2011
Instance terminated by LMS0, pid = 24081
Wed Jan 12 15:39:39 EAT 2011
Instance terminated by USER, pid = 17989
Wed Jan 12 15:41:00 EAT 2011

而對應的trace資訊：

$ more /opt/oracle/db/admin/orcl/bdump/orcl2_lms0_24081.trc
/opt/oracle/db/admin/orcl/bdump/orcl2_lms0_24081.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.5.0 - 64bit Production
With the Partitioning, Real Application Clusters, Data Mining and Real Application Testing options
ORACLE_HOME = /opt/oracle/db
System name:    HP-UX
Node name:      hisdb2
Release:        B.11.31
Version:        U
Machine:        ia64
Instance name: orcl2
Redo thread mounted by this instance: 0
Oracle process number: 7
Unix process pid: 24081, image: oracle@hisdb2 (LMS0)

*** SERVICE NAME:() 2011-01-11 14:59:27.444
*** SESSION ID:(1650.1) 2011-01-11 14:59:27.444
 0 GCS shadows cancelled, 0 closed
 0 GCS resources traversed, 0 cancelled
 LMS 0: 618968 GCS resources on freelist, 619008 on array, 619008 allocated
 0 GCS shadows traversed, 0 replayed, 0 duplicates
RCFG(4) lms 0 finished replaying gcs resources
 0 write requests issued in 28 GCS resources
.
.
.
 0 PIs marked suspect, 0 flush PI msgs
 lms 0 finished fixing gcs write protocol
*** 2011-01-12 15:36:43.846
=================================
Begin 4031 Diagnostic Information
=================================
The following information assists Oracle in diagnosing
causes of ORA-4031 errors.  This trace may be disabled
by setting the init.ora _4031_dump_bitvec = 0
=====================================
Allocation Request Summary Informaton
=====================================
Current information setting:  04014fff
  SGA Heap Dump Interval=3600 seconds
  Dump Interval=300 seconds
  Last Dump Time=01/12/2011 15:36:35
  Dump Count=1
Allocation request for:    ges regular m
  Heap: c000000100e36920, size: 480
******************************************************
HEAP DUMP heap name="sga heap(1,1)"  desc=c000000100e36920
 extent sz=0xfe0 alt=216 het=32767 rec=9 flg=-126 pc=0
 parent=0000000000000000 wner=0000000000000000 nex=0000000000000000 xsz=0x1000000
 latch set 1 of 2
 durations enabled for this heap
 reserved granules for root 0 (granule size 16777216)
====================
Process State Object
====================
----------------------------------------
SO: c00000023f8fc8f8, type: 2, owner: 0000000000000000, flag: INIT/-/-/0x00
  (process) Oracle pid=7, calls cur/top: c00000023cf87400/c00000023cf85578, flag: (6) SYSTEM
            int error: 0, call error: 0, sess error: 0, txn error 0
  (post info) last post received: 0 0 94
              last post received-location: KJCS Post snd proxy to flush msg
              last process to post me: c00000023f8fd8f8 1 0
              last post sent: 0 0 98
              last post sent-location: kjbrcvdscn: scn acked
              last process posted by me: c00000023f8fd8f8 1 0
  (latch info) wait_event=0 bits=20
    holding    (efd=6) c000000100e11fa8 Child KJC message pool free list level=5 child#=1
        Location from where latch is held: kjcsmpav: allocate a msg buffer:
        Context saved from call: 0
        state=busy, wlstate=free
        waiters [orapid (seconds since: put on list, posted, alive check)]:
         8 (8, 1294817803, 8)
         waiter count=1
    Process Group: DEFAULT, pseudo proc: c00000023fa74fe8
    O/S info: user: oracle, term: UNKNOWN, ospid: 24081
    OSD pid info: Unix process pid: 24081, image: oracle@hisdb2 (LMS0)
PSO child state object changes :
Dump of memory from 0xC00000023F89C3A0 to 0xC00000023F89C5A8
C00000023F89C3A0 00000008 00000000 C0000002 3B72BDF0  [............;r..]
C00000023F89C3B0 00000010 000313F4 C0000002 3CF85578  [............<.ux>.
.
.
0xc000000100000000 - 0xc000000241003000  shm (5)         rwx : -XS-      
******************* End of process map dump ****************
==============================
Memory Utilization of Subpool 1
================================
     Allocation Name          Size  
_________________________  __________
"free memory              "    65315360 
"miscellaneous            "           0 
"trace buffer             "      278528 
"dsktab_kfgsg             "       50440 
"gcs res hash bucket      "      524288 
.
.
.
"KFG SO child             "        5312 
"KGKP randnum             "       40000 
==============================
Memory Utilization of Subpool 2
================================
     Allocation Name          Size  
_________________________  __________
"free memory              "    39095504 
"miscellaneous            "           0 
"dpslut_kfdsg             "         512 
"File Space Usage         "       11344 
"trace buffer             "      327680 
"trace_knlasg             "         504 
"ges big msg buffers      "    15936168 
.
.
.
  SGA Heap Dump Count = 0
===============================
End 4031 Diagnostic Information
===============================
kjcsmpav: error 4031 detected
kjcsmpav: error 4031 detected
kjcsmpav: error 4031 detected
kjcsmpav: error 4031 detected
kjcsmpav: error 4031 detected
kjcsmpav: error 4031 detected
.
.
.
kjcsmpav: error 4031 detected
*** 2011-01-12 15:38:04.245
kjcsmpav: error 4031 detected
kjcsmpav: error 4031 detected
kjcsmpav: error 4031 detected

可以看到，在關閉資料庫的過程中，Oracle出現了ORA-600(KJCCGMB:1)的錯誤，而這這個錯誤中，出現了大量的ORA-4031錯誤。

這顯然是Oracle在回收或釋放記憶體的時候出現的bug。

檢查了metalink文件，對應的bug資訊是BUG 6126415，Oracle在11.1.0.7才FIXED這個bug，這個問題可能發生在小於11.2的任何版本上。

好在記憶體不足的問題只是發生在關閉資料庫的時候，最大影響不過是使用SHUTDOWN ABORT來關閉資料庫，對資料庫的日常使用沒有影響。