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

千家信息网最后更新 2025年01月20日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 ~]$