Thursday, March 11, 2010

Oracle 11.1.0.6のトリガーバグ分析　－　ティパックの活用

この頃トラブルシューティングパック（Troubleshooting Pack。以下ティパック）という名前のライブラリーを開発しています。オラクルが提供するトラブルシューティング機能（診断イベント、ダンプ、X$ビュー）を利用して普遍的ないくつかの性能問題について意味のあるレポートを提供する目的で企画されました。


次のアーティクルにOracle 11.1.0.6の面白いトリガー関係のバグが紹介されています。


このバグで現れる現象ががティパックを活用して問題を分析できる良い例に見えて簡単に紹介します。


まず上のアーティクルで説明している問題は次のようです。


UKJA@ukja1106> create table t1(c1 int);

Table created.

UKJA@ukja1106> create table t2(c1 int);

Table created.

次のように二つのトリガーを作ります。二つ目のトリガーをどんな意味もないトリガーだけれど開発規則によって追加されました。何もしないトリガーなので性能に与える影響はほとんどないはずです。

UKJA@ukja1106> create or replace trigger t1_trg1 after insert on t1 for each row
  2  begin
  3    insert into t2 values(:new.c1);
  4  end;
  5  /

Trigger created.

UKJA@ukja1106> 
UKJA@ukja1106> create or replace trigger t1_trg2 after insert on t2 for each row
  2  begin
  3    declare
  4    numrows number;
  5    begin
  6    numrows := 1;
  7    end;
  8  end;
  9  /

Trigger created.

どころが、Oracle 11.1.0.6で次のように繰り返しにテーブルT1に対してInsertを行うとだんだんその性能が遅れていきます。

UKJA@ukja1106> declare
  2    v_start_time  number := dbms_utility.get_time;
  3  begin
  4    for idx in 1 .. 50000 loop
  5    insert into t1 values(idx);
  6  
  7    if mod(idx, 1000) = 0 then
  8      dbms_output.put_line(idx || 'th exe = ' || (dbms_utility.get_time - v_start_time)/100);
  9      v_start_time := dbms_utility.get_time;
 10    end if;
 11    end loop;
 12  end;
 13  /
1000th exe = .14
2000th exe = .17
3000th exe = .16
4000th exe = .17
5000th exe = .15
6000th exe = .19
7000th exe = .16
8000th exe = .2
9000th exe = .19
10000th exe = .2
11000th exe = .21
12000th exe = .23
13000th exe = .22
14000th exe = .23
15000th exe = .25
16000th exe = .24
17000th exe = .23
18000th exe = .27
19000th exe = .28
20000th exe = .26
21000th exe = .27
22000th exe = .28
23000th exe = .3
24000th exe = .31
25000th exe = .3
26000th exe = .34
27000th exe = .31
28000th exe = .35
29000th exe = .36
30000th exe = .43
31000th exe = .52
32000th exe = .45
33000th exe = .49
34000th exe = .43
35000th exe = .68
36000th exe = .64
37000th exe = .89
38000th exe = .53
39000th exe = .44
40000th exe = .47
41000th exe = .48
42000th exe = .52
43000th exe = .56
44000th exe = .59
45000th exe = .64
46000th exe = .69
47000th exe = .7
48000th exe = .77
49000th exe = .78
50000th exe = .84

PL/SQL procedure successfully completed.

Oracle 10gR2やOracle 11.1.0.7ではこのような現象は発生しません。Oracle 11.1.0.6のバグに見えます。


上のアーティクルでは次のような二つの現象を報告しています。


  1. 実行回数が増えるほどCPU使用時間が増えていく（SQL*Trace）
  2. 実行回数が増えるほどPGA使用量が増えていく（V$SESSTAT）

上の現象から見るとたぶんわけのわからない理由のためメモリーを使いすぎて、その過程でCPU使用時間も増えるように見えます。


この問題をティパック（Troubleshooting Pack）を通じて分析してみます。


  • Session Snapshot機能を通じてどんな性能指標がおもに増加するか観察する。
  • PGA Heap Dump分析を通じてPGAのサイズが増加する原因を分析します。
  • Call Stack Traceの分析を通じてどんな係数をおもに呼び出しながらCPUを使用するか分析する。

下にその結果があります。


Session Snapshotで得た結果はアーティクルの結果と一致します。500,000件のInsertが終わったあとPGAのサイズが1.6Mから45Mまで増加したのがわかります。


01. statistics

NAME                                          DIFF         VALUE1         VALUE2
----------------------------------- -------------- -------------- --------------
session pga memory                      45,285,376      1,663,952     46,949,328
session pga memory max                  45,154,304      1,795,024     46,949,328
session uga memory                      45,104,696        891,300     45,995,996
session uga memory max                  44,973,768      1,022,228     45,995,996
...

PGAのサイズが増加した原因を分析するためにPGAレポートを生成します。

UKJA@ukja1106> select * from table(tpack.get_pga_report);

...
02. Size per Chunk Type

Heap Name            Chunk Type Count      Chunk Size Heap Size  Ratio(%)
-------------------- ---------- ---------- ---------- ---------- ----------
...
kxs-heap-p           perm                1          0       20.9          0
kxs-heap-p           freeable       250005       20.9       20.9       99.6
pesom.c:Proces       free                2          0          0       68.3
...


03. Size Per Object Type
Heap Name            Obj Type             Count      Chunk Si Heap Siz Ratio
-------------------- -------------------- ---------- -------- -------- -----
...
kxs-heap-p           kxt.c: PL/SQL p          150000     16.3     20.9  77.7
kxs-heap-p           kxt.c: Trigger           100000      4.5     20.9  21.8
kxs-heap-p           none                       3334        0     20.9    .3
kxs-heap-p           kxtcin:kxscplx                1        0     20.9     0
...


Kxs-heap-pヒープのfreeable Chunk（再活用可能なChunk）の数が250,005個に達して、20M程度のサイズを占めています。メモリーりーくが疑われます。KXSはKernel Execution Shared Cursorの略語です。Shared Cursorと関連したメモリー問題の可能性があります。PGA内のShared Cursorの領域はSESSION_CACHED_CURSORパラメータで制御されます。


Ksx-heap-pヒープのkxt.c: PL/SQL p、kxt.c: Triggerオブジェクトの数が250,000個です。この値はkxs-heap-pヒープのfreeable Chunkの数とほとんど一致しています。KXTはKernel Execution Triggerの略語です。


情報を総合してみると、トリガー実行関係のオブジェクトがShared Cursor領域で再活用されないまま繰り返しに追加され、メモリーとCPUの使用量が一緒に増加していると仮定できます。


Call Stack Trace分析を通じて実際にどんなコードがおもに呼び出されているのか確認してみます。


UKJA@ukja1106> select * from table(tpack.stacktrace_profile_report(&1,5,0.1));
old   1: select * from table(tpack.stacktrace_profile_report(&1,5,0.1))
new   1: select * from table(tpack.stacktrace_profile_report(134,5,0.1))


STACK_TRACE
--------------------------------------------------------------------------------
   HIT_CNT    HIT_PCT
---------- ----------
->00000000->7C80B710->_OracleThreadStart@4()+764->_opimai()+92->_opimai_real()+1
30->_sou2o()+45->_opidrv()+807->_opiodr()+1224->_opiino()+1067->_opitsk()+1278->
_ttcpip()+2733->_opiodr()+1224->_kpoal8()+2299->_opiexe()+14438->_kkxexe()+1046-
>_peicnt()+250->_plsql_run()+729->_pfrrun()+875->_pfrrun_no_tool()+56->_pfrinstr
_EXECC()+58->_pevm_EXECC()+295->_psdnal()+348->_psddr0()+487->_rpidrv()+1357->_r
piswu2()+560->_rpidru()+88->_rpidrus()+178->_opiodr()+1224->_opipls()+1312->_opi
exe()+5344->_insexe()+1027->_qerltcFetch()+896->_qerltcInsertValuesRop()+243->_q
erltcLoadStateMachine()+609->__PGOSF492__qerltcNoKdtBufferedInsRowCBK()+336->__V
Infreq__qesltcAfterRowProcessing()+238->_qesltcExecuteAfterRowTriggers()+1299->_
kxtexe()+483->_rpiswu2()+560->_kxtex1()+478->_kkxtexe()+901->_peiet_execute_trig
ger()+47->_peicnt()+250->_plsql_run()+729->_pfrrun()+875->_pfrrun_no_tool()+56->
_pfrinstr_EXECC()+58->_pevm_EXECC()+295->_psdnal()+348->_psddr0()+487->_rpidrv()
+1357->_rpiswu2()+560->_rpidru()+88->_rpidrus()+178->_opiodr()+1224->_opipls()+1
312->_opiexe()+1823->_kksfbc()+12485->_kxtInstantiateAllTriggers()+77->_kxtCreat
eTriggerInst()+250->_kxsPersistentHeapAllocFree()+42->_kghalf()+188->00000000->7
C80B710->_OracleOradebugThreadStart@4()+825->_ssthreadsrgruncallback()+432->_ksd
xcb()+1780->_ksdxfdmp()+850->_ksedst_tracecb()+53->_ksedst1()+91->_skdstdst()+11
4
         8         16

->00000000->7C80B710->_OracleThreadStart@4()+764->_opimai()+92->_opimai_real()+1
30->_sou2o()+45->_opidrv()+807->_opiodr()+1224->_opiino()+1067->_opitsk()+1278->
_ttcpip()+2733->_opiodr()+1224->_kpoal8()+2299->_opiexe()+14438->_kkxexe()+1046-
>_peicnt()+250->_plsql_run()+729->_pfrrun()+875->_pfrrun_no_tool()+56->_pfrinstr
_EXECC()+58->_pevm_EXECC()+295->_psdnal()+348->_psddr0()+487->_rpidrv()+1357->_r
piswu2()+560->_rpidru()+88->_rpidrus()+178->_opiodr()+1224->_opipls()+1312->_opi
exe()+1823->_kksfbc()+12485->_kxtInstantiateAllTriggers()+77->_kxtCreateTriggerI
nst()+250->_kxsPersistentHeapAllocFree()+42->_kghalf()+188->00000000->7C80B710->
_OracleOradebugThreadStart@4()+825->_ssthreadsrgruncallback()+432->_ksdxcb()+178
0->_ksdxfdmp()+850->_ksedst_tracecb()+53->_ksedst1()+91->_skdstdst()+114
         3          6

->00000000->7C80B710->_OracleThreadStart@4()+764->_opimai()+92->_opimai_real()+1
30->_sou2o()+45->_opidrv()+807->_opiodr()+1224->_opiino()+1067->_opitsk()+1278->
_ttcpip()+2733->_opiodr()+1224->_kpoal8()+2299->_opiexe()+14438->_kkxexe()+1046-
>_peicnt()+250->_plsql_run()+729->_pfrrun()+875->_pfrrun_no_tool()+56->_pfrinstr
_EXECC()+58->_pevm_EXECC()+295->_psdnal()+348->_psddr0()+487->_rpidrv()+1357->_r
piswu2()+560->_rpidru()+88->_rpidrus()+178->_opiodr()+1224->_opipls()+1312->_opi
exe()+5344->_insexe()+1027->_qerltcFetch()+896->_qerltcInsertValuesRop()+243->_q
erltcLoadStateMachine()+609->__PGOSF492__qerltcNoKdtBufferedInsRowCBK()+336->__V
Infreq__qesltcAfterRowProcessing()+238->_qesltcExecuteAfterRowTriggers()+1299->_
kxtexe()+483->_rpiswu2()+560->_kxtex1()+478->_kkxtexe()+901->_peiet_execute_trig
ger()+47->_peicnt()+250->_plsql_run()+729->_pfrrun()+875->_pfrrun_no_tool()+56->
_pfrinstr_EXECC()+58->_pevm_EXECC()+295->_psdnal()+348->_psddr0()+487->_rpidrv()
+1357->_rpiswu2()+560->_rpidru()+88->_rpidrus()+178->_opiodr()+1224->_opipls()+1
312->_opiexe()+1823->_kksfbc()+12485->_kxtInstantiateAllTriggers()+77->_kxtCreat
eTriggerInst()+304->_kxsPersistentHeapAllocFree()+42->_kghalf()+188->00000000->7
C80B710->_OracleOradebugThreadStart@4()+825->_ssthreadsrgruncallback()+432->_ksd
xcb()+1780->_ksdxfdmp()+850->_ksedst_tracecb()+53->_ksedst1()+91->_skdstdst()+11
4
         3          6

...


Call Stack Traceを見ると下の呼びさしパターンが一番普遍的に発生していることがわかります。

_kxtInstantiateAllTriggers
_kxtCreateTriggerInst
_kxsPersistentHeapAllocFree

PGAレポートと完璧に一致する係数呼び出しパターンです。トリガーオブジェクトを続けて生成し、その過程でメモリーを続けて割り当てされています。


確かに、メモリー関係のバグの可能性が高そうです。こんな情報があればメタリンクをもっと正確に検索できます。下にメタリンクの検索結果があります。




バグ番号6400175が見えるでしょう。ほとんど完璧に一致する現象を報告しています。


オラクルが提供するいくつかの基本的な性能データを通じてオラクルでの性能異常現象を体系的に分析できるということを見せてくれる良い例だと思われます。


PS) 上の例で紹介されたティパックの機能は次のようなデータを利用しています。このデータたちを直接検索し、分析できると誰でも同一な分析が可能です。


  • V$SESSTAT
  • PGA Heap Dump (oradebug dump heapdump 0x20000001)
  • Call Stack (oradebug dump callstack 1)
at 8:55 PM Posted by Dion_Cho

No comments:

Post a Comment

Subscribe to: Post Comments (Atom)