A DB suddenly hang during a load. User come to me.
When i login the server, i can see the issue DB consuming 100% CPU on the server.
Tried "sqlplus / as sysdba" but also hang.
I gernerate a systemstate dump and notice that the PMON is blocked:
PROCESS 2: PMON
O/S info: user: oracle, term: UNKNOWN, ospid: 1193
OSD pid info: Unix process pid: 1193, image: oracle@alpcisddb484.corporate.ge.com (PMON)
waiting for 60108b48 Child shared pool level=7 child#=3
Location from where latch is held: kgh.h LINE:6387 ID:kghalo:
Context saved from call: 0
state=busy [holder orapid=89] wlstate=free [value=0]
waiters [orapid (seconds since: put on list, posted, alive check)]:
possible holder pid = 89 ospid=10478
Let's check which session is holding latch 60108b48, and what is the session waiting for:
PROCESS 89:
O/S info: user: oracle, term: UNKNOWN, ospid: 10478
OSD pid info: Unix process pid: 10478, image: oracle@alpcisddb484.corporate.ge.com
holding (efd=8) 60108b48 Child shared pool level=7 child#=3
Current Wait Stack:
0: waiting for 'library cache: mutex X'
idn=0xfc57b2b7, value=0xd100000000, where=0x4f
wait_id=57 seq_num=60 snap_id=1
wait times: snap=45 min 11 sec, exc=45 min 11 sec, total=45 min 11 sec
wait times: max=infinite, heur=45 min 11 sec
wait counts: calls=0 os=0
in_wait=1 iflags=0x5a2
Let’s see which session is holding mutex 0xfc57b2b7 and what is the session waiting for:
PROCESS 42: M000
SO: 0x19f40dda8, type: 4, owner: 0x19f2de3f8, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0x19f2de3f8, name=session, file=ksu.h LINE:12459, pg=0
(session) sid: 209 ser: 521 trans: (nil), creator: 0x19f2de3f8
Current Wait Stack:
Not in wait; last wait ended 45 min 10 sec ago
OK, till now we found the root blocking is M000.
It is holding mutex:
PROCESS 42: M000
SO: 0x19f40dda8, type: 4, owner: 0x19f2de3f8, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0x19f2de3f8, name=session, file=ksu.h LINE:12459, pg=0
(session) sid: 209 ser: 521 trans: (nil), creator: 0x19f2de3f8
Current Wait Stack:
Not in wait; last wait ended 45 min 10 sec ago
KGL-UOL SO Cache(total=240, free=0)
KGX Atomic Operation Log 0x17d569fc0
Mutex 0x19eb2b4c8(209, 0) idn 1fc57b2b7 oper EXCL
Library Cache uid 209 efd 7 whr 49 slp 0
oper=0 pt1=(nil) pt2=(nil) pt3=(nil)
But above also shows that M000 itself not in a wait since 45 mins back. What is M000 doing and why it doesn't release that mutex all along?
It is un-reasonable.
After review the process state of M000, i notice the process is already dead:
SO: 0x19f2de3f8, type: 2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0x19f2de3f8, name=process, file=ksu.h LINE:12451, pg=0
(process) Oracle pid:42, ser:16, calls cur/top: 0x1908c1eb8/0x1906a28f8
flags : (0x3) DEAD
flags2: (0x8030), flags3: (0x0)
intr error: 0, call error: 0, sess error: 0, txn error 0
intr queue: empty
ksudlp FALSE at location: 0
Cleanup details:
Found dead = 44 min 27 sec ago
Total Cleanup attempts = 10, Cleanup time = 15 min 49 sec, Cleanup timer = 15 min 45 sec
Last attempt (full) ended 54 sec ago, Length = 2 min 30 sec, Cleanup timer = 2 min 30 sec
OK. Now it is clear to us that M000's death leading to the DB hang.
But why M000 suddenly dead?
After checking alert.log i find blow:
Thu Dec 06 22:00:48 2012
Exception [type: SIGSEGV, Address not mapped to object] [ADDR:0x1060] [PC:0x90ED147, kglic0()+1075] [flags: 0x0, count: 1]
Errors in file /x484/dump01/oracle/hrxt/diag/rdbms/hrxdt/hrxdt_m000_10618.trc (incident=6337):
ORA-07445: exception encountered: core dump [kglic0()+1075] [SIGSEGV] [ADDR:0x1060] [PC:0x90ED147] [Address not mapped to object] []
Now all are clear.
After searching on metalink with above symbol, our scenario excatly matches this bug:
MMON Slave Process Reports ORA-7445 [kglic0] Error, Plus Database Hangs [ID 1487720.1]
More......
GE, AGFA. experienced in 9i/10g/11g/12c, AdvanceReplication, Stream, GoldenGate, RAC, DataGuard, ODA, EXADATA, GridControl. In my career I have always been assigned to handle most complicated and critical oracle issues without solution online, and I hope to record some of them via this blog.
December 7, 2012
MMON Slave Process Reports ORA-7445 [kglic0] Error, Plus Database Hangs
November 27, 2012
LOCK diagnose: NOWAIT lock requests could hang in RAC (blocked in compatble mode)
This summary is not available. Please
click here to view the post.
More......
June 30, 2012
RMAN blocked by ARCH process, waiting “enq: WL - contention”
Today, we got a file system alert, one server's arch mount point is 90% full.
After checking found one DB's archivelog occupied 90% space.
And this DB's backup arch job was running since 10 days ago and still hang there, no progress.
After checking in the DB, found the rman job was blocked by below red part event:
SSID OSUSER USERNAME STATE STATUS MODULE ---------- --------- ------------ -------------- ------------ -------------------------
BLOCKING_SESSION EVENT PROGRAM
---------------- ----------------------- --------------------------------
244 oracle SYS WAITING ACTIVE rman@server621 (TNS V1-V3)
58 enq: WL - contention rman@server621 (TNS V1-V3)
SQL_TEXT
--------------------------------------
begin dbms_rcvman.setDatabase(upper(:dbname), :rlscn, :rltime, :fhdbi, :db_unique_name, TRUE); dbms_rcvman.setCanApplyAnyRedo(TRUE); dbms_rcvman.setCanConvertCf(TRUE); if (:canhandletts = 1) then dbms_rcvman.setCanHandleTransportableTbs(TRUE); end if; end;
It is blocked by session 58, which is ARC0 process:
SID SPID ROGRAM
------ -------- --------------------------
58 10899 oracle@server621 (ARC1)
Killing ARC0 process, oracle will restart it automaticlly.
Then the rman backup job began to progress normally.
More......
June 2, 2012
what will happen if we hang CSSD process in Rac
in 11gR2, we have many new background processes including two cssd related processes cssdmonitor and cssdagent. cssdagent process is charge of respawn cssd.bin.
And both of those processes are charge of monitor cssd state and system hang problem.
[root@node1 node1]# ps -ef|grep cssd
root 479 1 0 00:30 ? 00:00:01 /prod/grid/app/11.2.0/grid/bin/cssdmonitor
root 471 1 0 00:30 ? 00:00:01 /prod/grid/app/11.2.0/grid/bin/cssdagent
grid 568 1 0 00:30 ? 00:00:04 /prod/grid/app/11.2.0/grid/bin/ocssd.bin
Let's see what will happen if we hang the ocssd.bin process:
[root@node1 ~]# kill -SIGSTOP 568
[root@node1 ~]# kill -SIGSTOP 568
[root@node1 ~]# kill -SIGSTOP 568
After a few seconds the node got a reboot. Let's go to check the log. We can find below information in alert$hostname.log:
2012-05-27 09:39:01.558
[ohasd(4545)]CRS-8011:reboot advisory message from host: node1, component: mo224552, with time stamp: L-2012-02-05-22:51:26.126
[ohasd(4545)]CRS-8013:reboot advisory message text: clsnomon_status: need to reboot, unexpected failure 8 received from CSS
2012-05-27 09:39:01.634
[ohasd(4545)]CRS-8011:reboot advisory message from host: node1, component: ag014510, with time stamp: L-2012-05-26-05:35:13.032
[ohasd(4545)]CRS-8013:reboot advisory message text: Rebooting after limit 28500 exceeded; disk timeout 28180, network timeout 28500, last heartbeat from CSSD at epoch seconds 1337981671.618, 28541 milliseconds ago based on invariant clock value of 57493073
2012-05-26 05:34:53.160: [ USRTHRD][2915036048] clsnproc_needreboot: Impending reboot at 50% of limit 28500; disk timeout 28180, network timeout 28500, last heartbeat from CSSD at epoch seconds 1337981671.618, 14871 milliseconds ago based on invariant clock 57493073; now polling at 100 ms
2012-05-26 05:35:02.748: [ USRTHRD][2915036048] clsnproc_needreboot: Impending reboot at 75% of limit 28500; disk timeout 28180, network timeout 28500, last heartbeat from CSSD at epoch seconds 1337981671.618, 21401 milliseconds ago based on invariant clock 57493073; now polling at 100 ms
2012-05-26 05:35:08.907: [ USRTHRD][2915036048] clsnproc_needreboot: Impending reboot at 90% of limit 28500; disk timeout 28180, network timeout 28500, last heartbeat from CSSD at epoch seconds 1337981671.618, 25681 milliseconds ago based on invariant clock 57493073; now polling at 100 ms
Since cssd was hang, so cssd itself's log won't have any information:
2012-05-26 05:34:25.052: [ CSSD][2894060432]clssnmSendingThread: sending status msg to all nodes
2012-05-26 05:34:25.052: [ CSSD][2894060432]clssnmSendingThread: sent 4 status msgs to all nodes
2012-05-26 05:34:30.525: [ CSSD][2894060432]clssnmSendingThread: sending status msg to all nodes
2012-05-26 05:34:30.525: [ CSSD][2894060432]clssnmSendingThread: sent 4 status msgs to all nodes
----HERE REBOOTED----2012-05-27 09:39:24.030: [ CSSD][3046872768]clssscmain: Starting CSS daemon, version 11.2.0.1.0, in (clustered) mode with uniqueness value 1306460363
2012-05-27 09:39:24.032: [ CSSD][3046872768]clssscmain: Environment is productionMore......