查看: 6327|回复: 3

[原创] WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK 问题诊断

[复制链接]
论坛徽章:
20
娜美
日期:2017-06-26 15:18:15目光如炬
日期:2018-04-29 22:00:00火眼金睛
日期:2018-04-30 22:00:00目光如炬
日期:2018-07-29 22:00:00火眼金睛
日期:2018-08-31 22:00:00目光如炬
日期:2018-09-02 22:00:00目光如炬
日期:2018-09-16 22:00:01火眼金睛
日期:2018-09-30 22:00:00目光如炬
日期:2018-10-14 22:00:00目光如炬
日期:2018-04-22 22:00:00
发表于 2018-8-9 17:02 | 显示全部楼层 |阅读模式

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)


论坛徽章:
20
娜美
日期:2017-06-26 15:18:15目光如炬
日期:2018-04-29 22:00:00火眼金睛
日期:2018-04-30 22:00:00目光如炬
日期:2018-07-29 22:00:00火眼金睛
日期:2018-08-31 22:00:00目光如炬
日期:2018-09-02 22:00:00目光如炬
日期:2018-09-16 22:00:01火眼金睛
日期:2018-09-30 22:00:00目光如炬
日期:2018-10-14 22:00:00目光如炬
日期:2018-04-22 22:00:00
 楼主| 发表于 2018-8-9 18:01 | 显示全部楼层

其实通过10g下的 V$SGA_DYNAMIC_COMPONENTS 视图可观察,SGA动态调整次数判断内存分配是否合理!
11G下查询方式:
prompt List Mem Usage

COL mem_component HEAD COMPONENT FOR A35
col last_opmode noprint
col last_optime noprint
col LAST_OPTYPE for a12
col gran_mb haed 'Granule|Size'
SELECT
    component mem_component
  , ROUND(current_size/1048576) current_mb
  , ROUND(min_size/1048576)     min_mb
  , ROUND(max_size/1048576)     max_mb
  , ROUND(user_specified_size/1048576)    spec_mb
  , oper_count
  , last_oper_type last_optype
  , last_oper_mode last_opmode
  , last_oper_time last_optime
  , granule_size/1048576        gran_mb
FROM
    v$memory_dynamic_components
order by ROUND(current_size/1048576) desc
/


break on report on sid on pid on SERIAL#
SELECT
    s.sid,pm.*
FROM
    v$session s
  , v$process p
  , v$process_memory pm
WHERE
    s.paddr = p.addr
AND p.pid = pm.pid
AND s.USERNAME not in ('SYS','SYSTEM')
ORDER BY
    sid
  , category
/


使用道具 举报

回复
论坛徽章:
20
娜美
日期:2017-06-26 15:18:15目光如炬
日期:2018-04-29 22:00:00火眼金睛
日期:2018-04-30 22:00:00目光如炬
日期:2018-07-29 22:00:00火眼金睛
日期:2018-08-31 22:00:00目光如炬
日期:2018-09-02 22:00:00目光如炬
日期:2018-09-16 22:00:01火眼金睛
日期:2018-09-30 22:00:00目光如炬
日期:2018-10-14 22:00:00目光如炬
日期:2018-04-22 22:00:00
 楼主| 发表于 2018-8-10 09:28 | 显示全部楼层

通过修改SHARED_POOL_SIZE=10240M 后,系统自动调整后的状态:

shared pool 收缩了236次,DEFAULT buffer cache 自动增大了238次

SQL> @mem10
List Mem Usage

COMPONENT                      CURRENT_SIZE_GB MIN_SIZE_GB MAX_SIZE_GB USER_SPECIFIED_SIZE_GB OPER_COUNT LAST_OPER_TYPE
------------------------------ --------------- ----------- ----------- ---------------------- ---------- --------------
shared pool                          10.609375   10.609375   29.046875                     10        236 SHRINK
large pool                             .078125     .078125     .078125                      0          0 STATIC
java pool                              .015625     .015625     .015625                      0          0 STATIC
streams pool                           .015625     .015625      .03125                      0          2 SHRINK
DEFAULT buffer cache                 20.015625      1.5625   20.015625                      0        238 GROW
KEEP buffer cache                            1           1           1                      1          0 STATIC
RECYCLE buffer cache                         0           0           0                      0          0 STATIC
DEFAULT 2K buffer cache                      0           0           0                      0          0 STATIC
DEFAULT 4K buffer cache                      0           0           0                      0          0 STATIC
DEFAULT 8K buffer cache                      0           0           0                      0          0 STATIC
DEFAULT 16K buffer cache                     0           0           0                      0          0 STATIC
DEFAULT 32K buffer cache                     0           0           0                      0          0 STATIC
ASM Buffer Cache                             0           0           0                      0          0 STATIC

13 rows selected.


   INST_ID NAME                                SIZE_MB RESIZEABLE
---------- -------------------------------- ---------- ---------------
         1 Maximum SGA Size                      32768 No
           Buffer Cache Size                     21520 Yes
           Shared Pool Size                      10864 Yes
           Startup overhead in Shared Pool         448 No
           Redo Buffers                            269 No
           Large Pool Size                          80 Yes
           Streams Pool Size                        16 Yes
           Granule Size                             16 No
           Java Pool Size                           16 Yes
           Fixed SGA Size                            2 No
           Free SGA Memory Available                 0
         2 Maximum SGA Size                      32768 No
           Shared Pool Size                      22352 Yes
           Buffer Cache Size                     10032 Yes
           Startup overhead in Shared Pool        1408 No
           Redo Buffers                            269 No
           Large Pool Size                          80 Yes
           Granule Size                             16 No
           Streams Pool Size                        16 Yes
           Java Pool Size                           16 Yes
           Fixed SGA Size                            2 No
           Free SGA Memory Available                 0

22 rows selected.


依据上面的方法,再次分析,SHARED_POOL_SIZE=5120M 就可以满足系统要求。
继续调整:

node1:
alter system set SHARED_POOL_SIZE=6144M sid='yyjc1'
node2:
alter system set SHARED_POOL_SIZE=6144M sid='yyjc2'

现在可以调整DB_CACHE_SIZE 大小:
alter system set DB_CACHE_SIZE=20480M sid='yyjc1'

注意上面查询结果,node2还没有调整到位,因为node2基本没什么业务操作,不会频繁引起SGA调整
所以还是会报错:
SQL> alter system set DB_CACHE_SIZE=20480M sid='yyjc2';
alter system set DB_CACHE_SIZE=20480M sid='yyjc2'
*
ERROR at line 1:
ORA-32017: failure in updating SPFILE
ORA-00384: Insufficient memory to grow cache

等待有足够的剩余内存时再做调整,或者等待下次重启。


通过case学到了什么?


通过这个case让我们明白AMM,ASMM自动管理有时候也是不可靠的,需要定期查询v$sga_dynamic_components/
v$memory_dynamic_components(11G)视图,分析是否存在大量的内存动态调整,确定内存分配是否合理,是否需要
人为调整。

系统经过一段时间运行优化,基本稳定后,需要依据oracle内存各部件统计数据和建议值,
调整SHARED_POOL_SIZE和DB_CACHE_SIZE 参数。合理分配内存主要部件的大小,避免内存
频繁调整带来的隐患。

最后看一个稳定的系统:

下面这个系统是稳定的,是经过调整的,实例启动后没有发生内存自动调整,这个是我们期待的效果:
(这个库原来报4031错误,和上面这个case正好相反shared pool 太小),调整后运行平稳

sho parameter shared_pool_size
shared_pool_size                big integer 8G


COMPONENT                      CURRENT_SIZE_GB MIN_SIZE_GB MAX_SIZE_GB USER_SPECIFIED_SIZE_GB OPER_COUNT LAST_OPER_TYPE
------------------------------ --------------- ----------- ----------- ---------------------- ---------- --------------
shared pool                                  8           8           0                      8          0 STATIC
large pool                             .015625           0           0                      0          1 GROW
java pool                              .015625     .015625           0                      0          0 STATIC
streams pool                                 0           0           0                      0          0 STATIC
DEFAULT buffer cache                 23.828125   23.828125           0                      0          1 INITIALIZING
KEEP buffer cache                         .125        .125           0                   .125          0 STATIC
RECYCLE buffer cache                         0           0           0                      0          0 STATIC
DEFAULT 2K buffer cache                      0           0           0                      0          0 STATIC
DEFAULT 4K buffer cache                      0           0           0                      0          0 STATIC
DEFAULT 8K buffer cache                      0           0           0                      0          0 STATIC
DEFAULT 16K buffer cache                     0           0           0                      0          0 STATIC
DEFAULT 32K buffer cache                     0           0           0                      0          0 STATIC
ASM Buffer Cache                             0           0           0                      0          0 STATIC

13 rows selected.


使用道具 举报

回复
论坛徽章:
0
发表于 2018-10-31 00:36 | 显示全部楼层
学习,慢慢消化,还有很多不懂的,
多谢分享

使用道具 举报

回复

您需要登录后才可以回帖 登录 | 注册

本版积分规则 发表回复

TOP技术积分榜 社区积分榜 徽章 团队 统计 知识索引树 积分竞拍 文本模式 帮助
  ITPUB首页 | ITPUB论坛 | 数据库技术 | 企业信息化 | 开发技术 | 微软技术 | 软件工程与项目管理 | IBM技术园地 | 行业纵向讨论 | IT招聘 | IT文档
  ChinaUnix | ChinaUnix博客 | ChinaUnix论坛
CopyRight 1999-2011 itpub.net All Right Reserved. 北京盛拓优讯信息技术有限公司版权所有 联系我们 
京ICP备09055130号-4  北京市公安局海淀分局网监中心备案编号:11010802021510 广播电视节目制作经营许可证:编号(京)字第1149号
  
快速回复 返回顶部 返回列表