GEO RAC 12.2:: takes extra 4 minutes as port 20048 is blocked by firewall

(Doc ID 2337034.1)

Last updated on JANUARY 25, 2018

Applies to:

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

Symptoms

Case ::1

One of voting disk is placed on NFS on 2 node Geo RAC environment.

The startup of ASM instances wait 4 minutes on "KSXPPING: KSXP selected for Ping".

NOTE: cache began mount (first) of group DGTEST 7/0x6700250D
2017-10-31T10:00:41.920232+01:00
KSXPPING: KSXP selected for Ping <----- 4 minutes
2017-10-31T10:04:59.010423+01:00
NOTE: Assigning number (1,0) to disk (AFD:ACFS101)
NOTE: Assigning number (1,6) to disk (AFD:ACFS107)

 As per stack ,it was trying to mount NFS filer .

=> Oracle session identified by:
{
instance: 1 (+asm.+asm1)
os id: 46939
process id: 26, oracle@xxx.xxxx.xxx.xx
session id: 1369
session serial #: 41804
}
which is waiting for 'Disk file operations I/O' with wait info:
{
p1: 'FileOperation'=0x2
p2: 'fileno'=0x0
p3: 'filetype'=0xf
time in wait: 6.392151 sec
timeout after: never
wait id: 11
blocking: 1 session <<-----
current sql:
short stack: ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-read()+14<-kgnfs_exec_remote_mount()+2745
<-kgnfsgetmnthdl()+2105<-kgodm_getnfscdata()+907<-kgodm_identify()+1517<-ksfdodm_libidentify()+697<-ksfd_odmopn()+875<-ksfdopn1()+374
<-ksfdopn()+240<-ksfd_get_storage_type()+815<-kfk_fill_ufs_kfknm()+435<-kfk_ufs_next_discvdsk()+402<-kfk_fetch_next_disk()+403
<-kfk_next_discvdsk()+369<-kfk_discover_disks()+590<-kfdDiscoverString()+646<-kfdDiscoverShallow()+1098<-kfgbDriver()+1794<-ksbabs()+683
<-ksbrdp
wait history:
* time between current wait and wait #1: 1.315761 sec
1. event: 'CSS operation: action'
time waited: 0.001202 sec
wait id: 10 p1: 'function_id'=0x43

time waited: 0.003179 sec
wait id: 8
}

Chain 1 Signature: 'Disk file operations I/O'<='rdbms ipc reply'
Chain 1 Signature Hash: 0x7278e935
-------------------------------------------------------------------------------

File_name :: _ASM1_diag_46907.trc

 

Case 2::

While doing failover in RAC ONE database ,it was delaying 120 seconds with below message.

Wed Jan 10 15:46:03 2018
CKPT (ospid: 33426) waits for event 'Disk file operations I/O' for 79 secs.
Wed Jan 10 15:46:13 2018
CKPT (ospid: 33426) waits for event 'Disk file operations I/O' for 89 secs.
CKPT (ospid: 33426) waits for event 'Disk file operations I/O' for 99 secs.
Wed Jan 10 15:46:33 2018
CKPT (ospid: 33426) waits for event 'Disk file operations I/O' for 109 secs.
Wed Jan 10 15:46:43 2018
CKPT (ospid: 33426) waits for event 'Disk file operations I/O' for 119 secs.

From hanganalyze ,

 

-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
Oracle session identified by:
{
instance: 1 (lhdb2.lhdb2_1)
os id: 115957
process id: 44, oracle@xxxx.xx.xx.xxx (TNS V1-V3)
session id: 241
session serial #: 19587
}
is waiting for 'rdbms ipc reply' with wait info:
{
p1: 'from_process'=0x18
time in wait: 59.514433 sec <<--------
timeout after: 14 min 0 sec
wait id: 85
blocking: 0 sessions
current sql: ALTER DATABASE MOUNT /* db agent *//* {1:11217:3086} */
short stack: ksedsts()+244<-ksdxfstk()+58<-ksdxcb()+918<-sspuser()+224<-__sighandler()<-semtimedop()+10<-skgpwwait()+200<-ksliwat()+2091
<-kslwaitctx()+161<-ksarcr()+410<-ksbwcoex()+33<-kccidf()+91<-kccocf()+113<-kcfcmb()+1071<-kcfmdb()+43<-adbdrv_options()+789<-adbdrv()+151
<-opiexe()+20361<-opiosq0()+4534<-kpoal8()+1268<-opiodr()+1165<-ttcpip()+2699<-opitsk()+1740<-opiino()+945<-opiodr()+1165<-opidrv()+587
<-sou2o()+145<-opimai_real()+154<-ssthrdmain()+412<-main()+236<-__libc_start_main()+253
wait history:
* time between current wait and wait #1: 0.000048 sec
1. event: 'DFS lock handle'
time waited: 0.000497 sec
wait id: 84 p1: 'type|mode'=0x444d0005
p2: 'id1'=0x0
p3: 'id2'=0x2
* time between wait #1 and #2: 0.000043 sec
2. event: 'enq: DM - contention'
time waited: 0.000628 sec
wait id: 83 p1: 'name|mode'=0x444d0006
p2: 'type'=0x0
p3: 'type'=0x1
* time between wait #2 and #3: 0.000094 sec
3. event: 'rdbms ipc reply'
time waited: 0.000067 sec
wait id: 82 p1: 'from_process'=0x16
}
and is blocked by
=> Oracle session identified by:
{
instance: 1 (lhdb2.lhdb2_1)
os id: 115787
process id: 24, oracle@xxxx.xx.xx.xxx (CKPT)
session id: 3
session serial #: 37827
}
which is waiting for 'Sync ASM discovery' with wait info:
{
time in wait: 2.479280 sec
heur. time in wait: 59.451227 sec <<--------
timeout after: never
wait id: 37
blocking: 1 session
current sql: <none>
short stack: ksedsts()+244<-ksdxfstk()+58<-ksdxcb()+918<-sspuser()+224<-__sighandler()<-semtimedop()+10<-skgpwwait()+200
<-ksliwat()+2091<-kslwaitctx()+161<-kfgbWaitForDiscovery()+214<-kfgCreate()+1394<-kfgUse()+1605<-kfioIdentify()+1625
<-ksfdafOpen()+1099<-ksfdopn1()+4787<-ksfdopn()+217<-kcc_identify_file()+173<-kcc_identify()+287<-kccida()+307
<-ksbabs()+874<-ksbrdp()+1068<-opirip()+1488<-opidrv()+616<-sou2o()+145<-opimai_real()+270<-ssthrdmain()+412
<-main()+236<-__libc_start_main()+253
wait history:
* time between current wait and wait #1: 0.000000 sec
1. event: 'Disk file operations I/O'
time waited: 0.000004 sec (last interval)
time waited: 57.035109 sec (total)
wait id: 25 p1: 'FileOperation'=0x2
p2: 'fileno'=0x0
p3: 'filetype'=0x1
* time between wait #1 and #2: 0.000000 sec
2. event: 'Sync ASM discovery'
time waited: 10.003005 sec
wait id: 36
* time between wait #2 and #3: 0.000000 sec
3. event: 'Disk file operations I/O'
time waited: 0.000005 sec (last interval)
time waited: 47.032100 sec (total)
wait id: 25 p1: 'FileOperation'=0x2
p2: 'fileno'=0x0
p3: 'filetype'=0x1
}

Chain 1 Signature: 'Sync ASM discovery'<='rdbms ipc reply'
Chain 1 Signature Hash: 0x15ce4322
-------------------------------------------------------------------------------

-------------------------------------------------------------------------------
Chain 2:
-------------------------------------------------------------------------------
Oracle session identified by:
{
instance: 1 (lhdb2.lhdb2_1)
os id: 115815
process id: 31, oracle@xxxx.xx.xx.xxx (RBAL)
session id: 417
session serial #: 27610
}
is waiting for 'Disk file operations I/O' with wait info:
{
p1: 'FileOperation'=0x2
p2: 'fileno'=0x0
p3: 'filetype'=0xf
time in wait: 59.377701 sec
timeout after: never
wait id: 14
blocking: 0 sessions
current sql: <none>
short stack: ksedsts()+244<-ksdxfstk()+58<-ksdxcb()+918<-sspuser()+224<-__sighandler()<-read()+14<-kgnfs_exec_remote_mount()+1896
<-kgnfsgetmnthdl()+1470<-kgodm_getnfscdata()+808<-kgodm_identify()+661<-odm_identify()+63<-ksfdodm_libidentify()+216<-ksfd_odmopn()+786
<-ksfdopn1()+338<-ksfdopn()+217<-ksfd_get_storage_type()+683<-kfk_fill_ufs_kfknm()+552<-kfk_ufs_next_discvdsk()+403
<-kfk_fetch_next_disk()+455<-kfk_next_discvdsk()+321<-kfk_discover_disks()+581<-kfdDiscoverString()+571<-kfdDiscoverShallow()+1091
<-kfgbSendShallow()+197
wait history:
* time between current wait and wait #1: 0.047133 sec
1. event: 'CSS operation: action'
time waited: 0.001236 sec
wait id: 13 p1: 'function_id'=0x43
* time between wait #1 and #2: 0.000003 sec
2. event: 'GPnP Termination'
time waited: 0.001741 sec
wait id: 12
* time between wait #2 and #3: 0.000006 sec
3. event: 'GPnP Get Item'
time waited: 0.001897 sec
wait id: 11
}

Chain 2 Signature: 'Disk file operations I/O'
Chain 2 Signature Hash: 0x1099d28b
-------------------------------------------------------------------------------

File_name :: /lhdb2_1_diag_115711.trc

 

Cause

Sign In with your My Oracle Support account

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

My Oracle Support provides customers with access to over a
Million Knowledge Articles and hundreds of Community platforms