Showing posts with label PGA Heap Dump. Show all posts
Showing posts with label PGA Heap Dump. Show all posts

Tuesday, June 15, 2010

PGAサイズの非正常的な増加

PGAサイズが多すぎるとシステムに多い問題を起こします。非正常的なPGAサイズの問題を分析する最高の方法はPGAヒープダンプを落としてそれを精密分析することです。しかし、PGAのサイズ増加が速すぎる場合は手動的にダンプコマンドを実行するのはむずかしいはずです。



幸い、オラクルが提供する診断イベントを活用すればPGAヒープダンプを自動的かすることができます。


1. まず、10261診断イベントを通じてPGAヒープダンプサイズを制限します。たとえば、下記のコマンドでPGAヒープサイズを100000KBに制限できます。


alter system set events '10261 trace name context forever, level 100000';


2. 10261イベントが存在する場合、PGAのサイズが設定したサイズを超えるプロセスはORA-600 [723]エラーとともに失敗します。

-- make big pga
declare
type varchar2_array is table of varchar2(32767) index by pls_integer;
vc varchar2_array;
v varchar2(32767);
begin
for idx in 1 .. 10000 loop
v := rpad('x',32767,'x');
vc(idx) := v;
end loop;
end;
/

ERROR at line 1:
ORA-00600: internal error code, arguments: [723], [41000], [pga heap], [], [],
[], [], []


3. この時、600診断イベントをPGAヒープダンプを実行するように設定すれば、10261→600→ヒープダンプの手順で自動的にPGAヒープダンプが実行されます。

alter system set events '600 trace name heapdump level 0x20000001';


4. 下記は自動的に生成されたPGAヒープダンプの一部です。特に、ダンプレベル0x20000001のおかげで下位Subheapを含んだダンプが記録されます。

DDE: Problem Key 'ORA 600 [723]' was flood controlled (0x2) (incident: 44800)
ORA-00600: internal error code, arguments: [723], [41000], [pga heap], [], [], [], [], []
****** ERROR: PGA size limit exceeded: 102450812 > 102400000 *****
******************************************************
HEAP DUMP heap name="pga heap" desc=11AFB098
extent sz=0x206c alt=92 het=32767 rec=0 flg=2 opc=1
parent=00000000 owner=00000000 nex=00000000 xsz=0xfff8 heap=00000000
fl2=0x60, nex=00000000
EXTENT 0 addr=39150008
Chunk 39150010 sz= 24528 free " "
Chunk 39155fe0 sz= 40992 freeable "koh-kghu call " ds=0D4D9A60
EXTENT 1 addr=39140008
Chunk 39140010 sz= 24528 free " "
Chunk 39145fe0 sz= 40992 freeable "koh-kghu call " ds=0D4D9A60
...


5. 最後の段階はヒープダンプを分析してどんなオブジェクトがヒープを使用しているのかを見破ることです。例えば、私はティパックという個人的なライブラリーを使用します。

select * from table(tpack.heap_file_report('C:\oracle\diag\rdbms\ukja1106\ukja1106\trace\ukja1106_ora_3640.trc'));

TYPE HEAP_NAME ITEM ITEM_COUNT ITEM_SIZE HEAP_SIZE RATIO
-------- ---------------- ---------------- ---------- ---------- ---------- ----------
HEAP pga heap 0 97.14 97.14 100
HEAP top call heap 0 .18 .18 100
HEAP top uga heap 0 .31 .31 100
CHUNK pga heap free 1554 36.2 97.1 37.3
CHUNK pga heap recreate 9 0 97.1 0
CHUNK pga heap perm 14 0 97.1 0
CHUNK pga heap freeable 1597 60.7 97.1 62.5
CHUNK top uga heap recreate 1 0 .3 19.9
CHUNK top uga heap free 5 0 .3 0
CHUNK top uga heap freeable 4 .2 .3 79.9
CHUNK top call heap free 3 .1 .1 65.5
CHUNK top call heap recreate 2 0 .1 1
CHUNK top call heap freeable 1 0 .1 33.3
CHUNK top call heap perm 1 0 .1 0
OBJECT pga heap kews sqlstat st 1 0 97.1 0
OBJECT pga heap pesom.c:Proces 3 0 97.1 0
...


6. オラクルの診断イベントのほかに、V$SESSTATビューをモニターリングしながらメモリーサイズがあるサイズを超える時、PGAヒープダンプを行なう方法もあります。例えば、前述のティパックライブラリーを次のように利用できます。

col report_id new_value report_id

select tpack_server.create_report('Heap Dump') as report_id from dual;

exec tpack_server.add_parameter('&report_id', 'dump_level', '0x20000001');
exec tpack_server.add_parameter('&report_id', 'get_whole_contents', 0);

exec tpack_server.add_condition('&report_id', 'STAT', 'session pga memory', '>100000000', 'SUM');

exec tpack_server.register_report('&report_id');

-- start server
exec tpack_server.start_server;

PGAヒープサイズが100000000Bに達すると、ティパックはあらかじめ定義されているプロシージャを実行してヒープダンプを落とします。

Fri Jun 11 06:19:10 GMT+00:00 2010 : Session 142 got! sum=659645392, name = session pga memory
...
Fri Jun 11 06:27:50 GMT+00:00 2010 : executing report 1:142:1973827792 for session 142
Fri Jun 11 06:27:55 GMT+00:00 2010 : executing report = begin tpack.heap_dump( dump_level=>'0x20000001', get_whole_contents=>0, session_id => 142); end;
...

10261と600診断イベントは仮の方便にすぎないでしょう。最も重要なのはヒープダンプを注意深く分析してPGAサイズの非正常的な増加を防ぐことです。

Monday, July 27, 2009

ORA-4030と遊ぶこと

ORA-4030エラーは昔からよく知られているもので、今頃なら初級DBAとしてもよほど深い知識を持っていなければならないはずです。でも、現実は私の期待とは違います。これが私がこの記事を書いている理由です。ORA-4030エラーをより楽しく扱えるように助けてくれるのがこの文の目的です。

まず、この定義をご覧ください。

04030
"out of process memory when trying to allocate %s bytes (%s,%s)"
// *Cause: Operating system process private memory has been exhausted
// *Action:

オラクルははっきりとORA-40404エラーがOSのプロセスメモリーの問題だと宣言しています。でも、これは五十パーセントだけの真実だと思います。

私が知る限り、ORA-4030の原因には普通三つぐらいがあります。

  1. OSのメモリー設定が低い。
  2. メモリーリークバグがいる。
  3. アプリがあまり多いオブジェクトを割り当てする。

Unixシステムでは、低いメモリー設定がORA-4030エラーを起こす場合があります。これに対する手軽な対応は設定値を高めることです。Unlimited値がよく使われます。

prompt> ulimit -a

core file size (blocks, -c) 0
data seg size (kbytes, -d) unlimited
file size (blocks, -f) unlimited
max locked memory       (kbytes, -l) unlimited
max memory size (kbytes, -m) unlimited
open files (-n) 1024
pipe size (512 bytes, -p) 8
stack size (kbytes, -s) unlimited
cpu time (seconds, -t) unlimited
max user processes (-u) 7168
virtual memory (kbytes, -v) unlimited


Windows32システムではプロセスメモリーの最高値は1.5Gぐらいです。フィジカルRAMサイズとは関係なく、プロセスメモリーのサイズはこのサイズ以上の値を取ることができません。こんな理由で、Windows64システムをお勧めする場合がたくさんあります。

大きいサイズのメモリーを使えるように設定したにもかかわらずORA-4030エラーが続けば、原因は異なる二つにあります。1)オラクルのバグ、2)アプリが多すぎるオブジェクトを生成しているかも知れません。

もっと詳細な分析のために、一番自然ながら易しい方法はPGAヒープダンプです。

PGAヒープダンプを実行する方法を説明する前に、ORA-4030エラーが正確にいつ発生するのかを簡単な例で紹介して行きます。
1. 次のように最小のPGA設定値を持っています。

alter system set "_pga_max_size" = 15000000;
alter system set pga_aggregate_target=50m;


2.PL/SQLブロックサイズをPGAの最大サイズより大きく設定しています。ORA-4030エラーは発生しましょうか。

-- case1. this does not cause 4030
set serveroutput on
spool temp.sql

begin
dbms_output.put_line('declare');
for idx in 1 .. 8000 loop
dbms_output.put_line(' v' || idx || ' varchar2(4000) := rpad(''x'',4000);');
end loop;
dbms_output.put_line('begin');
dbms_output.put_line('null;');
dbms_output.put_line('end;');
dbms_output.put_line('/');
end;
/

spool off
@temp

v91 varchar2(4000) := rpad('x',4000);
*
ERROR at line 92:
ORA-06550: line 1753, column 30:
PLS-00123: program too large (Diana nodes)

NAME VALUE
------------------------------ ----------------
session pga memory 2,022,996
session pga memory max 2,022,996

答えはNoです。オラクルはPL/SQLブロックサイズをPGAの最大サイズ以下に制限しています。

3.1.2GサイズのLOBオブジェクトを割り当てしています。ORA-4030エラーは発生しましょうか。

declare
v1 clob;
begin
for idx in 1 .. 1200000 loop
v1 := v1 || rpad('x', 1000, 'x');
end loop;
end;
/

NAME VALUE
---------------------------------------- ----------------
session pga memory 2,547,284
session pga memory max 5,627,476

PL/SQL procedure successfully completed.

今度も答えはNOです。LOBオブジェクトはPGAのサイズをを起こさないように具現しています。ソートに対しても同じ方式で動作します。2Gサイズのデータを15MのPGAでソートするのはもちろん性能が低いのは当然ですけど、ORA-4030エラーは絶対に発生しません。

4. 次のようなトリックはどうでしょうか。ORA-4030エラーは発生しましょうか。

create or replace procedure proc_rec(depth number)
is
v1 varchar2(1000) := rpad('x',1000);
v2 varchar2(1000) := rpad('x',1000);
v3 varchar2(1000) := rpad('x',1000);
v4 varchar2(1000) := rpad('x',1000);
v5 varchar2(1000) := rpad('x',1000);
v6 varchar2(1000) := rpad('x',1000);
v7 varchar2(1000) := rpad('x',1000);
v8 varchar2(1000) := rpad('x',1000);
v9 varchar2(1000) := rpad('x',1000);
v10 varchar2(1000) := rpad('x',1000);
begin
if depth > 0 then
proc_rec(depth - 1);
end if;
end;
/

UKJA@ukja102> exec proc_rec(100);

NAME VALUE
------------------------------ ----------------
session pga memory 2,940,500
session pga memory max 2,940,500

Elapsed: 00:00:00.00

UKJA@ukja102> exec proc_rec(10000);

NAME VALUE
------------------------------ ----------------
session pga memory 111,140,436
session pga memory max 124,575,316

UKJA@ukja102> exec proc_rec(20000);

NAME VALUE
------------------------------ ----------------
session pga memory 220,323,412
session pga memory max 248,307,284

メモリー使用量がPGAの最大サイズを軽く超えるのが分かります。複雑なアプリがこのようなパターンに会えばORA-4030エラーが発生する可能性があると予想できます。

5. PL/SQLコレクションもPGAの最大サイズを超えることができます。

create or replace procedure proc_array(len number)
is
type vtable is table of varchar2(1000);
vt vtable := vtable();
begin
for idx in 1 .. len loop
vt.extend;
vt(idx) := rpad('x',1000,'x');
end loop;
end;
/
UKJA@ukja102> exec proc_array(10000);

NAME VALUE
------------------------------ ----------------
session pga memory 221,896,276
session pga memory max 248,307,284

UKJA@ukja102> exec proc_array(10000);

NAME VALUE
------------------------------ ----------------
session pga memory 220,192,340
session pga memory max 364,961,364

UKJA@ukja102> exec proc_array(1200000);

ERROR at line 1:
ORA-04030: out of process memory when trying to allocate 16396 bytes (koh-kghu
call ,pl/sql vc2)

NAME VALUE
------------------------------ ----------------
session pga memory 219,668,052
session pga memory max 1,405,476,436

Windows32システムではプロセスメモリーの最大は1.5Gぐらいです。従って、1,405,476,436でORA-4030エラーガ発生していることです。

6. 一番重要なものはORA-4030エラーが発生した時どのように対応すればいいのかということです。私の一番好きな方法はPGAヒープダンプです。

-- This time
alter session set events
'4030 trace name heapdump level 0x20000001, lifetime 1';

レベル0x20000001のヒープダンプに関してはここに説明しています。

次のステップはトレースファイルをサマリーして、リポートを作成することです。

UKJA@ukja102> @heap_analyze ukja10_ora_5728.trc


HEAP_NAME HSZ
-------------------- ----------
pga heap 1,362.7
koh-kghu call 1,022.8
top uga heap .2
session heap .2
top call heap .1
PLS non-lib hp .0
qmtmInit .0
Alloc environm .0
KSFQ heap .0
Alloc server h .0
koh-kghu sessi .0
callheap .0

12 rows selected.

Elapsed: 00:00:00.09

HEAP_NAME CHUNK_TYPE CNT SZ HSZ HRATIO
-------------------- --------------- -------- ---------- ---------- ------
Alloc environm freeable 3 .0 .0 80.9
Alloc environm recreate 1 .0 .0 14.6
Alloc environm perm 2 .0 .0 4.5
Alloc server h free 6 .0 .0 94.3
Alloc server h perm 2 .0 .0 3.1
Alloc server h freeable 2 .0 .0 2.6
KSFQ heap perm 2 .0 .0 100.0
PLS non-lib hp freeable 12 .0 .0 75.1
PLS non-lib hp free 6 .0 .0 15.9
PLS non-lib hp perm 2 .0 .0 9.0
callheap free 6 .0 .0 77.1
callheap perm 2 .0 .0 22.9
koh-kghu call freeable 65,415 1,022.8 1,022.8 100.0
koh-kghu sessi freeable 4 .0 .0 100.0
pga heap freeable 65,453 1,024.1 1,362.7 75.2
pga heap free 43,616 338.4 1,362.7 24.8
pga heap recreate 6 .0 1,362.7 .0
pga heap perm 28 .2 1,362.7 .0
qmtmInit freeable 12 .0 .0 69.1
qmtmInit free 8 .0 .0 30.9
session heap perm 2 .1 .2 36.8
session heap freeable 333 .1 .2 33.6
session heap free 14 .0 .2 23.0
session heap recreate 8 .0 .2 6.6
top call heap free 2 .1 .1 93.5
top call heap perm 2 .0 .1 .1
top call heap freeable 1 .0 .1 3.1
top call heap recreate 2 .0 .1 3.3
top uga heap recreate 1 .1 .2 33.3
top uga heap free 6 .1 .2 33.4
top uga heap freeable 1 .1 .2 33.3

31 rows selected.

Elapsed: 00:00:00.15

HEAP_NAME OBJ_TYPE CNT SZ HSZ HRATIO
-------------------- -------------------- -------- ---------- ---------- ------
Alloc environm 1 .0 .0 17.2
Alloc environm Alloc server h 3 .0 .0 78.4
Alloc environm perm 2 .0 .0 4.5
Alloc server h 8 .0 .0 96.9
Alloc server h perm 2 .0 .0 3.1
KSFQ heap perm 2 .0 .0 100.0
PLS non-lib hp PL/SQL STACK 2 .0 .0 69.3
PLS non-lib hp PLSQL Stack des 2 .0 .0 .2
PLS non-lib hp perm 2 .0 .0 9.0
PLS non-lib hp pl_lut_alloc 1 .0 .0 .4
PLS non-lib hp peihstdep 5 .0 .0 .7
PLS non-lib hp PEIDEF 1 .0 .0 4.2
PLS non-lib hp 6 .0 .0 15.9
PLS non-lib hp pl_iot_alloc 1 .0 .0 .4
callheap 6 .0 .0 77.1
callheap perm 2 .0 .0 22.9
koh-kghu call pl/sql vc2 65,414 1,022.8 1,022.8 100.0 <-- This is it!
koh-kghu call pmucalm coll 1 .0 1,022.8 .0
koh-kghu sessi pl/sql vc2 1 .0 .0 39.9
koh-kghu sessi pliost struct 3 .0 .0 60.1
pga heap KJZT context 1 .0 1,362.7 .0
pga heap external name 1 .0 1,362.7 .0
pga heap KFIO PGA struct 1 .0 1,362.7 .0
pga heap KSFQ heap descr 1 .0 1,362.7 .0
pga heap PLS cca hp desc 1 .0 1,362.7 .0
pga heap KFK PGA 1 .0 1,362.7 .0
pga heap kews sqlstat st 1 .0 1,362.7 .0
pga heap koh-kghu call h 2 .0 1,362.7 .0
pga heap kpuinit env han 1 .0 1,362.7 .0
pga heap joxp heap 2 .0 1,362.7 .0
pga heap kjztprq struct 1 .0 1,362.7 .0
pga heap kopolal dvoid 5 .0 1,362.7 .0
pga heap KSFQ heap 1 .0 1,362.7 .0
pga heap Alloc environm 2 .0 1,362.7 .0
pga heap ldm context 13 .0 1,362.7 .0
pga heap qmtmInit 4 .0 1,362.7 .0
pga heap kgh stack 1 .0 1,362.7 .0
pga heap PLS non-lib hp 3 .0 1,362.7 .0
pga heap Fixed Uga 1 .0 1,362.7 .0
pga heap perm 28 .2 1,362.7 .0
pga heap kzsna:login nam 1 .0 1,362.7 .0
pga heap koh-kghu call 65,415 1,024.1 1,362.7 75.2
pga heap 43,616 338.4 1,362.7 24.8
qmtmInit qmushtCreate 3 .0 .0 44.9
qmtmInit 8 .0 .0 30.9
qmtmInit qmtmltAlloc 6 .0 .0 23.0
qmtmInit qmtmltCreate 3 .0 .0 1.2
session heap perm 2 .1 .2 36.8
session heap 14 .0 .2 23.0
session heap koklug hxctx in 1 .0 .2 .0
session heap koklug hlctx in 1 .0 .2 .0
session heap koddcal dvoid 1 .0 .2 .0
session heap system trigger 1 .0 .2 .0
session heap kxsFrame4kPage 5 .0 .2 12.8
session heap koh-kghu sessio 7 .0 .2 4.9
session heap koh-kghu sessi 6 .0 .2 4.6
session heap kxsc: kkspsc0 12 .0 .2 3.6
session heap kgsc ht segs 266 .0 .2 3.2
session heap PLS non-lib hp 2 .0 .2 2.6
session heap kzctxhugi1 1 .0 .2 2.6
session heap kpuinit env han 1 .0 .2 1.0
session heap kgiob 6 .0 .2 .7
session heap kokl lob id has 1 .0 .2 .6
session heap kxs-heap-p 1 .0 .2 .6
session heap kodpai image 1 .0 .2 .6
session heap kxs-krole 7 .0 .2 .4
session heap session languag 1 .0 .2 .3
session heap Session NCHAR l 1 .0 .2 .3
session heap PLS cca hp desc 2 .0 .2 .2
session heap kokl transactio 1 .0 .2 .2
session heap kokahin kgglk 1 .0 .2 .1
session heap kqlpWrntoStr:st 1 .0 .2 .1
session heap kwqidwh memory 2 .0 .2 .1
session heap kwqaalag 2 .0 .2 .1
session heap kgiobdtb 1 .0 .2 .1
session heap kwqb context me 2 .0 .2 .1
session heap kwqica hash tab 2 .0 .2 .1
session heap kwqmahal 2 .0 .2 .1
session heap kodmcon kodmc 1 .0 .2 .0
session heap kzsrcrdi 1 .0 .2 .0
session heap ksulu : ksulueo 1 .0 .2 .0
top call heap perm 2 .0 .1 .1
top call heap callheap 3 .0 .1 6.4
top call heap 2 .1 .1 93.5
top uga heap session heap 2 .1 .2 66.6
top uga heap 6 .1 .2 33.4

86 rows selected.

Elapsed: 00:00:00.15

HEAP_NAME SUBHEAP CNT SZ HSZ HRATIO
-------------------- -------------------- -------- ---------- ---------- ------
Alloc environm ds=04F665B8 2 .0 .0 63.7
Alloc environm 4 .0 .0 36.3
Alloc server h 10 .0 .0 100.0
KSFQ heap 2 .0 .0 100.0
PLS non-lib hp 20 .0 .0 100.0
callheap 8 .0 .0 100.0
koh-kghu call 65,415 1,022.8 1,022.8 100.0
koh-kghu sessi 4 .0 .0 100.0
pga heap ds=05003858 65,414 1,024.1 1,362.7 75.2
pga heap 43,683 338.6 1,362.7 24.8
pga heap ds=04F67B34 1 .0 1,362.7 .0
pga heap ds=04F8D9CC 2 .0 1,362.7 .0
pga heap ds=04FE3470 3 .0 1,362.7 .0
qmtmInit 20 .0 .0 100.0
session heap 356 .2 .2 98.7
session heap ds=07F7EAAC 1 .0 .2 1.3
top call heap ds=083B8E20 1 .0 .1 3.1
top call heap 6 .1 .1 96.9
top uga heap 7 .1 .2 66.7
top uga heap ds=05007600 1 .1 .2 33.3

20 rows selected.

Elapsed: 00:00:00.12


(heap_analyze.sqlはここ)
koh-kghu call pl/sql vc2という項目が見えますか。

KOHはKernel Object Heapという意味で、KGHUはKernel Generic Service for Heap Management(U=UGA or User object)という意味です。すなわち、アプリが多すぎるPL/SQL Varchar2オブジェクトを生成していることが分かります。
(Metalinkノート175982.1を見てください)

現実のORA-4030トラブルシューティングは上のような例よりずっと複雑です。でも、このぐらいの知識があればもう少しおそろしさなしにエラーに対応することができるんでしょう。

Tuesday, June 9, 2009

PGA Heap Dumpを利用したPGA メモリリークTroubleshooting

時々PGAメモリリークによりORA-4030エラーが発生する場合があります。本当の問題はORA-4030その自体ではない、メモリリークが発生する原因を探すのが易しくないという点です。

ここで、PGA Heap Dumpを利用し、メモリリークの原因を追跡する例を見ましょう。

下はFORALLを使用して効率的にデータを生成するProcedureです。


define m_string_length = 20

drop table t1 purge;
create table t1(v1 varchar2( &m_string_length ));

create or replace procedure proc1 (
i_rowcount in number default 1000000,
i_bulk_pause in number default 0,
i_forall_pause in number default 0,
i_free_pause in number default 0
)
as
type w_type is table of varchar2( &m_string_length );
w_list w_type := w_type();
w_free w_type := w_type();
begin
for i in 1..i_rowcount loop
w_list.extend;
w_list(i) := rpad('x', &m_string_length );
end loop;

dbms_lock.sleep(i_bulk_pause);

forall i in 1..w_list.count
insert into t1 values(w_list(i));

dbms_lock.sleep(i_forall_pause);
commit;
w_list := w_free;
dbms_session.free_unused_user_memory;

dbms_lock.sleep(i_free_pause);
end;
/


このProcedureを読み続けながら、メモリ使用率を観察しましょう。

UKJA@ukja102> exec proc1;

PL/SQL procedure successfully completed.

SYS@ukja10> select
2 name, value
3 from
4 v$sesstat ss,
5 v$statname sn
6 where
7 sn.name like '%ga memory%'
8 and ss.statistic# = sn.statistic#
9 and ss.sid = 149
10 ;

NAME VALUE
------------------------------ ----------------
session uga memory 498,942,840
session uga memory max 500,053,908
session pga memory 599,907,924
session pga memory max 675,602,004

UKJA@ukja102> exec proc1;

PL/SQL procedure successfully completed.

NAME VALUE
------------------------------ ----------------
session uga memory 695,429,288
session uga memory max 695,429,288
session pga memory 904,191,572
session pga memory max 904,257,108

UKJA@ukja102> exec proc1;

PL/SQL procedure successfully completed.

NAME VALUE
------------------------------ ----------------
session uga memory 840,565,088
session uga memory max 840,565,088
session pga memory 1,077,861,972
session pga memory max 1,077,861,972


深刻なメモリリークが発生することをわかります。OracleはProcedureの実行済みの後でもメモリを解除していません。

問題はOracleがどのようなObjectについてメモリを非正常的に占有しているのか判別しにくいと言うことです。ここで試せるのがPGA Heap Dumpです。

oradebug setospid 6760
oradebug dump heapdump 1


Heap Dump File自体は読みやすいですが、長さがとても長い場合が多くあります。それで、heap_analyze.sqlを利用してサマリ結果を見ましょう。

UKJA@ukja102> @heap_analyze heap_dump_1.trc
UKJA@ukja102> set echo off

ATYPE CSIZE TOTAL_HEAP_SIZE RATIO
------------------------ ---------- --------------- -------
free 99660580 598579832 16.650
freeable 498650144 598579832 83.306
perm 181928 598579832 .030
recreate 87180 598579832 .015

Elapsed: 00:00:01.03

CTYPE CSIZE TOTAL_HEAP_SIZE RATIO
------------------------------ ---------- --------------- -------
Alloc environm 4144 598579832 .001
Fixed Uga 20572 598579832 .003
KFIO PGA struct 72 598579832 .000
KFK PGA 260 598579832 .000
KJZT context 60 598579832 .000
KSFQ heap 3928 598579832 .001
KSFQ heap descr 92 598579832 .000
PLS cca hp desc 212 598579832 .000
PLS non-lib hp 18560 598579832 .003
callheap 2144 598579832 .000
external name 24 598579832 .000
joxp heap 2000 598579832 .000
kews sqlstat st 1292 598579832 .000
kgh stack 17012 598579832 .003
kjztprq struct 2068 598579832 .000
koh-kghu call h 1328 598579832 .000
kopolal dvoid 2524 598579832 .000
kpuinit env han 1584 598579832 .000
kzsna:login nam 24 598579832 .000
ldm context 12712 598579832 .002
perm 181928 598579832 .030
qmtmInit 13980 598579832 .002
session heap 498632732 598579832 83.303
99660580 598579832 16.650

24 rows selected.

Elapsed: 00:00:01.12

DS CSIZE TOTAL_SUBHEAP_SIZE RATIO
-------------------- ---------- ------------------ -------
083BD9CC 10320 498590012 .002
08563470 12436 498590012 .002
085A7600 498567256 498590012 99.995

Elapsed: 00:00:00.76

Subheap(08563470)が全体のメモリの80%以上を占めるのが見えます。次の作業はSubheap Dumpを実行することです。

oradebug dump heapdump_addr 1 0xa067600
UKJA@ukja102> @heap_analyze heap_subdump_1.trc
UKJA@ukja102> set echo off

ATYPE CSIZE TOTAL_HEAP_SIZE RATIO
------------------------ ---------- --------------- -------
free 9701516 498589224 1.946
freeable 488817960 498589224 98.040
perm 54896 498589224 .011
recreate 14852 498589224 .003

Elapsed: 00:00:00.70

CTYPE CSIZE TOTAL_HEAP_SIZE RATIO
------------------------------ ---------- --------------- -------
PLS cca hp desc 400 498589224 .000
PLS non-lib hp 488740608 498589224 98.025
Session NCHAR l 552 498589224 .000
kgict 40 498589224 .000
kgicttab 44 498589224 .000
kgicu 92 498589224 .000
kgiob 1928 498589224 .000
kgiobdtb 192 498589224 .000
kgsc ht segs 5720 498589224 .001
koddcal dvoid 24 498589224 .000
kodmcon kodmc 64 498589224 .000
kodpai image 1036 498589224 .000
koh-kghu sessi 15888 498589224 .003
koh-kghu sessio 14252 498589224 .003
kokahin kgglk 140 498589224 .000
kokl lob id has 1036 498589224 .000
kokl transactio 268 498589224 .000
koklug hlctx in 24 498589224 .000
koklug hxctx in 24 498589224 .000
kpuinit env han 1584 498589224 .000
kqlpWrntoStr:st 112 498589224 .000
ksulu : ksulueo 40 498589224 .000
kwqaalag 92 498589224 .000
kwqb context me 92 498589224 .000
kwqica hash tab 92 498589224 .000
kwqidwh memory 92 498589224 .000
kwqmahal 92 498589224 .000
kxs-heap-d 1036 498589224 .000
kxs-heap-p 4148 498589224 .001
kxs-krole 780 498589224 .000
kxsFrame4kPage 28840 498589224 .006
kxsc: kkspbd0 968 498589224 .000
kxsc: kkspsc0 7756 498589224 .002
kzctxhugi1 4108 498589224 .001
kzsrcrdi 60 498589224 .000
perm 54896 498589224 .011
session languag 552 498589224 .000
system trigger 36 498589224 .000
9701516 498589224 1.946

39 rows selected.

Elapsed: 00:00:00.81

DS CSIZE TOTAL_SUBHEAP_SIZE RATIO
-------------------- ---------- ------------------ -------
08B3608C 2076 488746828 .000
08B3EAAC 488738512 488746828 99.998
08B578F4 2080 488746828 .000
08B5A114 2080 488746828 .000
0FD400B0 2080 488746828 .000

Elapsed: 00:00:00.89

同じPatternで、Subheap(08B3EAAC)が大部分のメモリを占めるものが分かります。


oradebug dump heapdump_addr 1 0x0A08EAAC

UKJA@ukja102> @heap_analyze heap_subdump_2.trc
UKJA@ukja102> set echo off

ATYPE CSIZE TOTAL_HEAP_SIZE RATIO
------------------------ ---------- --------------- -------
free 483911940 488662624 99.028
freeable 4750540 488662624 .972
perm 144 488662624 .000

Elapsed: 00:00:05.03

CTYPE CSIZE TOTAL_HEAP_SIZE RATIO
------------------------------ ---------- --------------- -------
DPAGE 4750096 488662624 .972
peihstdep 260 488662624 .000
perm 144 488662624 .000
pl_iot_alloc 92 488662624 .000
pl_lut_alloc 92 488662624 .000
483911940 488662624 99.028

6 rows selected.

Elapsed: 00:00:05.40

no rows selected

Elapsed: 00:00:03.21

今、問題の原因が見えます。OracleはFORALLで使用されたメモリをfree状態に変えたにもかかわらず、そのメモリを完全に解除していないと言えます。これは間違いなくBugだと考えられます。

次のようにMetalinkで検索してみます。



検索の結果(Bug# 5866410)が上で見た現状と完璧に一致しています。

Bulk insert in PLSQL can consume a large amount of PGA memory which can lead to ORA-4030 errors.

A heapdump will show lot of free memory in the free lists which is not used but instead fresh allocations are made.


PGA Heap Dump分析がいくら有用か分かる良い例です。でも、実際には分析は見えるものより難しい場合が多くあります。理由は

  • Heap Dump Fileは長すぎる場合が多いです。適切なツールがなければ、分析はほとんど不可能です。上で紹介したheap_analyze.sqlがいい例です。
  • Heapは階層的な構造を持っているため、分析時に注意が必要です。
  • Object名を理解しにくい場合も多くあります。

このような限界にもかかわらず、特定状況ではPGA Heap Dump分析は大きい力を発揮します。そのメリトとデメリトを良く理解した後使用すれば立派な分析ツールとなるでしょう。