Tuesday, May 11, 2010

Library cache pin競合の面白いケース

最近、面白いlibrary cache pin(もしくはMutex)の競合の事例を経験しました。


(この例ではTPackという個人的なライブラリーを使用していますが、すべての情報はX$View,V$View,Trace Fileなどから取得できます。)


1.次のようにテーブルを作ります。


drop table t1 purge;
create table t1(c1 int);
insert into t1 values(1);
commit;

2.セッション#1で次のようなSQLコマンドを行います。1008エーらが発生するのに注意してください。

SID SERIAL# PID
---------- ---------- ----------
147 23608 11556

1 row selected.

Elapsed: 00:00:05.12

TPACK@ukja1021> declare
2 v_value number;
3 begin
4 execute immediate 'select 1 from t1 where c1 = :b1'
5 into v_value;
6
7 dbms_output.put_line('value = ' || v_value);
8
9 end;
10 /
declare
*
ERROR at line 1:
ORA-01008: not all variables bound
ORA-06512: at line 4

3.セッション#2が同じコマンドを実行します。でも、ブロックされて待機ようになります。

SID SERIAL# PID
---------- ---------- ----------
148 56408 11736

Elapsed: 00:00:00.00

TPACK@ukja1021> declare
2 v_value number;
3 begin
4 execute immediate 'select 1 from t1 where c1 = :b1'
5 into v_value;
6
7 dbms_output.put_line('value = ' || v_value);
8
9 end;
10 /

4.なぜセッション#2が待機するのでしょうか。詳細な待機情報を分析してみます。セッション#1(147)がCURSORタイプ(SQL)のオブジェクトに対してlibrary cache pinをExclusiveモードで獲得しているのが原因であることがわらります。

TPACK@ukja1021> select * from table(tpack.session_detail(&sid));
Enter value for sid: 148
old 1: select * from table(tpack.session_detail(&sid))
new 1: select * from table(tpack.session_detail(148))

NAME VALUE
------------------------------ --------------------
SID 148
Serial# 56408
SPID 11736
Program sqlplus.exe
Process 7940:1228
Module SQL*Plus
SQL ID
Child No
SQL Text
Status ACTIVE
Blocking Instance 1
Blocking Session 147
Event library cache pin
Seq# 29
P1(P1raw) 764496508(2D914A7C)
P2(P2raw) 764496508(2CDC1330)
P3(P3raw) 764496508(000000C8)
Seconds in wait 81
State WAITING
Wait Event library cache pin
Holder SID 147
Namespace CURSOR
Object select 1 from t1 whe
re c1 = :b1

Holding Mode 3(X)

24 rows selected.

5.より正確な情報のために待機しているセッション#1に対してコールスタックをプロファイリングしてみます。

TPACK@ukja1021> select * from table(tpack.callstack_prof_report(&sid));
Enter value for sid: 148
old 1: select * from table(tpack.callstack_prof_report(&sid))
new 1: select * from table(tpack.callstack_prof_report(148))

STACK_TRACE
--------------------------------------------------------------------------------
HIT_CNT HIT_PCT
---------- ----------
7C80B710
->_OracleThreadStart@4
->_opimai
->_opimai_real
->_sou2o
->_opidrv
->_opiodr
->_opiino
->_opitsk
->_ttcpip
->_opiodr
->_kpoal8
->_opiexe
->_kkxexe
->_peicnt
->_plsql_run
->_pfrrun
->_pfrrun_no_tool
->_pfrinstr_EXIM
->_pevm_EXIM
->_psdnal
->_psddr0
->_rpidrv
->_rpiswu2
->_rpidru
->_rpidrus
->_opiodr
->_opipls
->_opiosq0
->_kksParseCursor
->_kkspsc0
->_kksfbc
->_kksSearchChildList
->_kksCheckCursor
->_kkslce
->_kxsGetRuntimeLock
->_kglpin
->_kglpnal
->__PGOSF169__ksfwat
->_kslwait
->_kskthbwt
->_kslwaitns
->_ksliwat
->_skgpwwait
->7C80253D
->00000000
->7C80B710
->_OracleOradebugThreadStart@4
->_ssthreadsrgruncallback
->_ksdxcb
->_ksdxfdmp
->_ksedst_tracecb
10 100



関数名_pevm_EXIMに注意してください。これはExecute Immediateコマンドが実行しているのを意味します。複雑な状況でこのような待機が発生したらコールスタック情報が特に有効です。


これは疑いなくバグであるはずです。MOS(Metalink)で次のようなKeywordで検索してみます。


  • library cache pin
  • execute immediate
  • pevm_EXIM


いくつかの簡単な情報を適切に取得すれば問題の分析がより正確で便利にできるようになることが分かります。