ORA-4030错误分析-优快云博客

环境：

OS: SunOS Hostname 5.10 Generic_127111-11 sun4u sparc SUNW,Sun-Fire-V890

DB VERSION: Oracle9i Enterprise Edition Release 9.2.0.8.0 – Production

改动: 安装了CPUJul2009

这里有点要说明的：操作系统是64位的，而数据库是32位的。这个从理论上讲不会造成什么问题的，因为这个系统已经跑了几年了。

症状：执行如下SQL，碰到ORA-4030.

SQL> declare

sr sys_refcursor;

begin

sr:=Pkg_rpt_BillVsAccrual.FN_RPT_BILLVSACCRUAL('DE5','BILL-030',to_date('01/02/2006',

'MM/DD/YYYY'),to_date('02/28/2006', 'MM/DD/YYYY'));

end; 2 3 4 5 6 7

8 /

declare

ERROR at line 1:

ORA-04030: out of process memory when trying to allocate 12548 bytes

(callheap,kks sql text)

ORA-06512: at "SCBID.PKG_RPT_BILLVSACCRUAL", line 25

ORA-06512: at line 4

这个过程要执行二到三个小时，执行这个SP的session的主等待事件是：library cache，伴随少量的shared pool。

[@more@]

在执行过程中，监控PGA的使用情况：

SQL> select p.spid,s.sid,t.name,s.value, sw.event,sw.p1,sw.p2,sw.p3 from v$sesstat s,v$statname t ,v$session_wait sw,v$process p where s.sid=16 and s.statistic#=t.statistic# and t.name like 'session%memory%' and sw.sid=16 and p.addr in (select paddr from v$session where sid=16);

SPID SID NAME VALUE EVENT

P1 P2 P3

------------ ---------- ------------------------------ ---------- -------------------- --------

-- ---------- ----------

17443 16 session uga memory 77040 latch free

980764160 157 0

17443 16 session uga memory max 77040 latch free

980764160 157 0

17443 16 session pga memory 1976775572 latch free

980764160 157 0

17443 16 session pga memory max 1976775572 latch free

980764160 157 0

SQL> select count(1) from v$sql where (hash_value,address) in (select

sql_hash_value,sql_address from v$session where sid=16);

COUNT(1)

----------

4569

从监控的结果来看，这个SESSION PGA的使用是不断增长的，同时也可以看到，这个SESSION正在执行的SQL版本数量也是不断在增长的，在快执行完时，可以看到如下的结果：

SPID SID NAME VALUE EVENT

P1 P2 P3

------------ ---------- ------------------------------ ---------- -------------------- --------

-- ---------- ----------

17443 16 session uga memory 77040 latch free

980764160 157 0

17443 16 session uga memory max 77040 latch free

980764160 157 0

17443 16 session pga memory -1.528E+09 latch free

980764160 157 0

17443 16 session pga memory max -1.528E+09 latch free

980764160 157 0

SQL> select count(1) from v$sql where (hash_value,address) in (select sql_hash_value,sql_address from v$session where sid=16);

COUNT(1)

----------

6384

这里可以看出SESSION PGA已经溢出了。当前的SQL的版本数也增加了。如果按照这一趋势，整个shared pool也有使用完的可能。看到这么多的版本数在增加，可能第一个想到的是，想查看一下，这些SQL为什么不能共享，从这里入手或许可以找到一点信息。但糟糕的事是在V$SQL_SHARED_CURSOR没有一条记录 (可能从这一点可以判断是Oracle的BUG, 按理这么多的版本数，在这张视图里可以找到相应信息的, 另一个问题是这执行一条SQL，不可能解析这么多版本出来，正常情况下，如果shared pool里没有匹配到相应SQL的执行计划，在shared pool里就硬解析一次，生成一个执行计划，也就是版本数增加1, 但从监控的结果来看，事实上并不是如推断的那样，这也不得不怀疑，有可能是碰到BUG) ，根本上就没有相关的蛛丝马迹可寻. 同时在OS层面监控到的相应进程使用的内存是：

PID USERNAME SIZE RSS STATE PRI NICE TIME CPU PROCESS/NLWP

17443 oracle 2878M 2728M sleep 59 0 0:38:22 3.9% oracle/1

...

PID USERNAME SIZE RSS STATE PRI NICE TIME CPU PROCESS/NLWP

17443 oracle 3629M 3244M cpu4 1 0 1:15:00 3.5% oracle/1

这里没有抓到临近报ORA-4030错误时，究竟使用内存多少，但是从上面的结果来看，这个进程是在不断的消耗内存的。再分析这个SP的内容，其实这个SP就是返回一个ref cursor，当然这个ref cursor所指向的那条SQL是相当长，繁杂的。

还有一现象，这个SP有时不报错误，有时执行报错。跟踪这个错误还是比较难的。当然RP也是很重要的。

根据上次的跟踪方法：

oradebug setmypid;

oradebug event 4030 trace name errorstack level 3;name HEAPDUMP level 536870917

执行那个有问题的SP

oradebug event 4030 trace name errorstack off;name HEAPDUMP off;

oradebug tracefile_name;

然后分析那个trace文件，从报的错误，之后以报错，是因为在callheap HEAP里无法再分配内存了。初步分析一下trace文件:

$ ls -l _ora_17443.trc

-rw-r--r-- 1 oracle oinstall 438787862 Jan 22 19:09 _ora_17443.trc

$ grep -i chunk _ora_17443.trc | grep -i 'callheap' | grep -i chunk | head

Chunk aaa0378 sz= 1072 freeable "callheap " ds=316e600

Chunk aaa07a8 sz= 1072 freeable "callheap " ds=316e600

Chunk aaa0bd8 sz= 1072 freeable "callheap " ds=316e600

Chunk aaa1008 sz= 1072 freeable "callheap " ds=316e600

Chunk aaa1438 sz= 1072 freeable "callheap " ds=316e600

Chunk aaa1868 sz= 1072 freeable "callheap " ds=316e600

Chunk aaa1c98 sz= 1072 freeable "callheap " ds=316e600

Chunk aaa20c8 sz= 1072 freeable "callheap " ds=316e600

Chunk aaa24f8 sz= 1072 freeable "callheap " ds=316e600

Chunk aaa2928 sz= 4164 freeable "callheap " ds=316e600

$ grep -i chunk _ora_17443.trc | grep -i 'callheap' | awk 'BEGIN{sum=0}{sum=sum+$4}END{printf "%10.2f", sum}'

2765503204.00

$ grep -i chunk _ora_17443.trc | grep -i 'callheap' | grep -i chunk | awk 'BEGIN{sum=0}{sum=sum+$4}END{print sum/1024/1024/1024, ":",sum}'

2.57558 : 2.7655e+09

$ grep -i chunk _ora_17443.trc | grep -i 'callheap' | grep -i chunk | awk '{sum[$5]=sum[$5]+$4}END{ for (i in sum){print i,":",sum[i]}}'

recreate : 2144

freeable : 2.7655e+09

Trace文件400MB，一行一行分析是不可能的，从上面的输出结果来看，callheap堆占用空间已经达2.6GB了，按照上次的分析，PGA的内存可分为：free, recreate, freeable和perm, 最理想的内存分配方式为直接占用状态为free的内存，从上面的分析，我们可以看出，没有free的内存了。

继续分析这个trace文件：

$ egrep 'HEAP|Total' _ora_17443.trc

…..省略不相关信息

HEAP DUMP heap name="top call heap" desc=316ef78

Total heap size =2766292232

Total free space = 788796

FIVE LARGEST SUB HEAPS for heap name="top call heap" desc=316ef78

SUBHEAP 1: desc=316e600

HEAP DUMP heap name="callheap" desc=316e600 --从这里可以判断出callheap是top call heap的一个子堆。

Total heap size =2734337096 --这个子堆的大小跟上面shell计算出来的大小有点点出入，因为这里只计算了SUBHEAP 1的大小。

Total free space = 58760 -- 貌似这里有空闲的内存，上面报错要求分配的是12548 bytes,但打开文件去看的话，就会发现里面有很多free字节为20的chunk:

Chunk fde6b938 sz= 20 free " "

Chunk fde6d60c sz= 20 free " "

Chunk fde6e29c sz= 20 free " "

Bucket 1 size=268

Bucket 2 size=1036

Total free space = 58760

这个显然不能满足一次分配12548bytes.这个应理解为碎片过多，就是总数加起来满足，但具体到某个CHUNK时，不能满足请求.

FIVE LARGEST SUB HEAPS for heap name="callheap" desc=316e600

SUBHEAP 1: desc=fe3c7a2c -- Typecheck heap 为callheap的第一个大子堆，但free space才816,不能满足请求

HEAP DUMP heap name="Typecheck heap" desc=fe3c7a2c

Total heap size = 259096

Total free space = 816

FIVE LARGEST SUB HEAPS for heap name="Typecheck heap" desc=fe3c7a2c

SUBHEAP 2: desc=fe22266c fe3c7a2c -- callheap的第二个大子堆，但free space才20, 不能满足请求

HEAP DUMP heap name="Typecheck heap" desc=fe22266c

Total heap size = 259048

Total free space = 20

FIVE LARGEST SUB HEAPS for heap name="Typecheck heap" desc=fe22266c

SUBHEAP 3: desc=a28c15c -- callheap的第三个大子堆，但free space才20, 不能满足请求

HEAP DUMP heap name="Typecheck heap" desc=a28c15c

Total heap size = 259196

Total free space = 20

FIVE LARGEST SUB HEAPS for heap name="Typecheck heap" desc=a28c15c

SUBHEAP 4: desc=97cc15c -- callheap的第四个大子堆，但free space才20, 不能满足请求

HEAP DUMP heap name="Typecheck heap" desc=97cc15c

Total heap size = 259196

Total free space = 20

FIVE LARGEST SUB HEAPS for heap name="Typecheck heap" desc=97cc15c

SUBHEAP 5: desc=926c15c -- callheap的第五个大子堆，但free space才20, 不能满足请求

HEAP DUMP heap name="Typecheck heap" desc=926c15c

Total heap size = 259196

Total free space = 20

FIVE LARGEST SUB HEAPS for heap name="Typecheck heap" desc=926c15c --这里没有列出最大Typecheck heap的情况

SUBHEAP 2: desc=316e598 -- top call heap的第二个大子堆 cal heap

HEAP DUMP heap name="callheap" desc=316e598

Total heap size = 1036

Total free space = 496

FIVE LARGEST SUB HEAPS for heap name="callheap" desc=316e598

HEAP DUMP heap name="top uga heap" desc=316f094

Total heap size = 65524

Total free space = 48

FIVE LARGEST SUB HEAPS for heap name="top uga heap" desc=316f094

SUBHEAP 1: desc=3226438

HEAP DUMP heap name="session heap" desc=3226438

Total heap size = 65440

Total free space = 12112

FIVE LARGEST SUB HEAPS for heap name="session heap" desc=3226438

SUBHEAP 1: desc=fe96f650

HEAP DUMP heap name="PLS non-lib hp" desc=fe96f650

Total heap size = 2060

Total free space = 372

FIVE LARGEST SUB HEAPS for heap name="PLS non-lib hp" desc=fe96f650

SUBHEAP 2: desc=fe96b644

HEAP DUMP heap name="koh-kghu sessi" desc=fe96b644

Total heap size = 1036

Total free space = 0

FIVE LARGEST SUB HEAPS for heap name="koh-kghu sessi" desc=fe96b644

SUBHEAP 3: desc=fe96c024

HEAP DUMP heap name="koh-kghu sessi" desc=fe96c024

Total heap size = 1036

Total free space = 0

FIVE LARGEST SUB HEAPS for heap name="koh-kghu sessi" desc=fe96c024

SUBHEAP 4: desc=fe96ca60

HEAP DUMP heap name="koh-kghu sessi" desc=fe96ca60

Total heap size = 1036

Total free space = 0

FIVE LARGEST SUB HEAPS for heap name="koh-kghu sessi" desc=fe96ca60

SUBHEAP 5: desc=fe96e13c

HEAP DUMP heap name="koh-kghu sessi" desc=fe96e13c

Total heap size = 1036

Total free space = 0

FIVE LARGEST SUB HEAPS for heap name="koh-kghu sessi" desc=fe96e13c

从上面大概可以看出堆的关系：top call heap里包含多个callheap,当然top call heap也包括其它的类型的堆，只是上面只是列出最大的两个callheap, 而一个callheap包含多个其它的子堆，如Typecheck heap/ top uga heap,而这些子堆里又可能包含其它的子堆。初略的图形关系：

|->callheap-> |->Typecheck heap->更细的子堆

| |->其它子堆

Top call heap ->| ->callheap-> top uga heap->更细长的子堆

|->其它子堆

从上面的析可以看出，没有一个子堆里的一个CHUNK状态为free的, 大小超过12548 bytes,这样的话，系统不得不抛出ORA-4030错误。从内存为配优先级来看，freeàfreeableàrecreated , 至于为什么不会从freeable chunk和recreated chunk里分配？我个人判断，这个可能跟callheap的功能有关系,比如callheap根本就没有这些状态的chunk. 这里没有仔细去分析每一个堆里面freeable/recreated里的大小，也有可能freeable/created里的单个chunk的大小也无法满足12548 bytes.可以初略这样分析: 从上面的输出可以看出SUBHEAP 1: desc=fe3c7a2c 为callheap里的一个最大子堆，那就分析它就应可以得出一些结论.做如下分析：

$ sed -n '/SUBHEAP 1: desc=fe3c7a2c/,/Total heap size = 259096/p' _ora_17443.trc | grep -i chunk | awk '{sum[$5]=sum[$5]+$4}END{ for (i in sum){print i,":",sum[i]}}'

perm : 258280

free : 816

从这里可以看出，这个堆亚根就没有recreated/freeable的chunk.

还有一个可能就是OS上内存完全消耗完了，再也没有内存可以分配给这个session了。

关于这个错误，从Oracle那里得到的答复是，可能操作系统上的参数设置有问题：

ulimit -a

time(seconds) unlimited

file(blocks) unlimited

data(kbytes) unlimited

stack(kbytes) 8192

coredump(blocks) unlimited

nofiles(descriptors) 2048

vmemory(kbytes) unlimited

要求把stack(kbytes)设置成unlimited, 但由于种种原因，未能如愿更改这个参数，所以到目前为止也不能验证问题出在这里。这个得以后跟进再下结论，正所谓:欲知后事如何，且听下回分解。

感叹一下：整个事故追踪了近四个月，总体来说，有些Oracle的工程师服务还是比较糟糕的，处理这个案例，打了N次电话到服务中心，一开始是SQL相关工程师，然而提升到内存分析部门，又后来转到ARE(Advanced Resolution Engineer),这些部门里转来转去，相应的部门接管与否也不能在SR里做相应的更新。有时叫他们更新SR，也没一个反馈，即使电话催过去，也杳无音讯。这是自开过SR以来，最糟糕的服务! 以后碰到这事，应马上要求更换工程师，或者提升紧急程度。还好这次不是生产库。