|
|
WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK 问题诊断
作者简介：
----------------------------------------------------
@ 孙显鹏，海天起点oracle技术专家，十年从业经验
@ 精通oracle内部原理，擅长调优和解决疑难问题
@ 致力于帮助客户解决生产中的问题，提高生产效率。
@ 爱好：书法，周易，中医。微信：sunyunyi_sun
@ 易曰：精义入神，以致用也！
@ 调优乃燮理阴阳何其难也！
-----------------------------------------------------
版本：
操作系统 SunOS
oracle：
BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.5.0 - 64bi
现象：
sqlplus / as sysdba 无法登录
分析步骤：
1：检查 alter日志：
从晚上01:26:31 就开始报错：
Thu Aug 09 01:26:31 CST 2018
IPC Send timeout detected. Receiver ospid 9728
Thu Aug 09 01:26:31 CST 2018
Errors in file /u01/app/oracle/admin/yyjc/bdump/yyjc1_pz99_9728.trc:
Thu Aug 09 01:27:49 CST 2018
。。。。。。。
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=312
System State dumped to trace file /u01/app/oracle/admin/yyjc/udump/yyjc1_ora_23622.trc
Thu Aug 09 01:27:59 CST 2018
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=315
Thu Aug 09 01:28:15 CST 2018
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=321
Thu Aug 09 01:28:16 CST 2018
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=297
Thu Aug 09 01:28:51 CST 2018
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=324
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=1121
System State dumped to trace file /u01/app/oracle/admin/yyjc/udump/yyjc1_ora_17713.trc
Thu Aug 09 11:28:31 CST 2018
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=1122
Thu Aug 09 11:29:37 CST 2018
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=1124
Thu Aug 09 11:32:58 CST 2018
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=1126
System State dumped to trace file /u01/app/oracle/admin/yyjc/udump/yyjc1_ora_20938.trc
Thu Aug 09 11:35:01 CST 2018
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=1127
Thu Aug 09 11:38:59 CST 2018
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=1128
System State dumped to trace file /u01/app/oracle/admin/yyjc/udump/yyjc1_ora_24367.trc
Thu Aug 09 11:39:14 CST 2018
Errors in file /u01/app/oracle/admin/yyjc/bdump/yyjc1_pmon_23744.trc:
ORA-00822: MMAN --- Thu Aug 09 11:39:14 CST 2018
PMON: terminating instance due to error 822
Thu Aug 09 11:39:14 CST 2018
System state dump is made for local instance
Thu Aug 09 11:39:15 CST 2018
Trace dumping is performing id=[cdmp_20180809113914]
Thu Aug 09 11:39:20 CST 2018
Shutting down instance (abort)
License high water mark = 1081
Thu Aug 09 11:39:25 CST 2018
Instance terminated by PMON, pid = 23744
Thu Aug 09 11:39:30 CST 2018
Instance terminated by USER, pid = 22037
Thu Aug 09 11:39:48 CST 2018
Starting ORACLE instance (normal)
Thu Aug 09 11:39:50 CST 2018
sculkget: failed to lock /u01/app/oracle/product/10.2.0/db_1/dbs/lkinstyyjc1 exclusive
Thu Aug 09 11:39:50 CST 2018
sculkget: lock held by PID: 22229
Thu Aug 09 11:39:50 CST 2018
Oracle Instance Startup operation failed. Another process may be attempting to startup or shutdown this Instance.
Thu Aug 09 11:39:50 CST 2018
Failed to acquire instance startup/shutdown serialization primitive
LICENSE_MAX_SESSION = 0
LICENSE_SESSIONS_WARNING = 0
Interface type 1 aggr1 192.168.16.0 configured from OCR for use as a cluster interconnect
Interface type 1 e1000g2 10.208.16.0 configured from OCR for use as a public interface
Picked latch-free SCN scheme 3
LICENSE_MAX_USERS = 0
SYS auditing is disabled
Thu Aug 09 11:39:59 CST 2018
ksdpec: called for event 13740 prior to event group initialization
Starting up ORACLE RDBMS Version: 10.2.0.5.0. --实例启动
2：hang 分析:
sqlplus -prelim '/ as sysdba'
oradebug setmypid
oradebug unlimit
oradebug dump systemstate 10 --没有信息
oradebug hanganalyze 3
/u01/app/oracle/admin/yyjc/udump/yyjc1_ora_11932.trc
Found 28 objects waiting for <cnode/sid/sess_srno/proc_ptr/ospid/wait_event>
<0/2135/1/0x733d7548/23954/No Wait> --23954 进程阻塞了28个进程
此时kill了23954进程，实例自动重启，23954进程为mmon进程，正常kill mmon不会导致实例重启的！目前
实例启动后，正常！
下面是被阻塞进程：
Open chains found:
Chain 1 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/1919/452/0x76431c90/22228/row cache lock>
-- <0/1965/78/0x7f3df1d0/22054/library cache load lock>
Chain 2 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/2135/1/0x733d7548/23954/No Wait>
-- <0/1972/22297/0x7642ad00/9728/SGA: allocation forcing componen>
-- <0/524/12/0x7241f178/8349/library cache load lock>
Other chains found:
Chain 3 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/523/27/0x7741d6a0/11950/row cache lock>
Chain 4 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/526/19/0x7f41cdf0/11475/cursor: pin S wait on X>
。。。。。
3：分析自动trace的systemstate :
$ more /u01/app/oracle/admin/yyjc/udump/yyjc1_ora_20938.trc
/u01/app/oracle/admin/yyjc/udump/yyjc1_ora_20938.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.5.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP, Data Mining
and Real Application Testing options
Redo thread mounted by this instance: 1
Oracle process number: 1126 --1126进程等待>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! <<<
Unix process pid: 20938, image:
*** 2018-08-09 11:32:58.149
*** ACTION NAME ) 2018-08-09 11:32:58.147
*** MODULE NAMEJDBC Thin Client) 2018-08-09 11:32:58.147
*** SERVICE NAMESYS$USERS) 2018-08-09 11:32:58.147
*** SESSION ID577.103) 2018-08-09 11:32:58.147
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! <<<
row cache enqueue: session: b744dce68, mode: N, request: S
===================================================
/PROCESS 1126
PROCESS 1126:
----------------------------------------
SO: b7544e868, type: 2, owner: 0, flag: INIT/-/-/0x00
(process) Oracle pid=1126, calls cur/top: 3e08a89b0/3e08a89b0, flag: (0) -
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 0 0 167
last post received-location: kqrbtm
last process to post me: b733d9528 1 6
last post sent: 0 0 24
last post sent-location: ksasnd
last process posted by me: b733d9528 1 6
(latch info) wait_event=0 bits=0
Process Group: DEFAULT, pseudo proc: b73462c98
O/S info: user: oracle, term: UNKNOWN, ospid: 20938
OSD pid info: Unix process pid: 20938, image: oracle@yyjczx1
Short stack dump:
----------------------------------------
SO: 3e08a89b0, type: 3, owner: b7544e868, flag: INIT/-/-/0x00
(call) sess: cur b744dce68, rec b765169c8, usr b744dce68; depth: 0
----------------------------------------
SO: 3db148118, type: 50, owner: 3e08a89b0, flag: INIT/-/-/0x00
row cache enqueue: count=1 session=b744dce68 object=b7bdd7ed8, request=S --请求模式
savepoint=0x14
row cache parent object: address=b7bdd7ed8 cid=10(dc_usernames) ---row cahce 等待对象
hash=b62f6f8c typ=9 transaction=0 flags=00008000
own=b7bdd7fa8[3dbf98c50,3dbf98c50] wat=b7bdd7fb8[3dbf98b90,3db1761f0] mode=S
status=-/-/-/-/-/-/-/-/LOADING
request=N release=FALSE flags=0
instance lock id=QK b62f6f8c 159736d5
data=
00075855 4e4a4941 4e000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000
----------------------------------------
$ more /u01/app/oracle/admin/yyjc/udump/yyjc1_ora_20938.trc |grep b7bdd7ed8
row cache enqueue: count=1 session=b765da838 object=b7bdd7ed8, mode=S
--只有81号进程持有该对象的S锁，其他都是请求S锁，S和S兼容为什么无法获取呢？
row cache parent object: address=b7bdd7ed8 cid=10(dc_usernames)
row cache enqueue: count=1 session=b73551e38 object=b7bdd7ed8, request=S
row cache parent object: address=b7bdd7ed8 cid=10(dc_usernames)
row cache enqueue: count=1 session=b744d22a8 object=b7bdd7ed8, request=S
row cache parent object: address=b7bdd7ed8 cid=10(dc_usernames)
row cache enqueue: count=1 session=b7358b960 object=b7bdd7ed8, request=S
row cache parent object: address=b7bdd7ed8 cid=10(dc_usernames)
row cache enqueue: count=1 session=b725b0d38 object=b7bdd7ed8, request=S
row cache parent object: address=b7bdd7ed8 cid=10(dc_usernames)
row cache enqueue: count=1 session=b77545458 object=b7bdd7ed8, request=S
省略中间相似内容。。
row cache enqueue: count=1 session=b7f4c4fa8 object=b7bdd7ed8, request=S
row cache parent object: address=b7bdd7ed8 cid=10(dc_usernames)
row cache enqueue: count=1 session=b7f4c3a30 object=b7bdd7ed8, request=S
row cache parent object: address=b7bdd7ed8 cid=10(dc_usernames)
row cache enqueue: count=1 session=b774c7248 object=b7bdd7ed8, request=S
row cache parent object: address=b7bdd7ed8 cid=10(dc_usernames)
row cache enqueue: count=1 session=b754f8018 object=b7bdd7ed8, request=S
row cache parent object: address=b7bdd7ed8 cid=10(dc_usernames)
row cache enqueue: count=1 session=b774bf178 object=b7bdd7ed8, request=S
row cache parent object: address=b7bdd7ed8 cid=10(dc_usernames)
row cache enqueue: count=1 session=b7f4be450 object=b7bdd7ed8, request=S
row cache parent object: address=b7bdd7ed8 cid=10(dc_usernames)
row cache enqueue: count=1 session=b734cfbc0 object=b7bdd7ed8, request=S
row cache parent object: address=b7bdd7ed8 cid=10(dc_usernames)
row cache enqueue: count=1 session=b744d0d30 object=b7bdd7ed8, request=S
row cache parent object: address=b7bdd7ed8 cid=10(dc_usernames)
下面是81 号进程：
/PROCESS 81
PROCESS 81:
----------------------------------------
SO: b773d1368, type: 2, owner: 0, flag: INIT/-/-/0x00
(process) Oracle pid=81, calls cur/top: a740b5200/b0510a348, flag: (0) -
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 0 0 167
last post received-location: kqrbtm
last process to post me: b733d9528 1 6
last post sent: 0 0 24
last post sent-location: ksasnd
last process posted by me: b733d9528 1 6
(latch info) wait_event=0 bits=0
Process Group: DEFAULT, pseudo proc: b73462c98
O/S info: user: oracle, term: UNKNOWN, ospid: 23779
OSD pid info: Unix process pid: 23779, image: oracle@yyjczx1
Short stack dump:
ksdxfstk()+36<-ksdxcb()+2472<-sspuser()+176<-__sighndlr()+12<-call_user_handler()+992<-sigacthandler()+104<-_syscall6()+32<-s
skgpwwait()+196<-ksliwat()+1020<-kslwaitns_timed()+48<-kskthbwt()+456<-kslwait()+296<-kksLockWait()+372<-kgxWait()+416<-kgxMo
difyRefCount()+404<-kgxSharedExamine()+28<-kxsGetRuntimeLock()+204<-kksCheckCursor()+228<-kksSearchChildList()+1524<-kksfbc()
+4404<-kkspsc0()+1176<-kksParseCursor()+208<-opiosq0()+2152<-opiodr()+1536<-rpidrus()+196<-skgmstack()+168<-rpidru()+184<-rpi
swu2()+540<-rpidrv()+1704<-rpisplu()+332<-rpispl()+32<-kqdGetCursor()+572<-kqdunr()+12<-kqrpre1()+1504<-kqrpre()+40<-kkdlgui(
)+144<-kzia3a()+344<-kpolna()+1948<-kpogsk()+132<-opiodr()+1536<-ttcpip()+1188<-opitsk()+1532<-opiino()+1128<-opiodr()+1536<-
opidrv()+828<-sou2o()+80<-opimai_real()+124<-main()+152<-_start()+380
----------------------------------------
SO: b765da838, type: 4, owner: b773d1368, flag: INIT/-/-/0x00
(session) sid: 1590 trans: 0, creator: b773d1368, flag: (41) USR/- BSY/-/-/-/-/-
DID: 0000-0000-00000000, short-term DID: 0001-0051-0018BF2B
txn branch: 0
oct: 0, prv: 0, sql: 0, psql: 0, user: 0/SYS
service name: yyjc
O/S info: user: apache, term: , ospid: 20985, machine: AMS-Mini
program: perl@AMS-Mini (TNS V1-V3)
application name: perl@AMS-Mini (TNS V1-V3), hash value=2506949173
waiting for 'cursor: pin S wait on X' wait_time=0, seconds since wait started=0
idn=64424c68, value=7db00000000, where|sleeps=50041c836
blocking sess=0x0 seq=60305
该进程在获取 cursor: pin S wait on X ，pin S 其他进程持有 pin X
该等待是发生在library cache中的，
Dumping Session Wait History
for 'cursor: pin S wait on X' count=1 wait_time=0.355818 sec
idn=64424c68, value=7db00000000, where|sleeps=50041c619
for 'cursor: pin S wait on X' count=1 wait_time=0.009800 sec
idn=64424c68, value=7db00000000, where|sleeps=50041c609
for 'cursor: pin S wait on X' count=1 wait_time=0.009994 sec
idn=64424c68, value=7db00000000, where|sleeps=50041c5f8
for 'cursor: pin S wait on X' count=1 wait_time=0.009799 sec
idn=64424c68, value=7db00000000, where|sleeps=50041c5e8
for 'cursor: pin S wait on X' count=1 wait_time=0.009802 sec
idn=64424c68, value=7db00000000, where|sleeps=50041c5d8
for 'cursor: pin S wait on X' count=1 wait_time=0.009809 sec
idn=64424c68, value=7db00000000, where|sleeps=50041c5c8
for 'cursor: pin S wait on X' count=1 wait_time=0.009799 sec
idn=64424c68, value=7db00000000, where|sleeps=50041c5b9
for 'cursor: pin S wait on X' count=1 wait_time=0.009801 sec
idn=64424c68, value=7db00000000, where|sleeps=50041c5a9
for 'cursor: pin S wait on X' count=1 wait_time=0.009802 sec
idn=64424c68, value=7db00000000, where|sleeps=50041c599
for 'cursor: pin S wait on X' count=1 wait_time=0.009806 sec
idn=64424c68, value=7db00000000, where|sleeps=50041c589
......
----------------------------------------
SO: 3dbf98c20, type: 50, owner: b0510a348, flag: INIT/-/-/0x00
row cache enqueue: count=1 session=b765da838 object=b7bdd7ed8, mode=S
--持有row cache S锁！和上面grep结果一致
savepoint=0x14
row cache parent object: address=b7bdd7ed8 cid=10(dc_usernames)
hash=b62f6f8c typ=9 transaction=0 flags=00008000
own=b7bdd7fa8[3dbf98c50,3dbf98c50] wat=b7bdd7fb8[3dbf98b90,3db112bb0] mode=S
status=-/-/-/-/-/-/-/-/LOADING
request=N release=FALSE flags=0
instance lock id=QK b62f6f8c 159736d5
data=
00075855 4e4a4941 4e000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000
----------------------------------------
4：使用 ass.awk 分析
SunOS下awk 分析工具没有结果，索引把文件下载上传到linux机子分析：
awk -f ass.awk /home/oracle/yyjc1_ora_20938.trc
Blockers
~~~~~~~~
Above is a list of all the processes. If they are waiting for a resource
then it will be given in square brackets. Below is a summary of the
waited upon resources, together with the holder of that resource.
Notes:
~~~~~
o A process id of '???' implies that the holder was not found in the
systemstate.
Resource Holder State
Rcache object=b7b796ed8, 325: waiting for 'cursor: pin S wait on X'
Rcache object=b7b85a8b0, 460: waiting for 'cursor: pin S wait on X'
Rcache object=b7b2edc78, 317: waiting for 'cursor: pin S wait on X'
Rcache object=b7bdd7ed8, 81: waiting for 'cursor: pin S wait on X'
Rcache object=b7ba62950, 311: waiting for 'cursor: pin S wait on X'
Rcache object=b7bb68bc8, 410: waiting for 'cursor: pin S wait on X'
Rcache object=b7ba637a0, 301: waiting for 'cursor: pin S wait on X'
Rcache object=b7bddf8c0, 307: waiting for 'SGA: allocation forcing component growth'
Rcache object=b7b1916d0, 329: waiting for 'cursor: pin S wait on X'
Rcache object=a59b61d18, 345: waiting for 'cursor: pin S wait on X'
Rcache object=b7bb8a8c0, 334: waiting for 'cursor: pin S wait on X'
Rcache object=afc96ed00, 400: waiting for 'SGA: allocation forcing component growth'
Rcache object=b7b2ed550, 504: waiting for 'cursor: pin S wait on X'
Rcache object=b7be45b98, 614: waiting for 'cursor: pin S wait on X'
Rcache object=b7befb3a8, 633: waiting for 'cursor: pin S wait on X'
Object Names
~~~~~~~~~~~~
Rcache object=b7b796ed8,
Rcache object=b7b85a8b0,
Rcache object=b7b2edc78,
Rcache object=b7bdd7ed8,
Rcache object=b7ba62950,
Rcache object=b7bb68bc8,
Rcache object=b7ba637a0,
Rcache object=b7bddf8c0,
Rcache object=b7b1916d0,
Rcache object=a59b61d18,
Rcache object=b7bb8a8c0,
Rcache object=afc96ed00,
Rcache object=b7b2ed550,
Rcache object=b7be45b98,
Rcache object=b7befb3a8,
1924721 Lines Processed.
发现问题：
SGA: allocation forcing component growth，由于SGA动态调整导致LATCH持有时间太长，最终导致大量的row lock，
这个row lock 需要ROW CACHE ENQUEUE 保护，应该是用户登录需要访问DC_USER无法获取 ROW CACHE ENQUEUE导致了问题，最终
无法登录，系统HANG,这个问题有点类似11G新功能登录延迟导致不能登录。
我们看看307在干什么：
很明显在等待SGA: allocation forcing component growth
PROCESS 307:
----------------------------------------
SO: b75414410, type: 2, owner: 0, flag: INIT/-/-/0x00
(process) Oracle pid=307, calls cur/top: b1591a7f8/b05324bc8, flag: (0) -
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 3229 0 4
last post received-location: kslpsr
last process to post me: b733d7548 1 6
last post sent: 0 0 24
last post sent-location: ksasnd
last process posted by me: b733d7548 1 6
(latch info) wait_event=3229 bits=0
Process Group: DEFAULT, pseudo proc: b73462c98
O/S info: user: oracle, term: UNKNOWN, ospid: 23303
OSD pid info: Unix process pid: 23303, image: oracle@yyjczx1
Short stack dump:
ksdxfstk()+36<-ksdxcb()+2472<-sspuser()+176<-__sighndlr()+12<-call_user_handler()+992<-sigacthandler()+104<-_syscall6()+32<-s
skgpwwait()+196<-ksliwat()+1020<-kslwaitns_timed()+48<-kskthbwt()+456<-kslwait()+296<-kmgs_sleep_wait()+92<-kmgs_create_reque
st()+4324<-kmgs_immediate_req()+3560<-ksmasg()+188<-kghnospc()+1556<-kghalf()+1700<-kksLoadChild()+1728<-kxsGetRuntimeLock()+
1764<-kksfbc()+7056<-kkspsc0()+1176<-kksParseCursor()+208<-opiosq0()+2152<-opiodr()+1536<-rpidrus()+196<-skgmstack()+168<-rpi
dru()+184<-rpiswu2()+540<-rpidrv()+1704<-rpisplu()+332<-rpispl()+32<-kqdGetCursor()+572<-kqdunr()+12<-kqrpre1()+1504<-kqrpre(
)+40<-kkdlgui()+144<-kzia3a()+344<-kpolna()+1948<-kpogsk()+132<-opiodr()+1536<-ttcpip()+1188<-opitsk()+1532<-opiino()+1128<-o
piodr()+1536<-opidrv()+828<-sou2o()+80<-opimai_real()+124<-main()+152<-_start()+380
(FOB) flags=2 fib=b26dce4e0 incno=0 pending i/o cnt=0
fname=/u01/app/oracle/datafile/yyjc/lvyyjc_system1_5G
fno=1 lblksz=8192 fsiz=655359
----------------------------------------
SO: b75611c88, type: 4, owner: b75414410, flag: INIT/-/-/0x00
(session) sid: 2011 trans: 0, creator: b75414410, flag: (41) USR/- BSY/-/-/-/-/-
DID: 0001-0133-0003D072, short-term DID: 0001-0133-0003D073
txn branch: 0
oct: 0, prv: 0, sql: 0, psql: 0, user: 0/SYS
service name: yyjc
O/S info: user: infadc, term: , ospid: 364578, machine: dcdwetl2
program: pmdtm@dcdwetl2 (TNS V1-V3)
application name: pmdtm@dcdwetl2 (TNS V1-V3), hash value=4274089472
waiting for 'SGA: allocation forcing component growth' wait_time=0, seconds since wait started=0
=0, =0, =0
blocking sess=0x0 seq=63634
Dumping Session Wait History
for 'SGA: allocation forcing component growth' count=1 wait_time=0.000014 sec --调整SGA组件大小！！！
=0, =0, =0
for 'SGA: allocation forcing component growth' count=1 wait_time=0.329896 sec
=0, =0, =0
for 'SGA: allocation forcing component growth' count=1 wait_time=0.002374 sec
=0, =0, =0
for 'SGA: allocation forcing component growth' count=1 wait_time=0.002218 sec
=0, =0, =0
for 'SGA: allocation forcing component growth' count=1 wait_time=0.002299 sec
=0, =0, =0
for 'SGA: allocation forcing component growth' count=1 wait_time=0.002281 sec
=0, =0, =0
for 'SGA: allocation forcing component growth' count=1 wait_time=0.002662 sec
=0, =0, =0
for 'SGA: allocation forcing component growth' count=1 wait_time=0.002118 sec
=0, =0, =0
for 'SGA: allocation forcing component growth' count=1 wait_time=0.002678 sec
=0, =0, =0
for 'SGA: allocation forcing component growth' count=1 wait_time=0.001290 sec
=0, =0, =0
AWK 分析刚开始发生问题的systemstate：0点产生的trace
结果问题是一致的，结果如下：
Blockers
~~~~~~~~
Above is a list of all the processes. If they are waiting for a resource
then it will be given in square brackets. Below is a summary of the
waited upon resources, together with the holder of that resource.
Notes:
~~~~~
o A process id of '???' implies that the holder was not found in the
systemstate.
Resource Holder State
Rcache object=b7b796ed8, 325: waiting for 'cursor: pin S wait on X'
Rcache object=b7b2edc78, 317: waiting for 'cursor: pin S wait on X'
Rcache object=b7bdd7ed8, 81: waiting for 'cursor: pin S wait on X'
Rcache object=b7ba62950, 311: waiting for 'cursor: pin S wait on X'
Rcache object=b7bddf8c0, 307: waiting for 'SGA: allocation forcing component growth'
Rcache object=b7b1916d0, 329: waiting for 'cursor: pin S wait on X'
Rcache object=b7bb68bc8, 410: waiting for 'cursor: pin S wait on X'
Rcache object=a59b61d18, 345: waiting for 'cursor: pin S wait on X'
Rcache object=b7bb8a8c0, 334: waiting for 'cursor: pin S wait on X'
Rcache object=afc96ed00, 400: waiting for 'SGA: allocation forcing component growth'
Rcache object=b7b85a8b0, 460: waiting for 'cursor: pin S wait on X'
Rcache object=b7b2ed550, 504: waiting for 'cursor: pin S wait on X'
Rcache object=b7be45b98, 614: waiting for 'cursor: pin S wait on X'
Rcache object=b7befb3a8, 633: waiting for 'cursor: pin S wait on X'
Object Names
~~~~~~~~~~~~
Rcache object=b7b796ed8,
Rcache object=b7b2edc78,
Rcache object=b7bdd7ed8,
Rcache object=b7ba62950,
Rcache object=b7bddf8c0,
Rcache object=b7b1916d0,
Rcache object=b7bb68bc8,
Rcache object=a59b61d18,
Rcache object=b7bb8a8c0,
Rcache object=afc96ed00,
Rcache object=b7b85a8b0,
Rcache object=b7b2ed550,
Rcache object=b7be45b98,
Rcache object=b7befb3a8,
2001314 Lines Processed.
结果：
问题是由于SGA自动调整导致。
解决方案：
1：增加SGA_TARGET，增加SGA
2：调整合适的 DB_CACHE_SIZE=(VALUE)M
SHARED_POOL_SIZE=<VALUE>M
看看内存使用情况：
看看AWR：
AWR报告从0点开始没有生成：
48711 08 Aug 2018 23:00 1
48712 09 Aug 2018 00:00 1
48717 09 Aug 2018 13:00 1
48718 09 Aug 2018 14:00 1
48719 09 Aug 2018 15:00 1
Cache Sizes
~~~~~~~~~~~ Begin End
---------- ----------
Buffer Cache: 7,776M 8,416M Std Block Size: 8K --buffer cache 太小动态调整
Shared Pool Size: 23,584M 22,944M Log Buffer: 276,456K
下一个采集的AWR：
Cache Sizes
~~~~~~~~~~~ Begin End
---------- ----------
Buffer Cache: 8,416M 8,736M Std Block Size: 8K --问题依旧
Shared Pool Size: 22,944M 22,624M Log Buffer: 276,456K
Buffer Pool Advisory DB/Inst: YYJC/yyjc1 Snap: 48719
-> Only rows with estimated physical reads >0 are displayed
-> ordered by Block Size, Buffers For Estimate
Est
Phys
Size for Size Buffers for Read Estimated
P Est (M) Factor Estimate Factor Physical Reads
--- -------- ------ ---------------- ------ ------------------
D 832 .1 99,684 1.4 25,827,938
D 1,664 .2 199,368 1.3 24,071,429
D 2,496 .3 299,052 1.3 22,596,277
D 3,328 .4 398,736 1.2 21,396,445
D 4,160 .5 498,420 1.1 20,118,361
D 4,992 .6 598,104 1.1 19,080,709
D 5,824 .7 697,788 1.0 18,439,617
D 6,656 .8 797,472 1.0 18,204,635
D 7,488 .9 897,156 1.0 18,072,722
D 8,320 1.0 996,840 1.0 17,942,272
D 8,416 1.0 1,008,342 1.0 17,927,764
D 9,152 1.1 1,096,524 1.0 17,815,634
D 9,984 1.2 1,196,208 1.0 17,716,737
D 10,816 1.3 1,295,892 1.0 17,579,276
D 11,648 1.4 1,395,576 1.0 17,432,568
D 12,480 1.5 1,495,260 1.0 17,353,391
D 13,312 1.6 1,594,944 1.0 17,281,649
D 14,144 1.7 1,694,628 1.0 17,165,232
D 14,976 1.8 1,794,312 0.9 16,976,949
D 15,808 1.9 1,893,996 0.9 16,719,235
D 16,640 2.0 1,993,680 0.9 16,407,425
Shared SP Est LC Time Time Load Load Est LC
Pool Size Size Est LC Saved Saved Time Time Mem Obj
Size(M) Factr (M) Mem Obj (s) Factr (s) Factr Hits (K)
-------- ----- -------- ------------ -------- ------ ------- ------ ------------
4,528 .2 1,085 63,411 729,457 1.0 831 1.0 15,220
6,832 .3 1,085 63,411 729,457 1.0 831 1.0 15,220
9,136 .4 1,085 63,411 729,457 1.0 831 1.0 15,220
11,440 .5 1,085 63,411 729,457 1.0 831 1.0 15,220
13,744 .6 1,085 63,411 729,457 1.0 831 1.0 15,220
16,048 .7 1,085 63,411 729,457 1.0 831 1.0 15,220
18,352 .8 1,085 63,411 729,457 1.0 831 1.0 15,220
20,656 .9 1,085 63,411 729,457 1.0 831 1.0 15,220
22,960 1.0 1,085 63,411 729,457 1.0 831 1.0 15,220
25,264 1.1 1,085 63,411 729,457 1.0 831 1.0 15,220
27,568 1.2 1,085 63,411 729,457 1.0 831 1.0 15,220
29,872 1.3 1,085 63,411 729,457 1.0 831 1.0 15,220
32,176 1.4 1,085 63,411 729,457 1.0 831 1.0 15,220
34,480 1.5 1,085 63,411 729,457 1.0 831 1.0 15,220
36,784 1.6 1,085 63,411 729,457 1.0 831 1.0 15,220
39,088 1.7 1,085 63,411 729,457 1.0 831 1.0 15,220
41,392 1.8 1,085 63,411 729,457 1.0 831 1.0 15,220
43,696 1.9 1,085 63,411 729,457 1.0 831 1.0 15,220
46,000 2.0 1,085 63,411 729,457 1.0 831 1.0 15,220
-------------------------------------------------------------
依据上面信息可以知道，ASMM调整不合理，shared pool 分配太大，shared pool 10g就足够，
需要手动修改，减小shared pool大小，增加buffer cache大小。
SGA当前策略：
SGA=32G
shared_pool:23,584M
buffer_cache:7,776M
应调整为：
SGA=32G
shared_pool:10240M
buffer_cache:15240M
调整脚本：
alter system set SHARED_POOL_SIZE=10240M sid='yyjc1'
alter system set SHARED_POOL_SIZE=10240M sid='yyjc2'
select * from v$sgainfo;
因为是改小所以目前是不起作用的，需要重启实例生效。
重启实例后修改buffer cache：
alter system set DB_CACHE_SIZE=15240M sid='yyjc1'
alter system set DB_CACHE_SIZE=15240M sid='yyjc2'
注意：
不可集群范围修改：
SQL> alter system set SHARED_POOL_SIZE=10240M sid='*';
alter system set SHARED_POOL_SIZE=10240M sid='*'
*
ERROR at line 1:
ORA-32018: parameter cannot be modified in memory on another instance
操作系统内存：
# prtconf |grep Memory
Memory size: 130560 Megabytes
# vmstat 2 5
kthr memory page disk faults cpu
r b w swap free re mf pi po fr de sr s5 s6 s7 s8 in sy cs us sy id
0 0 0 55145544 31603400 649 1337 2020 69 67 0 0 -0 0 0 6 35491 94960 36508 2 1 97
1 5 0 56351504 34789280 246 691 917 0 0 0 0 0 0 0 0 44722 134819 48548 3 1 96
0 6 0 56374784 34812744 205 597 945 0 0 0 0 0 0 0 4 50980 157102 57051 3 2 96
1 4 0 56377408 34816592 211 597 11 0 0 0 0 0 0 0 0 48934 152637 53955 3 2 96
1 3 0 56264944 34756856 648 2774 944 36 36 0 0 0 0 0 17 45433 252221 50372 3 2 95
看来操作系统剩余内存还有30G可用，后续可依据SGA使用情况调整！
关于WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK 其他原因可查看下面文档：
Troubleshooting: "WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! " (Doc ID 278316.1)
|
|
IP卡
狗仔卡
发表于 2018-8-9 17:02
提升卡
置顶卡
变色卡
显身卡
楼主