My Oracle Support Banner

Database instance crash due to slow IO response (Doc ID 2441906.1)

Last updated on MARCH 12, 2021

Applies to:

Oracle Database - Enterprise Edition - Version 12.1.0.2 and later
Information in this document applies to any platform.

Symptoms

2 node RAC running on Hp-Ux.
Diagnostic destination of database instances pointing to same shared cluster OS filesystem alongwith other database files.
Instance eviction was taking place randomly.

Thu Jul 12 10:59:52 2018
LGWR (ospid: 12635) waits for event 'log file parallel write' for 3 secs.
Thu Jul 12 11:00:46 2018

Thu Jul 12 11:09:56 2018
Received an instance abort message from instance 2
Please check instance 2 alert and LMON trace files for detail.
Thu Jul 12 11:09:56 2018
System state dump requested by (instance=1, osid=678960 (LMD0)), summary=[abnormal instance termination].
Thu Jul 12 11:09:57 2018
LMD0 (ospid: 12528): terminating the instance due to error 481

Thu Jul 12 11:10:00 2018
License high water mark = 756
Thu Jul 12 11:10:03 2018
Instance terminated by LMD0, pid = 12528
Thu Jul 12 11:10:04 2018
USER (ospid: 3046): terminating the instance
Thu Jul 12 11:10:04 2018
Instance terminated by USER, pid = 3046
Thu Jul 12 11:10:40 2018
Starting ORACLE instance (normal) (OS id: 3724)

File_name :: alert_<ORACLE_SID>1.log 

 

*** 2018-07-12 11:00:16.499
Warning: log write elapsed time 7264ms, size 67434KB

*** 2018-07-12 11:00:22.796
Warning: log write elapsed time 6191ms, size 56344KB

File_name:: <ORACLE_SID>_lgwr_12635.trc

 

*** 2018-07-12 10:30:47.939
==============================
DIA0 (ospid: 12523) has not moved for 70 sec (1531391447.1531391377)
: heartbeat check status 2 (acceptable) (threshold 300 sec)
: heartbeat poke time 0x5b472d99 req 0x3d ack 0x3c freq 30
: heartbeat state 0x2.ffff () pso-flag 0x0

*** 2018-07-12 10:30:48.553
: Not in wait; last wait ended 69 secs ago.
: last wait_id 11721 at 'DIAG idle wait'.
==============================
Dumping PROCESS DIA0 (ospid: 12523) States
==============================
===[ Callstack ]===

*** 2018-07-12 10:30:49.251
Process diagnostic dump for oracle@<connect_string> (DIA0), OS id=12523,
pid: 13, proc_ser: 1, sid: 4902, sess_ser: 30356

*** 2018-07-12 10:30:49.563
-------------------------------------------------------------------------------
os thread scheduling delay history: (sampling every 1.000000 secs)
0.000000 secs at [ 10:30:49 ]
NOTE: scheduling delay has not been sampled for 0.326921 secs
0.000000 secs from [ 10:30:45 - 10:30:50 ], 5 sec avg
0.000612 secs from [ 10:29:50 - 10:30:50 ], 1 min avg
0.000981 secs from [ 10:25:50 - 10:30:50 ], 5 min avg
loadavg : 0.11 0.37 0.35
Swapinfo :
Avail = 267022.06Mb Used = 83416.61Mb

*** 2018-07-12 10:30:50.589
Swap free = 183539.84Mb Kernel rsvd = 12794.94Mb
Free Mem = 42609.86Mb
F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME COMD
1401 S oracle 12523 1 0 178 20 e0000006e4210680 131535 e0000007065e70c0 09:57:40 ? 0:32 ora_dia0_<ORACLE_SID>
Short stack dump:
ksedsts()+336<-ksdxfstk()+64<-ksdxcb()+1984<-sspuser()+656<-<kernel><-_write_sys()+48<-write()+176<-sdbgrfuwf_write_file()+176<-sdbgrfwf_write_file()+96
<-dbgtfdFileWrite()+928<-dbgtfdFileAccessCbk()+304<-dbgtfmWriteMetadata()+2368<-dbgtfWriteRec()+2192<-dbgtRecVAWriteDisk()+304<-dbgtTrcVaList_int()+2048
<-dbgtTrc_int()+96<-ksdhng_chain_dump()+19824<-ksdhng_prt_chains()+784<-$cold_ksdhng_graph_output()+752<-ksdhng_request_msg_get_phase3()+1072
<-ksdhng_request_msg_get()+208<-kjzh_master_start_next_phase()+2896<-kjzhifcp()+1392<-kjzdpreg()+2640<-kjzdm_rac()+5520<-$cold_kjzdm()+880<-ksbrdp()+3264
<-opirip()+1728<-opidrv()+1232<-sou2o()+288<-opimai_real()+320<-ssthrdmain()+896<-main()+336<-main_opd_entry()+80

-------------------------------------------------------------------------------

*** 2018-07-12 10:30:51.595
Process diagnostic dump actual duration=1.935000 sec
(max dump time=5.000000 sec)

*** 2018-07-12 10:30:51.804

===[ Callstack ]===

*** 2018-07-12 11:00:21.715
Process diagnostic dump for oracle@<connect_string> (LGWR), OS id=12635,
pid: 25, proc_ser: 1, sid: 3395, sess_ser: 41015
-------------------------------------------------------------------------------
os thread scheduling delay history: (sampling every 1.000000 secs)
0.000000 secs at [ 11:00:21 ]
NOTE: scheduling delay has not been sampled for 0.364756 secs
0.000730 secs from [ 11:00:17 - 11:00:22 ], 5 sec avg
0.000932 secs from [ 10:59:22 - 11:00:22 ], 1 min avg
0.000960 secs from [ 10:55:22 - 11:00:22 ], 5 min avg

*** 2018-07-12 11:00:22.634
loadavg : 0.13 0.14 0.17
Swapinfo :
Avail = 267022.06Mb Used = 86317.03Mb
Swap free = 180639.44Mb Kernel rsvd = 12906.94Mb
Free Mem = 42477.21Mb
F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME COMD
1401 S oracle 12635 1 0 178 20 e0000006d9479cc0 133623 e000000747fef9c0 09:57:47 ? 0:08 ora_lgwr_<ORACLE_SID>
Short stack dump:

*** 2018-07-12 11:00:23.455
ksedsts()+336<-ksdxfstk()+64<-ksdxcb()+1984<-sspuser()+656<-<kernel><-_write_sys()+48<-write()+176<-skgfqio()+2096<-ksfd_skgfqio()+336<-ksfdgo()+816<-ksfd_sbio()+1520<-ksfdbio()+1968<-kcrfw_do_write()+3568<-kcrfw_redo_write()+2272<-kcrfw_redo_write_driver()+3280<-kcrfw_redo_hbt()+128<-ksbabs()+2064<-ksbrdp()+3264<-opirip()+1728<-opidrv()+1232<-sou2o()+288<-opimai_real()+320<-ssthrdmain()+896<-main()+336<-main_opd_entry()+80

-------------------------------------------------------------------------------
Process diagnostic dump actual duration=1.662000 sec
(max dump time=5.000000 sec)

File_name:: <ORACLE_SID>_lmhb_12541.trc 

Changes

 

Cause

To view full details, sign in with your My Oracle Support account.

Don't have a My Oracle Support account? Click to get started!


In this Document
Symptoms
Changes
Cause
Solution


My Oracle Support provides customers with access to over a million knowledge articles and a vibrant support community of peers and Oracle experts.