查看: 32003|回復: 3

[原創] WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK 問題診斷

[復制鏈接]
論壇徽章:
21
娜美
日期:2017-06-26 15:18:15火眼金睛
日期: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-11-30 22:00:01目光如炬
日期:2018-04-29 22:00:00
跳轉到指定樓層
1#
發表于 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: [email protected]
    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: [email protected]
    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: [email protected] (TNS V1-V3)
    application name: [email protected] (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: [email protected]
    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: [email protected] (TNS V1-V3)
    application name: [email protected] (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)


論壇徽章:
21
娜美
日期:2017-06-26 15:18:15火眼金睛
日期: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-11-30 22:00:01目光如炬
日期:2018-04-29 22:00:00
2#
 樓主| 發表于 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
/


使用道具 舉報

回復
論壇徽章:
21
娜美
日期:2017-06-26 15:18:15火眼金睛
日期: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-11-30 22:00:01目光如炬
日期:2018-04-29 22:00:00
3#
 樓主| 發表于 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
4#
發表于 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號
  
快速回復 返回頂部 返回列表
30岁的男人干啥赚钱快赚钱多 羚锐制药股票股吧 河北体育彩票11选五结果 北京十一选五开奖app 腾讯分分彩手机分析工具 江西十一选五1000期走势图 2020年安徽十一选五带线走势图 山西快乐10分钟开奖 天津体彩11远五走势图 福彩3d百十位差振幅 快乐8下载安装