生产系统特别慢，查看数据库的等待事件。 SQL> col event for a30 SQL> select event,count(*) from v$session where wait_class 'Idle' group by event; EVENT COUNT(*) ------------------------------ ---------- asynch descriptor resize 1 log file sy
生产系统特别慢，查看数据库的等待事件。
SQL> col event for a30
SQL> select event,count(*) from v$session where wait_class
'Idle' group by event;
EVENT COUNT(*)
------------------------------ ----------
asynch descriptor resize 1
log file sync 2
read by other session 1
db file sequential read 1
library cache: mutex X 8
db file scattered read 1
log file parallel write 1
7 rows selected.
SQL> !uptime
18:27:03 up 199 days, 19:22, 6 users, load average: 10.92, 11.73, 10.37
top - 18:43:04 up 199 days, 19:38, 10 users, load average: 8.87, 9.56, 10.07
Tasks: 557 total, 10 running, 547 sleeping, 0 stopped, 0 zombie
Cpu(s): 99.2%us, 0.8%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 7840976k total, 7779784k used, 61192k free, 11932k buffers
Swap: 8385920k total, 163056k used, 8222864k free, 4986384k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
29684 oracle 25 0 3910m 78m 75m R 100.6 1.0 36:14.31 oraclehollycrm (LOCAL=NO)
29678 oracle 25 0 3911m 64m 60m R 100.0 0.8 36:33.71 oraclehollycrm (LOCAL=NO)
29688 oracle 25 0 3909m 46m 44m R 100.0 0.6 37:21.14 oraclehollycrm (LOCAL=NO)
32140 oracle 25 0 64996 2128 920 R 100.0 0.0 0:59.38 awk -f ass109.awk /home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_ora_30754.trc
29686 oracle 25 0 3910m 78m 75m R 99.6 1.0 36:25.12 oraclehollycrm (LOCAL=NO)
29680 oracle 25 0 3910m 84m 81m R 98.3 1.1 36:18.24 oraclehollycrm (LOCAL=NO)
29692 oracle 25 0 3910m 47m 44m R 98.0 0.6 36:51.41 oraclehollycrm (LOCAL=NO)
29682 oracle 25 0 3910m 47m 44m R 97.7 0.6 37:56.95 oraclehollycrm (LOCAL=NO)
29671 oracle 15 0 3911m 1.6g 1.6g S 2.0 22.0 7:01.01 oraclehollycrm (LOCAL=NO)
32216 oracle 15 0 3908m 23m 21m S 2.0 0.3 0:00.06 oraclehollycrm (LOCAL=NO)
32214 root 15 0 13000 1444 812 R 1.3 0.0 0:00.10 top -c
31891 root 15 0 13000 1448 812 S 1.0 0.0 0:03.29 top -c
8989 oracle 15 0 3907m 181m 175m S 0.3 2.4 553:08.53 ora_dia0_hollycrm
20331 oracle 15 0 3911m 757m 753m S 0.3 9.9 1:24.42 oraclehollycrm (LOCAL=NO)
做了hanganalyze level 10（11g的hanganalyze相比10g确实清晰了很多）
SQL> oradebug setmypid
Statement processed.
SQL> oradebug tracefile_name
/home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_ora_31189.trc
SQL> oradebug hanganalyze 10
Hang Analysis in /home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_ora_31189.trc
Trace file /home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_ora_31189.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /home/oracle/app/oracle/product/11.2.0/dbhome_1
System name: Linux
Node name: zrdb-2
Release: 2.6.18-128.el5xen
Version: #1 SMP Wed Dec 17 12:01:40 EST 2008
Machine: x86_64
Instance name: hollycrm
Redo thread mounted by this instance: 1
Oracle process number: 204
Unix process pid: 31189, image: oracle@zrdb-2 (TNS V1-V3)
*** 2014-05-13 18:26:14.114
*** SESSION ID:(831.9054) 2014-05-13 18:26:14.114
*** CLIENT ID:() 2014-05-13 18:26:14.114
*** SERVICE NAME:(SYS$USERS) 2014-05-13 18:26:14.114
*** MODULE NAME:(sqlplus@zrdb-2 (TNS V1-V3)) 2014-05-13 18:26:14.114
*** ACTION NAME:() 2014-05-13 18:26:14.114
Processing Oradebug command 'setmypid'
*** 2014-05-13 18:26:14.114
Oradebug command 'setmypid' console output:
*** 2014-05-13 18:27:16.717
Processing Oradebug command 'setmypid'
*** 2014-05-13 18:27:16.717
Oradebug command 'setmypid' console output:
*** 2014-05-13 18:27:23.165
Processing Oradebug command 'tracefile_name'
*** 2014-05-13 18:27:23.165
Oradebug command 'tracefile_name' console output:
/home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_ora_31189.trc
*** 2014-05-13 18:27:31.260
Processing Oradebug command 'hanganalyze 10'
*** 2014-05-13 18:27:32.964
===============================================================================
HANG ANALYSIS:
instances (db_name.oracle_sid): hollycrm.hollycrm
oradebug_node_dump_level: 10
analysis initiated by oradebug
===============================================================================
Chains most likely to have caused the hang:
[a] Chain 1 Signature: 'db file scattered read'<='read by other session'
Chain 1 Signature Hash: 0xa95f04bc
[b] Chain 2 Signature: 'log file parallel write'<='log file sync'
Chain 2 Signature Hash: 0x9a625f43
[c] Chain 3 Signature:
Chain 3 Signature Hash: 0x673a0128
===============================================================================
Non-intersecting chains:
-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
Oracle session identified by:
{
instance: 1 (hollycrm.hollycrm)
os id: 30806
process id: 209, oracle@zrdb-2 (J004)
session id: 262
session serial #: 3621
}
is waiting for 'read by other session' with wait info:
{
p1: 'file#'=0x5
p2: 'block#'=0x9b384
p3: 'class#'=0x1
time in wait: 0.066700 sec
timeout after: never
wait id: 1025
blocking: 0 sessions
current sql: INSERT INTO T_AGENT_STATUS_MTP( TIME_PIECE, DAY_ID, MONTH_ID, YEAR_ID, AGENT_DN, AGENT_ID, AGENT_NAME, TENANT_ID, TENANT_NAME, ONLINE_TIMELEN
GTH, WORK_TIMELENGTH, FREE_TIMELENGTH, BUSY_TIMELENGTH, CALLIN_TALKTIMELENGTH, CALLOUT_TALKTIMELENGTH, CALLIN_AFTERTIMELENGTH, CALLOUT_AFTERTIMELENGTH, REST_TIMELENGTH
, MIN_LOGIN
short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1782<-sspuser()+112<-__restore_rt()<-semtimedop()+10<-skgpwwait()+156<-ksliwat()+1821<-kslwaitctx()+16
2<-kcbzwb()+1561<-kcbgtcr()+27847<-ktrget2()+529<-kdst_fetch()+655<-kdstf11001010000km()+3621<-kdsttgr()+37120<-qertbFetch()+772<-rwsfcd()+103<-qerhjFetch()+3169<-rwsf
cd()+103<-qerhjFetch()+3169<-qerjoFetch()+656<-qerjoFetch()+656<-qerflFetch()+142<-qerghFetch()+308<-rwsfcd()+103<-qerltcFetch()+1192<-insexe()+1106<-opiexe()+4683<-op
ipls()+3103<-opiodr()+1149<-__PGOSF141_rpidr
wait history:
* time between current wait and wait #1: 0.002106 sec
1. event: 'read by other session'
time waited: 0.086792 sec
wait id: 1024 p1: 'file#'=0x5
p2: 'block#'=0x9b304
p3: 'class#'=0x1
* time between wait #1 and #2: 0.002215 sec
2. event: 'read by other session'
time waited: 0.129272 sec
wait id: 1023 p1: 'file#'=0x5
p2: 'block#'=0x9b284
p3: 'class#'=0x1
* time between wait #2 and #3: 0.002387 sec
3. event: 'read by other session'
time waited: 0.287277 sec
wait id: 1022 p1: 'file#'=0x5
p2: 'block#'=0x9b204
p3: 'class#'=0x1
}
and is blocked by
=> Oracle session identified by:
{
instance: 1 (hollycrm.hollycrm)
os id: 30800
process id: 206, oracle@zrdb-2 (J001)
session id: 1175
session serial #: 1258
}
which is waiting for 'db file scattered read' with wait info:
{
p1: 'file#'=0x5
p2: 'block#'=0x9b384
p3: 'blocks'=0x80
time in wait: 0.067670 sec
timeout after: never
wait id: 2771
blocking: 1 session
current sql: INSERT INTO T_TOTAL_OPERATION_MTP( TIME_PIECE , DAY_ID, MONTH_ID , YEAR_ID , TENANT_ID, TENANT_NAME, PROVINCE, CITY, TOTAL_CALL_COUNT , IVR_C
OUNT , IVR_GIVEUP_COUNT , IVR_SELF_SERVICE_COUNT, IVR_SERVICE_TIMELENGTH, MANUAL_COUNT , CONNECT_COUNT , QUEUE_GIVEUP_COUNT , RING_GIVEUP_COUNT , CONNECT_COUNT_5, CONN
ECT_COUNT_1
short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1782<-sspuser()+112<-__restore_rt()<-pread()+19<-ksfd_skgfqio()+191<-ksfd_io()+727<-ksfdread()+152<-kc
frbd1()+615<-kcbz_table_scan_read()+333<-kcbzibmlt()+2857<-kcbzib()+3815<-kcbgtcr()+16933<-ktrget2()+529<-kdst_fetch()+655<-kdstf11001010000km()+3621<-kdsttgr()+37120<
-qertbFetch()+772<-qerflFetch()+142<-qergsFetch()+7906<-qervwFetch()+139<-rwsfcd()+103<-qerhjFetch()+3169<-rwsfcd()+103<-qerhjFetch()+1753<-rwsfcd()+103<-qerhjFetch()+
1753<-qergsFetch()+7906<-rwsfcd()+103<-qerlt
wait history:
* time between current wait and wait #1: 0.002977 sec
1. event: 'db file scattered read'
time waited: 0.086056 sec
wait id: 2770 p1: 'file#'=0x5
p2: 'block#'=0x9b304
p3: 'blocks'=0x80
* time between wait #1 and #2: 0.003042 sec
2. event: 'db file scattered read'
time waited: 0.128587 sec
wait id: 2769 p1: 'file#'=0x5
p2: 'block#'=0x9b284
p3: 'blocks'=0x80
* time between wait #2 and #3: 0.003251 sec
3. event: 'db file scattered read'
time waited: 0.286321 sec
wait id: 2768 p1: 'file#'=0x5
p2: 'block#'=0x9b204
p3: 'blocks'=0x80
}
Chain 1 Signature: 'db file scattered read'<='read by other session'
Chain 1 Signature Hash: 0xa95f04bc
-------------------------------------------------------------------------------
-------------------------------------------------------------------------------
Chain 2:
-------------------------------------------------------------------------------
Oracle session identified by:
{
instance: 1 (hollycrm.hollycrm)
os id: 20331
process id: 355, oracle@zrdb-2
session id: 646
session serial #: 450
}
is waiting for 'log file sync' with wait info:
{
p1: 'buffer#'=0x5d2
p2: 'sync scn'=0x3709ba42
time in wait: 0.153704 sec
timeout after: never
wait id: 487011
blocking: 0 sessions
current sql:
short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1782<-sspuser()+112<-__restore_rt()<-read()+14<-nttfprd()+343<-nsbasic_brc()+338<-nsbrecv()+69<-nioqrc
()+485<-__PGOSF24_opikndf2()+978<-opitsk()+824<-opiino()+958<-opiodr()+1149<-opidrv()+570<-sou2o()+103<-opimai_real()+133<-ssthrdmain()+214<-main()+201<-__libc_start_m
ain()+244<-_start()+36
wait history:
* time between current wait and wait #1: 0.000216 sec
1. event: 'SQL*Net message from client'
time waited: 0.000169 sec
wait id: 487010 p1: 'driver id'=0x74637000
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: 487009 p1: 'driver id'=0x74637000
p2: '#bytes'=0x1
* time between wait #2 and #3: 0.000222 sec
3. event: 'SQL*Net message from client'
time waited: 0.000434 sec
wait id: 487008 p1: 'driver id'=0x74637000
p2: '#bytes'=0x1
}
and is blocked by
=> Oracle session identified by:
{
instance: 1 (hollycrm.hollycrm)
os id: 8995
process id: 11, oracle@zrdb-2 (LGWR)
session id: 575
session serial #: 1
}
which is waiting for 'log file parallel write' with wait info:
{
p1: 'files'=0x1
p2: 'blocks'=0x2
p3: 'requests'=0x1
time in wait: 0.153706 sec
timeout after: never
wait id: 97756259
blocking: 1 session
current sql:
short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1782<-sspuser()+112<-__restore_rt()<-semtimedop()+10<-skgpwwait()+156<-ksliwat()+1821<-kslwaitctx()+16
2<-kslwait()+141<-ksarcv()+207<-ksbabs()+323<-ksbrdp()+923<-opirip()+623<-opidrv()+603<-sou2o()+103<-opimai_real()+266<-ssthrdmain()+214<-main()+201<-__libc_start_main
()+244<-_start()+36
wait history:
* time between current wait and wait #1: 0.000027 sec
1. event: 'rdbms ipc message'
time waited: 0.142824 sec
wait id: 97756258 p1: 'timeout'=0x94
* time between wait #1 and #2: 0.000051 sec
2. event: 'log file parallel write'
time waited: 0.000004 sec
wait id: 97756257 p1: 'files'=0x1
p2: 'blocks'=0x2
p3: 'requests'=0x1
* time between wait #2 and #3: 0.000003 sec
3. event: 'log file parallel write'
time waited: 0.038758 sec
wait id: 97756256 p1: 'files'=0x1
p2: 'blocks'=0x2
p3: 'requests'=0x1
}
Chain 2 Signature: 'log file parallel write'<='log file sync'
Chain 2 Signature Hash: 0x9a625f43
-------------------------------------------------------------------------------
===============================================================================
Sessions in an involuntary wait or not in a wait:
。。。
===============================================================================
Extra information that will be dumped at higher levels:
[level 4] : 2 node dumps -- [LEAF] [LEAF_NW]
[level 5] : 10 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]):
[24]/1/25/347/0x145db45d0/29680/SINGLE_NODE_NW/
[66]/1/67/199/0x145d776a0/29690/SINGLE_NODE_NW/
[256]/1/257/1384/0x145e8e0a0/29682/SINGLE_NODE_NW/
[261]/1/262/3621/0x142ec7e58/30806/NLEAF/[1174]
[407]/1/408/77/0x1410ecef0/29684/SINGLE_NODE_NW/
[574]/1/575/1/0x1401e3a20/8995/LEAF/
[600]/1/601/12/0x1401bde70/29686/SINGLE_NODE_NW/
[645]/1/646/450/0x1411bde70/20331/NLEAF/[574]
[834]/1/835/2801/0x140294ad0/29692/SINGLE_NODE_NW/
[1171]/1/1172/846/0x141541a10/29688/SINGLE_NODE_NW/
[1174]/1/1175/1258/0x1404fbf90/30800/LEAF/
[1361]/1/1362/9234/0x141658410/29678/SINGLE_NODE_NW/
*** 2014-05-13 18:27:32.972
===============================================================================
END OF HANG ANALYSIS
===============================================================================
*** 2014-05-13 18:27:32.978
===============================================================================
HANG ANALYSIS DUMPS:
oradebug_node_dump_level: 10
===============================================================================
State of LOCAL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[24]/1/25/347/0x145db45d0/29680/SINGLE_NODE_NW/
[66]/1/67/199/0x145d776a0/29690/SINGLE_NODE_NW/
[256]/1/257/1384/0x145e8e0a0/29682/SINGLE_NODE_NW/
[261]/1/262/3621/0x142ec7e58/30806/NLEAF/[1174]
[407]/1/408/77/0x1410ecef0/29684/SINGLE_NODE_NW/
[574]/1/575/1/0x1401e3a20/8995/LEAF/
[600]/1/601/12/0x1401bde70/29686/SINGLE_NODE_NW/
[645]/1/646/450/0x1411bde70/20331/NLEAF/[574]
[834]/1/835/2801/0x140294ad0/29692/SINGLE_NODE_NW/
[1171]/1/1172/846/0x141541a10/29688/SINGLE_NODE_NW/
[1174]/1/1175/1258/0x1404fbf90/30800/LEAF/
[1361]/1/1362/9234/0x141658410/29678/SINGLE_NODE_NW/
Dumping call stack for process with ospid 29680
Dumping call stack for process with ospid 29690
Dumping call stack for process with ospid 29682
Dumping call stack for process with ospid 29684
Dumping call stack for process with ospid 29686
Dumping call stack for process with ospid 29692
Dumping call stack for process with ospid 29688
Dumping call stack for process with ospid 29678
Dumping call stack for process with ospid 29680
Dumping call stack for process with ospid 29690
Dumping call stack for process with ospid 29682
Dumping call stack for process with ospid 29684
Dumping call stack for process with ospid 29686
Dumping call stack for process with ospid 29692
Dumping call stack for process with ospid 29688
Dumping call stack for process with ospid 29678
*** 2014-05-13 18:27:34.520
Dumping detailed process information (fixed sga, context, etc.) for ospid 29680
dump location: /home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_ora_29680.trc
Dumping detailed process information (fixed sga, context, etc.) for ospid 29690
dump location: /home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_ora_29690.trc
Dumping detailed process information (fixed sga, context, etc.) for ospid 29682
dump location: /home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_ora_29682.trc
Dumping detailed process information (fixed sga, context, etc.) for ospid 29684
dump location: /home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_ora_29684.trc
Dumping detailed process information (fixed sga, context, etc.) for ospid 29686
dump location: /home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_ora_29686.trc
Dumping detailed process information (fixed sga, context, etc.) for ospid 29692
dump location: /home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_ora_29692.trc
Dumping detailed process information (fixed sga, context, etc.) for ospid 29688
dump location: /home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_ora_29688.trc
Dumping detailed process information (fixed sga, context, etc.) for ospid 29678
dump location: /home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_ora_29678.trc
*** 2014-05-13 18:28:04.538
Dumping process information for ospid 30806
dump location: /home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_j004_30806.trc
Dumping process information for ospid 8995
dump location: /home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_lgwr_8995.trc
Dumping process information for ospid 20331
dump location: /home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_ora_20331.trc
Dumping process information for ospid 30800
dump location: /home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_j001_30800.trc
*** 2014-05-13 18:28:09.102
===============================================================================
HANG ANALYSIS DUMPS: END
===============================================================================
*** 2014-05-13 18:28:09.102
*** 2014-05-13 18:28:09.103
Oradebug command 'hanganalyze 10' console output:
Hang Analysis in /home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_ora_31189.trc
不过发觉这个block 进程经常在变化，而且在os级别kill掉block后马上又出现了新的阻塞，甚至有些被阻塞的进程找不到blocker。
而造成library cache mutex x其实这些进程都是因为一个sql_id引起的library cache mutex x，library cache mutex x event的p1参数都是同一个。
然后再次运行了Systemstate 266：
oradebug setmypid
oradebug unlimit
oradebug dump systemstate 266
SQL> oradebug setmypid;
Statement processed.
SQL> oradebug tracefile_name;
/home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_ora_30754.trc
SQL> oradebug dump systemstate 266;
Statement processed.
[oracle@zrdb-2 ~]$ awk -f ass109.awk /home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_ora_30754.trc
Starting Systemstate 1
..............................................................................
...............................................................................
...............................................................................
...............................................................................
....................................
Ass.Awk Version 1.0.9 - Processing /home/oracle/app/oracle/diag/rdbms/hollycrm/hollycrm/trace/hollycrm_ora_30754.trc
System State 1
~~~~~~~~~~~~~~~~
1:
2: 0: waiting for 'pmon timer'
3: 0: waiting for 'VKTM Logical Idle Wait'
4: 0: waiting for 'rdbms ipc message'
5: 0: waiting for 'DIAG idle wait'
6: 0: waiting for 'rdbms ipc message'
7: 0: waiting for 'rdbms ipc message'
8: 0: waiting for 'DIAG idle wait'
9: 0: waiting for 'rdbms ipc message'
10: 0: waiting for 'rdbms ipc message'
11: 0: waiting for 'rdbms ipc message'
12: 0: waiting for 'rdbms ipc message'
13: 0: waiting for 'smon timer'
14: 0: waiting for 'rdbms ipc message'
15: 0: waiting for 'rdbms ipc message'
16: 0: waiting for 'rdbms ipc message'
17:
18:
19: 0: waiting for 'SQL*Net message from client'
20: 0: waiting for 'SQL*Net message from client'
21: 0: waiting for 'SQL*Net message from client'
22: 0: waiting for 'SQL*Net message from client'
23: 0: waiting for 'SQL*Net message from client'
24: 0: waiting for 'SQL*Net message from client'
25: 0: waiting for 'SQL*Net message from client'
26: 0: waiting for 'SQL*Net message from client'
27: 0: waiting for 'Streams AQ: qmn coordinator idle wait'
28: 0: waiting for 'rdbms ipc message'
29: 0: waiting for 'SQL*Net message from client'
Cmd: Select
30: 0: waiting for 'SQL*Net message from client'
31: 2: waited for 'Streams AQ: waiting for time management or cleanup tasks'
32: 0: waiting for 'SQL*Net message from client'
33: 0: waiting for 'SQL*Net message from client'
34: 0: waiting for 'SQL*Net message from client'
35: 0: waiting for 'SQL*Net message from client'
36: 0: waiting for 'SQL*Net message from client'
37: 0: waiting for 'SQL*Net message from client'
38: 0: waiting for 'SQL*Net message from client'
39: 0: waiting for 'SQL*Net message from client'
40: 0: waiting for 'SQL*Net message from client'
Cmd: Select
41: 0: waiting for 'SQL*Net message from client'
42: 0: waiting for 'SQL*Net message from client'
43: 0: waiting for 'SQL*Net message from client'
44:
Cmd: Select
45: 0: waiting for 'SQL*Net message from client'
46: 0: waiting for 'SQL*Net message from client'
47: 0: waiting for 'SQL*Net message from client'
48: 0: waiting for 'SQL*Net message from client'
49: 0: waiting for 'SQL*Net message from client'
50: 0: waiting for 'SQL*Net message from client'
51: 0: waiting for 'SQL*Net message from client'
52: 0: waiting for 'SQL*Net message from client'
53: 0: waiting for 'SQL*Net message from client'
54: 0: waiting for 'rdbms ipc message'
55: 0: waiting for 'SQL*Net message from client'
56: 0: waiting for 'SQL*Net message from client'
57: 0: waiting for 'SQL*Net message from client'
58: 0: waiting for 'SQL*Net message from client'
59: 0: waiting for 'SQL*Net message from client'
60: 0: waiting for 'SQL*Net message from client'
61: 0: waiting for 'SQL*Net message from client'
62: 0: waiting for 'SQL*Net message from client'
63: 0: waiting for 'SQL*Net message from client'
Cmd: Select
64: 0: waiting for 'SQL*Net message from client'
65: 0: waiting for 'SQL*Net message from client'
66: 0: waiting for 'SQL*Net message from client'
67: 0: waiting for 'Streams AQ: qmn slave idle wait'
68: 0: waiting for 'SQL*Net message from client'
69: 0: waiting for 'SQL*Net message from client'
70: 0: waiting for 'SQL*Net message from client'
71: 0: waiting for 'SQL*Net message from client'
72: 0: waiting for 'SQL*Net message from client'
73: 0: waiting for 'SQL*Net message from client'
74: 0: waiting for 'SQL*Net message from client'
Cmd: Update
75: 0: waiting for 'SQL*Net message from client'
76: 0: waiting for 'SQL*Net message from client'
77: 0: waiting for 'SQL*Net message from client'
78: 0: waiting for 'SQL*Net message from client'
79: 0: waiting for 'SQL*Net message from client'
80: 0: waiting for 'SQL*Net message from client'
81: 0: waiting for 'SQL*Net message from client'
82: 0: waiting for 'SQL*Net message from client'
83: 0: waiting for 'SQL*Net message from client'
84: 0: waiting for 'SQL*Net message from client'
85: 0: waiting for 'SQL*Net message from client'
86: 0: waiting for 'SQL*Net message from client'
87: 0: waiting for 'SQL*Net message from client'
Cmd: Insert
88: 0: waiting for 'SQL*Net message from client'
89: 0: waiting for 'SQL*Net message from client'
90: 0: waiting for 'SQL*Net message from client'
91: 0: waiting for 'SQL*Net message from client'
92: 0: waiting for 'Space Manager: slave idle wait'
93: 0: waiting for 'SQL*Net message from client'
94: 0: waiting for 'SQL*Net message from client'
95: 0: waiting for 'SQL*Net message from client'
96: 0: waiting for 'SQL*Net message from client'
97: 0: waiting for 'SQL*Net message from client'
98: 0: waiting for 'SQL*Net message from client'
99: 0: waiting for 'SQL*Net message from client'
100:0: waiting for 'SQL*Net message from client'
101:0: waiting for 'SQL*Net message from client'
102:0: waiting for 'SQL*Net message from client'
103:0: waiting for 'SQL*Net message from client'
104:0: waiting for 'SQL*Net message from client'
105:0: waiting for 'SQL*Net message from client'
106:0: waiting for 'SQL*Net message from client'
107:0: waiting for 'SQL*Net message from client'
108:0: waiting for 'SQL*Net message from client'
109:0: waiting for 'SQL*Net message from client'
110:0: waiting for 'SQL*Net message from client'
111:0: waiting for 'SQL*Net message from client'
112:0: waiting for 'SQL*Net message from client'
113:0: waiting for 'SQL*Net message from client'
114:0: waiting for 'SQL*Net message from client'
115:0: waiting for 'SQL*Net message from client'
116:0: waiting for 'SQL*Net message from client'
117:0: waiting for 'SQL*Net message from client'
118:0: waiting for 'SQL*Net message from client'
119:0: waiting for 'SQL*Net message from client'
120:0: waiting for 'SQL*Net message from client'
121:0: waiting for 'SQL*Net message from client'
122:0: waiting for 'SQL*Net message from client'
123:0: waiting for 'SQL*Net message from client'
124:0: waiting for 'SQL*Net message from client'
125:0: waiting for 'SQL*Net message from client'
126:0: waiting for 'SQL*Net message from client'
127:0: waiting for 'SQL*Net message from client'
128:0: waiting for 'SQL*Net message from client'
129:0: waiting for 'SQL*Net message from client'
130:0: waiting for 'SQL*Net message from client'
131:0: waiting for 'SQL*Net message from client'
132:0: waiting for 'SQL*Net message from client'
133:0: waiting for 'SQL*Net message from client'
134:0: waiting for 'SQL*Net message from client'
135:0: waiting for 'SQL*Net message from client'
136:0: waiting for 'SQL*Net message from client'
137:0: waiting for 'SQL*Net message from client'
138:0: waiting for 'SQL*Net message from client'
139:0: waiting for 'SQL*Net message from client'
140:0: waiting for 'SQL*Net message from client'
141:0: waiting for 'SQL*Net message from client'
142:0: waiting for 'SQL*Net message from client'
143:0: waiting for 'SQL*Net message from client'
144:0: waiting for 'SQL*Net message from client'
145:0: waiting for 'SQL*Net message from client'
146:0: waiting for 'SQL*Net message from client'
147:0: waiting for 'SQL*Net message from client'
148:0: waiting for 'SQL*Net message from client'
Cmd: Select
149:0: waiting for 'SQL*Net message from client'
150:0: waiting for 'SQL*Net message from client'
151:0: waiting for 'SQL*Net message from client'
152:0: waiting for 'SQL*Net message from client'
153:0: waiting for 'SQL*Net message from client'
154:0: waiting for 'SQL*Net message from client'
155:0: waiting for 'SQL*Net message from client'
156:0: waiting for 'SQL*Net message from client'
Cmd: Update
157:0: waiting for 'SQL*Net message from client'
158:0: waiting for 'SQL*Net message from client'
159:0: waiting for 'SQL*Net message from client'
160:0: waiting for 'SQL*Net message from client'
161:0: waiting for 'SQL*Net message from client'
162:0: waiting for 'SQL*Net message from client'
163:0: waiting for 'SQL*Net message from client'
164:0: waiting for 'SQL*Net message from client'
165:0: waiting for 'SQL*Net message from client'
Cmd: Select
166:0: waiting for 'SQL*Net message from client'
Cmd: Update
167:0: waiting for 'SQL*Net message from client'
Cmd: Update
168:0: waiting for 'SQL*Net message from client'
169:0: waiting for 'SQL*Net message from client'
170:0: waiting for 'SQL*Net message from client'
Cmd: Update
171:0: waiting for 'SQL*Net message from client'
172:0: waiting for 'SQL*Net message from client'
173:0: waiting for 'SQL*Net message from client'
174:0: waiting for 'SQL*Net message from client'
175:0: waiting for 'SQL*Net message from client'
176:0: waiting for 'SQL*Net message from client'
177:0: waiting for 'SQL*Net message from client'
178:0: waiting for 'SQL*Net message from client'
179:0: waiting for 'SQL*Net message from client'
180:0: waiting for 'SQL*Net message from client'
181:0: waiting for 'SQL*Net message from client'
182:0: waiting for 'SQL*Net message from client'
183:0: waiting for 'SQL*Net message from client'
184:
185:0: waiting for 'SQL*Net message from client'
186:0: waiting for 'SQL*Net message from client'
187:0: waiting for 'SQL*Net message from client'
188:0: waiting for 'SQL*Net message from client'
Cmd: Select
189:0: waiting for 'SQL*Net message from client'
190:0: waiting for 'SQL*Net message from client'
191:
Cmd: Select
192:
Cmd: Select
193:0: waiting for 'library cache: mutex X'
Cmd: Select
194:
Cmd: Select
195:
Cmd: Select
196:0: waiting for 'SQL*Net message from client'
197:0: waiting for 'SQL*Net message from client'
198:
Cmd: Select
199:0: waiting for 'SQL*Net message from client'
200:
Cmd: Select
201:0: waiting for 'SQL*Net message from client'
202:0: waiting for 'SQL*Net message from client'
203:0: waiting for 'SQL*Net message from client'
204:0: waiting for 'SQL*Net message from client'
205:0: waiting for 'db file scattered read' (0xe,0x2c804,0x80)
Cmd: Delete
206:
Cmd: Insert
207:0: waiting for 'db file scattered read' (0xe,0x1f484,0x80)
Cmd: Delete
208:
209:0: waiting for 'read by other session'
Cmd: Insert
210:
221:0: waiting for 'SQL*Net message from client'
222:0: waiting for 'SQL*Net message from client'
223:0: waiting for 'SQL*Net message from client'
224:0: waiting for 'SQL*Net message from client'
225:0: waiting for 'SQL*Net message from client'
226:0: waiting for 'SQL*Net message from client'
227:0: waiting for 'SQL*Net message from client'
228:0: waiting for 'SQL*Net message from client'
229:0: waiting for 'SQL*Net message from client'
230:0: waiting for 'SQL*Net message from client'
231:0: waiting for 'SQL*Net message from client'
232:0: waiting for 'SQL*Net message from client'
233:0: waiting for 'SQL*Net message from client'
234:0: waiting for 'SQL*Net message from client'
235:0: waiting for 'SQL*Net message from client'
236:0: waiting for 'SQL*Net message from client'
237:0: waiting for 'SQL*Net message from client'
238:0: waiting for 'SQL*Net message from client'
239:0: waiting for 'SQL*Net message from client'
240:0: waiting for 'SQL*Net message from client'
241:0: waiting for 'SQL*Net message from client'
242:0: waiting for 'SQL*Net message from client'
243:0: waiting for 'SQL*Net message from client'
244:0: waiting for 'SQL*Net message from client'
245:0: waiting for 'SQL*Net message from client'
246:0: waiting for 'SQL*Net message from client'
247:0: waiting for 'SQL*Net message from client'
248:0: waiting for 'SQL*Net message from client'
249:0: waiting for 'SQL*Net message from client'
250:0: waiting for 'SQL*Net message from client'
251:0: waiting for 'SQL*Net message from client'
252:0: waiting for 'SQL*Net message from client'
253:0: waiting for 'SQL*Net message from client'
254:0: waiting for 'SQL*Net message from client'
255:0: waiting for 'SQL*Net message from client'
256:0: waiting for 'SQL*Net message from client'
257:0: waiting for 'SQL*Net message from client'
258:0: waiting for 'SQL*Net message from client'
259:0: waiting for 'SQL*Net message from client'
260:0: waiting for 'SQL*Net message from client'
261:0: waiting for 'log file sync'
262:0: waiting for 'SQL*Net message from client'
263:0: waiting for 'SQL*Net message from client'
264:0: waiting for 'SQL*Net message from client'
265:0: waiting for 'SQL*Net message from client'
266:0: waiting for 'SQL*Net message from client'
267:0: waiting for 'SQL*Net message from client'
268:0: waiting for 'SQL*Net message from client'
269:0: waiting for 'SQL*Net message from client'
270:0: waiting for 'SQL*Net message from client'
271:0: waiting for 'SQL*Net message from client'
272:0: waiting for 'SQL*Net message from client'
273:0: waiting for 'SQL*Net message from client'
274:0: waiting for 'SQL*Net message from client'
275:0: waiting for 'SQL*Net message from client'
276:0: waiting for 'SQL*Net message from client'
277:0: waiting for 'SQL*Net message from client'
278:0: waiting for 'SQL*Net message from client'
279:0: waiting for 'SQL*Net message from client'
280:0: waiting for 'SQL*Net message from client'
281:0: waiting for 'SQL*Net message from client'
Cmd: Select
282:0: waiting for 'SQL*Net message from client'
283:0: waiting for 'SQL*Net message from client'
284:0: waiting for 'SQL*Net message from client'
285:0: waiting for 'SQL*Net message from client'
286:0: waiting for 'SQL*Net message from client'
287:0: waiting for 'SQL*Net message from client'
288:0: waiting for 'SQL*Net message from client'
289:0: waiting for 'SQL*Net message from client'
290:0: waiting for 'SQL*Net message from client'
291:0: waiting for 'SQL*Net message from client'
292:0: waiting for 'SQL*Net message from client'
293:0: waiting for 'SQL*Net message from client'
294:0: waiting for 'SQL*Net message from client'
Cmd: Select
295:0: waiting for 'SQL*Net message from client'
296:0: waiting for 'SQL*Net message from client'
298:0: waiting for 'SQL*Net message from client'
299:0: waiting for 'SQL*Net message from client'
300:0: waiting for 'SQL*Net message from client'
301:0: waiting for 'SQL*Net message from client'
302:0: waiting for 'SQL*Net message from client'
Cmd: Update
303:0: waiting for 'SQL*Net message from client'
304:0: waiting for 'SQL*Net message from client'
305:0: waiting for 'SQL*Net message from client'
306:0: waiting for 'SQL*Net message from client'
307:0: waiting for 'SQL*Net message from client'
308:0: waiting for 'SQL*Net message from client'
310:0: waiting for 'SQL*Net message from client'
312:0: waiting for 'SQL*Net message from client'
313:0: waiting for 'SQL*Net message from client'
314:0: waiting for 'SQL*Net message from client'
Cmd: Select
315:0: waiting for 'SQL*Net message from client'
316:0: waiting for 'SQL*Net message from client'
318:0: waiting for 'SQL*Net message from client'
319:0: waiting for 'SQL*Net message from client'
320:0: waiting for 'SQL*Net message from client'
322:0: waiting for 'SQL*Net message from client'
323:0: waiting for 'SQL*Net message from client'
324:0: waiting for 'SQL*Net message from client'
325:0: waiting for 'SQL*Net message from client'
326:0: waiting for 'SQL*Net message from client'
329:0: waiting for 'SQL*Net message from client'
330:0: waiting for 'SQL*Net message from client'
331:0: waiting for 'SQL*Net message from client'
332:0: waiting for 'SQL*Net message from client'
333:0: waiting for 'SQL*Net message from client'
334:0: waiting for 'SQL*Net message from client'
335:0: waiting for 'SQL*Net message from client'
336:0: waiting for 'SQL*Net message from client'
337:0: waiting for 'SQL*Net message from client'
338:0: waiting for 'SQL*Net message from client'
339:0: waiting for 'SQL*Net message from client'
340:0: waiting for 'SQL*Net message from client'
341:0: waiting for 'SQL*Net message from client'
342:0: waiting for 'SQL*Net message from client'
343:0: waiting for 'SQL*Net message from client'
345:0: waiting for 'SQL*Net message from client'
346:0: waiting for 'SQL*Net message from client'
347:0: waiting for 'SQL*Net message from client'
348:0: waiting for 'SQL*Net message from client'
349:0: waiting for 'SQL*Net message from client'
350:0: waiting for 'SQL*Net message from client'
355:0: waiting for 'SQL*Net message from client'
356:0: waiting for 'SQL*Net message from client'
358:0: waiting for 'SQL*Net message from client'
359:0: waiting for 'log file sync'
361:0: waiting for 'db file sequential read' (0x30,0x6ea3,0x1)
Cmd: Select
377:0: waiting for 'SQL*Net message from client'
378:0: waiting for 'SQL*Net message from client'
382:0: waiting for 'SQL*Net message from client'
385:0: waiting for 'SQL*Net message from client'
396:0: waiting for 'SQL*Net message from client'
412:0: waiting for 'SQL*Net message from client'
430:0: waiting for 'SQL*Net message from client'
446:0: waiting for 'SQL*Net message from client'
449:0: waiting for 'SQL*Net message from client'
451:0: waiting for 'SQL*Net message from client'
465:0: waiting for 'SQL*Net message from client'
486:0: waiting for 'SQL*Net message from client'
502:0: waiting for 'SQL*Net message from client'
514:0: waiting for 'SQL*Net message from client'
NO BLOCKING PROCESSES FOUND
找不到任何blocking processes
又运行了几次dump systemstate 266，还是找不到library cache mutex x的block，找了几篇mos的文章Troubleshooting: Waits for Mutex Type Events (文档 ID 1377998.1)
The SQL_ID is the SQL statement the session is running.
The P1 is the object the mutex is against.
For the topmost P1 run:
select KGLNAOBJ, KGLNAOWN, KGLHDNSP, KGLOBTYP
from x$kglob where KGLNAHSH= {value of P1}
This will tell you the object the mutex is against. If the same SQL_ID shows up with different P1 values in the Top10, then it is likely to be related to that SQL statement. If the SQL_ID and P1 is unique, it is likely to be a hot object.
If there is hot object, review following bug:
Note:9239863.8 Excessive "library cache:mutex X" contention on hot objects
而查看等待library cache mutex x的8个session都是运行同一个sql，sql_id是一致的，但是我们查看下x$kglob字段发现上述library cache mutex x等待事件p1对应的结果集有13000多个，
select KGLNAOBJ, KGLNAOWN, KGLHDNSP, KGLOBTYP
from x$kglob where KGLNAHSH=3127982377)
很可能这个是hot objects引起的library cache mutex x了，尝试刷新了shared pool还是没用，oracle给出的这个问题多半是个bug引起的。
Bug 9239863 - Excessive "library cache:mutex X" contention on hot objects (文档 ID 9239863.8)
Symptoms: Related To:
? Code Improvement
? Mutex Contention
? Waits for "library cache: mutex X"
? _kgl_hot_object_copies
? _KGL_DEBUG
Description
When there is *true* contention on a specific library cache object
then performance of the instance might be bottlenecked on
"library cache: mutex X" waits for that object.
This fix is really an enhancement to allow specific objects
which are known to exhibit high contention to be marked such
that the contention can be reduced (by holding multiple
copies of the object in the library cache).
Rediscovery Notes:
The following query may help identify objects being
accessed heavily:
select KGLNAOBJ, KGLNAOWN, KGLHDNSP, KGLOBTYP, KGLOBT23, KGLOBT24
from x$kglob where KGLOBT23 > 1000000 or KGLOBT24 > 1000000
order by KGLOBT24;
Note:
This fix requires special configuration via hidden parameters
to have any effect. The fix should only be enabled under the
guidance of Oracle Support.
Please note: The above is a summary description only. Actual symptoms can vary. Matching to any symptoms here does not confirm that you are encountering this problem. For questions about this bug please consult Oracle Support.
Oracle推荐的办法是打补丁到11.2.0.2版本，而影响的版本是有11.2.0.1版本的，刚好我这个库正是11.2.0.1版本，但是由于是生产环境，暂时是不能直接打补丁，最后想着是刷新shared pool，不过这个x$kglob里面的sql依然是没有踢出shared pool，问题依然出现
最后只能采取重启数据库或者调整业务逻辑的sql办法去避免这个library cache mutex x了，重启数据库后问题果然没有出现了。
这个性能案例其实并不算完全解决，因为很可能后面某个时间段再次出现hot object，这个算作小鱼职业生涯里面处理的最棘手的case，对于这个case的处理发觉自己在某些方面，特别是shared pool方面的理解还存在很多的不足，shared pool也是oracle最复杂的地方，后面要多处理些案例和内部原理的文章来加深自己的理解。
原文地址：library cache mutex x案例记录, 感谢原作者分享。
京公网安备 11010802041100号 | 京ICP备19059560号-4 | PHP1.CN 第一PHP社区 版权所有