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

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

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

１．次のようにテーブルを作ります。

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

２．セッション＃１で次のようなSQLコマンドを行います。１００８エーらが発生するのに注意してください。

       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

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

       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  /

４．なぜセッション＃２が待機するのでしょうか。詳細な待機情報を分析してみます。セッション＃１（１４７）が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.

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

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
  

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