11.2.0.4 ADGリポジトリでORA-01555/cursorに遭遇:pin S wait on X問題分析


11204バージョンのADGリポジトリ(ビジネスソフトウェアはORACLE EBS)環境では、ユーザーはビューをクエリーするときにORA-01555を直接エラーとして報告し、文は実行を開始しなかった.DGデータベースにログインしてALERTログを表示すると、数秒の文エラーORA-01555の文が大量に実行され、hanganalyze分析を行うと、ビジネスセッションが他のセッションをブロックしていることがわかり、他のセッションがcursor:pin S wait on X、library cache lockを待っていることがわかります.このセッションで実行されるSQLがクエリである場合、なぜ他のセッションがブロックされているのかが調べられません.MOSから見ると、Bug 10018789-Spin in kglock/DB hang with high library cache lock waits on ADG(ドキュメントID 10018789.8)のようなADGのバグによる可能性もあるが、この問題は11203バージョンで修復され、現在使用されているのは11204バージョンである.MOSにはBug 10018789を修復した文書タイトルもありますが、ここではこれ以上検証することができず、この問題だけを処理し、後で観察しました.
プロセス関連情報:1.データベースのステータスとログ
STATUS       INSTANCE_NAME    START_TIME
------------ ---------------- --------------------
OPEN         PROD             2018/06/28 09:37:45
OPEN_MODE            NAME      DB_UNIQUE_NA DATABASE_ROLE          DBID
-------------------- --------- ------------ ---------------- ----------
LANG                       CURRT_TIME
-------------------------- --------------------
READ ONLY WITH APPLY PROD      PRODSTD1     PHYSICAL STANDBY  342495180
AMERICAN_AMERICA.AL32UTF8  2018/07/02 14:55:53

$ tail -n 100 alert_PROD.log 
ORA-01555 caused by SQL statement below (SQL ID: 58161b809rkhq, Query Duration=3 sec, SCN: 0x000d.d2928afb):
select count(*) from AALINES_ALL where LAST_UPDATE_DATE > to_date('2018-07
…………
Mon Jul 02 14:42:15 2018
ORA-01555 caused by SQL statement below (SQL ID: 6a4dr5y4kbsmj, Query Duration=7 sec, SCN: 0x000d.d2928afb):
select count(*), from AAALL where DATE > to_date('2018-07-02 10:01

2.hanganalyzeで問題を分析してblockerを見つける
SQL> oradebug setmypid
Statement processed.
SQL> oradebug unlimit
Statement processed.
SQL> oradebug hanganalyze 3
Hang Analysis in /u02/prod/db^/trace/PROD_ora_11469346.trc

  hanganalyze TRACE    :
Chains most likely to have caused the hang:
 [a] Chain 1 Signature: <='cursor: pin S wait on X'
     Chain 1 Signature Hash: 0x3a7b30c
 [b] Chain 2 Signature: <='library cache lock'
     Chain 2 Signature Hash: 0x24734cf
 [c] Chain 3 Signature: <='cursor: pin S wait on X'
     Chain 3 Signature Hash: 0x3a7b30c
Chain 1:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                instance: 1 (prodstd1.prod)
                   os id: 13959918
              process id: 60,
              session id: 5
        session serial #: 91
    }
    is waiting for 'cursor: pin S wait on X' with wait info:
    {
                      p1: 'idn'=0xb9295c99
                      p2: 'value'=0x8da00000000
                      p3: 'where'=0x500000000
            time in wait: 6 min 13 sec
      heur. time in wait: 17 min 9 sec
           timeout after: never
                 wait id: 7
                blocking: 0 sessions  
                blocking: 0 sessions
             current sql: select count(*) from …………ITEMTBL where DATE > to_date('2018-01-1
             short stack: ksedsts………… Oracle session identified by:
    {
                instance: 1 (prodstd1.prod)
                   os id: 2949500 <<<<<< 
             short stack: ksedsts()**-opiosq0()+2064<='cursor: pin S wait on X'
Chain 1 Signature Hash: 0x3a7b30c

TRACE       :
State of LOCAL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[1]/1/2/3/700010751bf98a8/13369432/SINGLE_NODE/
[4]/1/5/91/70001074dbafa18/13959918/NLEAF/[2265] --NLEAF      ,  adjlist       [nodenum] ;
[379]/1/380/1/700010771c8c9c0/10747992/SINGLE_NODE/
[756]/1/757/1/700010759e02818/2753006/SINGLE_NODE/
[1134]/1/1135/1/700010755e6e138/9437520/SINGLE_NODE/
[1509]/1/1510/3/700010759fcfc38/12321708/SINGLE_NODE/
[1511]/1/1512/1/700010771f3ef80/8651010/SINGLE_NODE/
[1888]/1/1889/1/70001075a0b4dd8/12584132/SINGLE_NODE/
[2263]/1/2264/1/70001074e117678/12714402/SINGLE_NODE/
[2265]/1/2266/3615/70001075215e428/2949500/LEAF_NW/  ---LEAF_NW      ,SID2266
[2641]/1/2642/1/70001075a2821f8/16253402/SINGLE_NODE/
[2643]/1/2644/3177/7000107721f1540/8323676/SINGLE_NODE_NW/
[3017]/1/3018/1/7000107722d97c0/19595340/SINGLE_NODE/
[3394]/1/3395/1/70001075a44f618/11207384/SINGLE_NODE/
[3771]/1/3772/1/7000107524f8c68/15139302/SINGLE_NODE/
[4148]/1/4149/1/70001074e597058/11010422/SINGLE_NODE/
[4524]/1/4525/1/7000107526c6088/16974384/NLEAF/[2265] -------
[4525]/1/4526/1/700010756688358/16646406/SINGLE_NODE/
[4902]/1/4903/1/7000107727591a0/16318956/SINGLE_NODE/
[5279]/1/5280/1/70001075a8ceff8/12387402/SINGLE_NODE/
[5281]/1/5282/547/70001077283e340/3015824/NLEAF/[2265] ---------
[5656]/1/5657/1/700010752978648/15401432/SINGLE_NODE/
[6034]/1/6035/1/700010772a0b760/15270516/SINGLE_NODE/
[6411]/1/6412/1/70001075ab815b8/19071030/SINGLE_NODE/
[6413]/1/6414/411/700010772af0900/11600240/NLEAF/[2265]  ---------
[6787]/1/6788/9/700010772bd8b80/19398714/SINGLE_NODE/
[6789]/1/6790/933/700010756beced8/18219140/NLEAF/[2265] ----------
[7164]/1/7165/1/70001075ad4e9d8/14614642/SINGLE_NODE/