11G数据库之library cache lock及library cache pin模拟结合hanganalyze定位

session 1:

SQL> select sid from v$mystat where rownum=1;

       SID
----------
        41

SQL> create or replace procedure pining
    is
    begin
      null;
    end;
    /
Procedure created
SQL>
SQL> create or replace procedure calling
    is
    begin
      pining;
      dbms_lock.sleep(200);
    end;
    /
SQL>
SQL> call calling();
..............................................

session 2:

SQL> select sid from v$mystat where rownum=1;

       SID
----------
        37
SQL> alter procedure pining compile;   
hang...........
 
session 3:

SQL> select sid from v$mystat where rownum=1;

       SID
----------
        38

SQL> drop procedure pining;  
HANG...........................................

session 4:

SQL> select sid, event,wait_class, seconds_in_wait from v$session_wait w where w.WAIT_CLASS <> 'Idle';

       SID EVENT                                                            WAIT_CLASS                                                       SECONDS_IN_WAIT
---------- ---------------------------------------------------------------- ---------------------------------------------------------------- ---------------
         1 SQL*Net message to client                                        Network                                                                        0
        37 library cache pin                                                Concurrency                                                                   44
        38 library cache lock                                               Concurrency                                                                   33

SQL>  
SQL>  oradebug setmypid
Statement processed.
SQL> oradebug hanganalyze 3;
Hang Analysis in /u01/app/oracle/diag/rdbms/dbdb/DBdb/trace/DBdb_ora_27483.trc
SQL> oradebug close_trace;
Statement processed.

--查看trace文件:
[oracle@wang ~]$ more /u01/app/oracle/diag/rdbms/dbdb/DBdb/trace/DBdb_ora_27483.trc
Trace file /u01/app/oracle/diag/rdbms/dbdb/DBdb/trace/DBdb_ora_27483.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/11.2.0/db_1
System name:    Linux
Node name:      wang
Release:        3.10.0-327.el7.x86_64
Version:        #1 SMP Thu Oct 29 17:29:29 EDT 2015
Machine:        x86_64
Instance name: DBdb
Redo thread mounted by this instance: 1
Oracle process number: 32
Unix process pid: 27483, image: oracle@wang (TNS V1-V3)


*** 2017-12-11 11:02:22.201
*** SESSION ID:(1.201) 2017-12-11 11:02:22.201
*** CLIENT ID:() 2017-12-11 11:02:22.201
*** SERVICE NAME:(SYS$USERS) 2017-12-11 11:02:22.201
*** MODULE NAME:(sqlplus@wang (TNS V1-V3)) 2017-12-11 11:02:22.201
*** ACTION NAME:() 2017-12-11 11:02:22.201
 
Processing Oradebug command 'setmypid'

*** 2017-12-11 11:02:22.201
Oradebug command 'setmypid' console output:

*** 2017-12-11 11:02:30.699
Processing Oradebug command 'hanganalyze 3'

*** 2017-12-11 11:02:30.701
===============================================================================
HANG ANALYSIS:
  instances (db_name.oracle_sid): dbdb.dbdb
  oradebug_node_dump_level: 3
  analysis initiated by oradebug
  os thread scheduling delay history: (sampling every 1.000000 secs)
    0.000000 secs at [ 11:02:29 ]
      NOTE: scheduling delay has not been sampled for 0.879666 secs    0.000000 secs from [ 11:02:25 - 11:02:30 ], 5 sec avg
    0.000000 secs from [ 11:01:31 - 11:02:30 ], 1 min avg
    0.000000 secs from [ 10:57:31 - 11:02:30 ], 5 min avg
  vktm time drift history
===============================================================================
 
Chains most likely to have caused the hang:
 
 
===============================================================================
No chains found.
===============================================================================
Extra information that will be dumped at higher levels:
 
State of ALL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):

*** 2017-12-11 11:02:30.770
===============================================================================
END OF HANG ANALYSIS
===============================================================================

*** 2017-12-11 11:02:30.770
===============================================================================
HANG ANALYSIS DUMPS:
  oradebug_node_dump_level: 3
===============================================================================
 
State of LOCAL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
 
 
No processes qualify for dumping.
 
===============================================================================
HANG ANALYSIS DUMPS: END
===============================================================================

*** 2017-12-11 11:02:30.771
Oradebug command 'hanganalyze 3' console output:
Hang Analysis in /u01/app/oracle/diag/rdbms/dbdb/DBdb/trace/DBdb_ora_27483.trc

*** 2017-12-11 11:03:41.097
Processing Oradebug command 'close_trace'
Oradebug command 'close_trace' console output:
Processing Oradebug command 'setmypid'
Oradebug command 'setmypid' console output:
Processing Oradebug command 'hanganalyze 3'
===============================================================================
HANG ANALYSIS:
  instances (db_name.oracle_sid): dbdb.dbdb
  oradebug_node_dump_level: 3
  analysis initiated by oradebug
  os thread scheduling delay history: (sampling every 1.000000 secs)
    0.000000 secs at [ 11:05:35 ]
      NOTE: scheduling delay has not been sampled for 0.908940 secs    0.000000 secs from [ 11:05:31 - 11:05:36 ], 5 sec avg
    0.000000 secs from [ 11:04:37 - 11:05:36 ], 1 min avg
    0.000001 secs from [ 11:00:37 - 11:05:36 ], 5 min avg
  vktm time drift history
===============================================================================
 
Chains most likely to have caused the hang:
 [a] Chain 1 Signature: 'PL/SQL lock timer'<='library cache pin'<='library cache lock'
     Chain 1 Signature Hash: 0x38f0a7dd
 
===============================================================================
Non-intersecting chains:
 
-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                instance: 1 (dbdb.dbdb)
                   os id: 27238
              process id: 31, oracle@wang (TNS V1-V3)
              session id: 38
        session serial #: 75
    }
    is waiting for 'library cache lock' with wait info:
    {
                      p1: 'handle address'=0x72046288
                      p2: 'lock address'=0x721d7690
                      p3: '100*mode+namespace'=0x1618500010003
            time in wait: 9.863328 sec
           timeout after: 14 min 50 sec
                 wait id: 26
                blocking: 0 sessions
             current sql:
             short stack: ksedsts()+465<-ksdxfstk()+32<-ksdxcb()+1927<-sspuser()+112<-__sighandler()<-semtimedop()+10<-skgpwwait()+160<-ksliwat()+2022<-kslwaitctx()+16
3<-ksfwaitctx()+14<-kglLockWait()+870<-kgllkal()+1166<-kglLock()+1308<-kglget()+343<-kkdllk0()+423<-kkdlGetCodeObject()+307<-kkpdrp()+246<-opiexe()+18161<-opiosq0()+39
32<-kpooprx()+274<-kpoal8()+842<-opiodr()+917<-ttcpip()+2183<-opitsk()+1710<-opiino()+969<-opiodr()+917<-opidrv()+570<-sou2o()+103<-opimai_real()+133<-ssthrdmain()+265
<-main()+201<-__libc_start_main()+245
            wait history:
              * time between current wait and wait #1: 0.001590 sec
              1.       event: 'SQL*Net message from client'
                 time waited: 3 min 25 sec
                     wait id: 25              p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
              * time between wait #1 and #2: 0.000005 sec
              2.       event: 'SQL*Net message to client'
                 time waited: 0.000002 sec
                     wait id: 24              p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
              * time between wait #2 and #3: 0.000085 sec
              3.       event: 'log file sync'
                 time waited: 0.011217 sec
                     wait id: 23              p1: 'buffer#'=0x4e2
                                              p2: 'sync scn'=0x53ae65
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (dbdb.dbdb)
                   os id: 26883
              process id: 34, oracle@wang (TNS V1-V3)
              session id: 37
        session serial #: 121
    }
    which is waiting for 'library cache pin' with wait info:
    {
                      p1: 'handle address'=0x72046288
                      p2: 'pin address'=0x720c2960
                      p3: '100*mode+namespace'=0x1618500010003
            time in wait: 10.974797 sec
           timeout after: 14 min 49 sec
                 wait id: 11802
                blocking: 1 session
             current sql:  alter procedure pining compile
             short stack: ksedsts()+465<-ksdxfstk()+32<-ksdxcb()+1927<-sspuser()+112<-__sighandler()<-semtimedop()+10<-skgpwwait()+160<-ksliwat()+2022<-kslwaitctx()+16
3<-ksfwaitctx()+14<-kglpnal()+1991<-kglpin()+1373<-kkdllk0()+927<-kkdlGetCodeObject()+307<-kkpalt()+353<-opiexe()+18119<-opiosq0()+3932<-kpooprx()+274<-kpoal8()+842<-o
piodr()+917<-ttcpip()+2183<-opitsk()+1710<-opiino()+969<-opiodr()+917<-opidrv()+570<-sou2o()+103<-opimai_real()+133<-ssthrdmain()+265<-main()+201<-__libc_start_main()+
245
            wait history:
              * time between current wait and wait #1: 0.001621 sec
              1.       event: 'SQL*Net message from client'
                 time waited: 3 min 24 sec
                     wait id: 11801           p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
              * time between wait #1 and #2: 0.000006 sec
              2.       event: 'SQL*Net message to client'
                 time waited: 0.000002 sec
                     wait id: 11800           p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
              * time between wait #2 and #3: 0.000396 sec
              3.       event: 'log file sync'
                 time waited: 0.084778 sec
                     wait id: 11799           p1: 'buffer#'=0x4bf
                                              p2: 'sync scn'=0x53ae54
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (dbdb.dbdb)
                   os id: 27149
              process id: 19, oracle@wang (TNS V1-V3)
              session id: 41
        session serial #: 59
    }
    which is waiting for 'PL/SQL lock timer' with wait info:
    {
                      p1: 'duration'=0x0
            time in wait: 11.653800 sec
           timeout after: 3 min 8 sec
                 wait id: 11681
                blocking: 2 sessions
             current sql:  call calling()
             short stack: ksedsts()+465<-ksdxfstk()+32<-ksdxcb()+1927<-sspuser()+112<-__sighandler()<-semtimedop()+10<-skgpwwait()+160<-ksliwat()+2022<-kslwaitctx()+16
3<-psdwat()+169<-pevm_icd_call_common()+897<-pfrinstr_ICAL()+169<-pfrrun_no_tool()+63<-pfrrun()+627<-plsql_run()+649<-peidxr_run()+263<-peidxexe()+79<-kkxdexe()+340<-k
kxmpexe()+241<-kgmexwi()+605<-kgmexec()+2193<-evapls()+813<-evaopn2()+808<-kkxmexcs()+133<-opiexe()+20880<-kpoal8()+2118<-opiodr()+917<-ttcpip()+2183<-opitsk()+1710<-o
piino()+969<-opiodr()+917<-opidrv()+570<-sou
            wait history:
              * time between current wait and wait #1: 0.002402 sec
              1.       event: 'SQL*Net message from client'
                 time waited: 48.869463 sec
                     wait id: 11680           p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
              * time between wait #1 and #2: 0.000008 sec
              2.       event: 'SQL*Net message to client'
                 time waited: 0.000001 sec
                     wait id: 11679           p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
              * time between wait #2 and #3: 0.000079 sec
              3.       event: 'log file sync'
                 time waited: 0.001921 sec
                     wait id: 11678           p1: 'buffer#'=0x83a
                                              p2: 'sync scn'=0x53b046
    }
 
Chain 1 Signature: 'PL/SQL lock timer'<='library cache pin'<='library cache lock'
Chain 1 Signature Hash: 0x38f0a7dd
-------------------------------------------------------------------------------
 
===============================================================================
Extra information that will be dumped at higher levels:
[level  4] :   1 node dumps -- [LEAF] [LEAF_NW]
[level  5] :   2 node dumps -- [NO_WAIT] [INVOL_WT] [SINGLE_NODE] [NLEAF] [SINGLE_NODE_NW]
 
State of ALL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[36]/1/37/121/0x90e7b740/26883/NLEAF/[40]
[37]/1/38/75/0x90e78660/27238/NLEAF/[36]
[40]/1/41/59/0x90e6f3c0/27149/LEAF/

NLEAF       –》该状态的session通常被认为 “stuck” session。即其他session所需要的资源正被其holding。
[36]对应的sid:37,被[40]对应的sid:41所阻塞。
[37]对应的sid:38,被[36]对应的sid:37所阻塞。

===============================================================================
END OF HANG ANALYSIS
===============================================================================

Oradebug command 'hanganalyze 3' console output:
Hang Analysis in /u01/app/oracle/diag/rdbms/dbdb/DBdb/trace/DBdb_ora_27483.trc
Processing Oradebug command 'close_trace'
Oradebug command 'close_trace' console output:
[oracle@wang ~]$