Troubleshooting ORA-00600 [ORA_NPI_ERROR] ORA-00600: internal error code [kffilCreate01]
Oracle 11.2.0.3 2nodes RAC on AIX, node1 DB instance crash and db alert log show “ORA-00600 [ORA_NPI_ERROR] ORA-00600: internal error code [kffilCreate01]” and “ORA-15064: communication failure with ASM instance” then Instance terminated by ASMB.
# db alert log
Fri May 22 04:16:23 2020 Use ADRCI or Support Workbench to package the incident. See Note 411.1 at My Oracle Support for error and packaging details. NOTE: ASMB terminating Errors in file /oracle/app/oracle/diag/rdbms/anbob/anbob1/trace/anbob1_asmb_40373526.trc: ORA-15064: communication failure with ASM instance ORA-00600: internal error code, arguments: [ORA_NPI_ERROR], [600], [ORA-00600: internal error code, arguments: [kffilCreate01], [anbob1:anbob], [], [], [], [], [], [], [], [], [], [] ], [], [], [], [], [], [], [], [], [] ASMB (ospid: 40373526): terminating the instance due to error 15064 Fri May 22 04:16:33 2020 Instance terminated by ASMB, pid = 40373526
# asm instance alert
2020-05-22 04:16:18.672000 +08:00 Errors in file /oracle/app/11.2.0.3/grid/log/diag/asm/+asm/+ASM1/trace/+ASM1_ora_27264968.trc (incident=312217): ORA-00600: internal error code, arguments: [kffilCreate01], [anbob1:anbob], [], [], [], [], [], [], [], [], [], [] Incident details in: /oracle/app/11.2.0.3/grid/log/diag/asm/+asm/+ASM1/incident/incdir_312217/+ASM1_ora_27264968_i312217.trc
# tracefile
dump file: /oracle/app/11.2.0.3/grid/log/diag/asm/+asm/+ASM1/incident/incdir_312217/+ASM1_ora_27264968_i312217.trc ORA-00600: internal error code, arguments: [kffilCreate01], [anbob1:anbob], [], [], [], [], [], [], [], [], [], [] *** 2020-05-22 04:16:33.782 ------------------------------------------------------------------------------- Trace Bucket Dump Begin: default bucket for process 27 (osid: 27264968) TIME(*=approx):SEQ:COMPONENT:FILE@LINE:FUNCTION:SECT/DUMP: [EVENT#:PID:SID] DATA ------------------------------------------------------------------------------- 2020-05-22 04:16:18.656615 :C88A0662:KFNS:kfn.c@741:kfnDispatch(): completed KFNOP=5 callcnt=-1077812999 2020-05-22 04:16:18.656714 :C88A0667:KFNS:kfn.c@710:kfnDispatch(): calling server stub for KFNOP=5 2020-05-22 04:16:18.656715 :C88A0668:KFNU:kfns.c@1727:kfnsBackground(): kfnsBackground consuming in-progress message typ=14 unread=1 status=0xfffffff1 2020-05-22 04:16:18.656716 :C88A0669:KFNU:kfns.c@1965:kfnsConsume(): kfnsConsume message 0x70000013d66d2f8 status=0xfffffff1 flags=0x1 2020-05-22 04:16:18.656722 :C88A066A:KFNU:kfn.c@5315:kfnmsg_Dump(): kfnsBg (kfnmsg) opcode=15 (KFNMS_MAPLOAD) fd 0x7000001177b7e08 mid 4294967291, gn [2.1165624170], fn [1147.963253597] exts 4480, sta rt 0, cnt 60 2020-05-22 04:16:18.656723 :C88A066B:KFNU:kfns.c@1786:kfnsBackground(): kfnsBackground got targeted message 2020-05-22 04:16:18.656726 :C88A066C:db_trace:kfns.c@5385:kfnsFillMapMsg(): [10491:27:838] MAP_LOAD: gn=2 fn=1147, mapid=-5 start=0 cnt=60 2020-05-22 04:16:18.656727 :C88A066D:KFNU:kfns.c@1942:kfnsBackground(): kfnsBackground completed in 0 seconds (KFNPM=2) 2020-05-22 04:16:18.656728 :C88A066E:KFNS:kfn.c@741:kfnDispatch(): completed KFNOP=5 callcnt=-1077812998 2020-05-22 04:16:18.656813 :C88A0673:KFNS:kfn.c@710:kfnDispatch(): calling server stub for KFNOP=5 2020-05-22 04:16:18.656814 :C88A0674:KFNU:kfns.c@1727:kfnsBackground(): kfnsBackground consuming in-progress message typ=15 unread=1 status=0xfffffff1 2020-05-22 04:16:18.656814 :C88A0675:KFNU:kfns.c@1965:kfnsConsume(): kfnsConsume message 0x70000011769cfa8 status=0xfffffff1 flags=0x1 2020-05-22 04:16:18.657300 :C88A06AA:KFNU:kfn.c@5366:kfnmsg_Dump(): kfnsBg (kfnmsg) op=25 (KFNMS_FILEUSE) (filuse) gn 2 un 0 mid 4294967292 cod 65535 ----- Call Stack Trace ----- calling call entry location type point -------------------- -------- -------------------- dbkePostKGE_kgsf()+ call dbgePostErrorKGE() 68 kgeadse()+380 call dbkePostKGE_kgsf() kgerinv_internal()+ call kgeadse() 48 kgerinv()+48 call kgerinv_internal() kgeasnmierr()+72 call kgerinv() kffilCreate()+540 call kgeasnmierr() kfnsUFG()+4036 call kffilCreate() kfnsBackground()+39 call kfnsUFG() 88 kfnDispatch()+1128 call kfnsBackground() opiodr()+720 call kfnDispatch() ttcpip()+1028 call opiodr() opitsk()+1508 call ttcpip() opiino()+940 call opitsk() opiodr()+720 call opiino() opidrv()+1132 call opiodr() sou2o()+136 call opidrv() opimai_real()+608 call sou2o() ssthrdmain()+268 call opimai_real() main()+204 call ssthrdmain() __start()+112 call main()
kffilCreate()+540 kernel automatic storage management file Create
kfnsUFG()+4036 kernel automatic storage management networking subsystem server networking [partial hit for: kfns ]
# grep -i mapid /oracle/app/11.2.0.3/grid/log/diag/asm/+asm/+ASM1/incident/incdir_312217/+ASM1_ora_27264968_i312217.trc
(kffil) netnm: , mapid:
(kffil) netnm: anbob1:anbob, mapid: 4294967295
(kffil) netnm: anbob1:anbob, mapid: 4294967294
(kffil) netnm: anbob1:anbob, mapid: 4294946774
(kffil) netnm: anbob1:anbob, mapid: 3849552408
(kffil) netnm: anbob1:anbob, mapid: 3562194217
(kffil) netnm: anbob1:anbob, mapid: 3487906158
(kffil) netnm: anbob1:anbob, mapid: 3230128050
(kffil) netnm: anbob1:anbob, mapid: 3185598356
(kffil) netnm: anbob1:anbob, mapid: 3128598163
(kffil) netnm: anbob1:anbob, mapid: 3080044389
(kffil) netnm: anbob1:anbob, mapid: 3078043616
(kffil) netnm: anbob1:anbob, mapid: 3044289890
(kffil) netnm: anbob1:anbob, mapid: 2866698183
(kffil) netnm: anbob1:anbob, mapid: 2764660939
(kffil) netnm: anbob1:anbob, mapid: 2603804616
(kffil) netnm: anbob1:anbob, mapid: 2412295670
(kffil) netnm: anbob1:anbob, mapid: 2367686953
(kffil) netnm: anbob1:anbob, mapid: 2358398223
(kffil) netnm: anbob1:anbob, mapid: 2358377032
(kffil) netnm: anbob1:anbob, mapid: 1469824483
(kffil) netnm: anbob1:anbob, mapid: 1029941947
(kffil) netnm: anbob1:anbob, mapid: 501493211
(kffil) netnm: anbob1:anbob, mapid: 501288479
(kffil) netnm: anbob1:anbob, mapid: 104836
(kffil) netnm: anbob1:anbob, mapid: 89301
(kffil) netnm: anbob1:anbob, mapid: 49316
(kffil) netnm: anbob1:anbob, mapid: 47922
(kffil) netnm: anbob1:anbob, mapid: 1067
(kffil) netnm: anbob1:anbob, mapid: 1066
(kffil) netnm: anbob1:anbob, mapid: 1065
(kffil) netnm: anbob1:anbob, mapid: 1064
(kffil) netnm: anbob1:anbob, mapid: 1062
(kffil) netnm: anbob1:anbob, mapid: 1061
...
...
(kffil) netnm: anbob1:anbob, mapid: 8
(kffil) netnm: anbob1:anbob, mapid: 7
(kffil) netnm: anbob1:anbob, mapid: 6
(kffil) netnm: anbob1:anbob, mapid: 5
(kffil) netnm: anbob1:anbob, mapid: 4
(kffil) netnm: anbob1:anbob, mapid: 3
(kffil) netnm: anbob1:anbob, mapid: 2
2020-05-22 04:16:18.656726 :C88A066C:db_trace:kfns.c@5385:kfnsFillMapMsg(): [10491:27:838] MAP_LOAD: gn=2 fn=1147, mapid=-5 start=0 cnt=60
2020-05-22 04:16:18.657439 :C88A06CD:db_trace:kfns.c@5310:kfnsFillMapMsg(): [10491:27:838] MAP_ALLOCATE: gn=2 fn=1135, mapid=-4 size=4480
2020-05-22 04:16:18.658157 :C88A079C:db_trace:kfns.c@5385:kfnsFillMapMsg(): [10491:27:838] MAP_LOAD: gn=2 fn=1135, mapid=-4 start=0 cnt=60
2020-05-22 04:16:18.658236 :C88A07BF:db_trace:kfns.c@5385:kfnsFillMapMsg(): [10491:27:838] MAP_LOAD: gn=2 fn=1147, mapid=-5 start=60 cnt=4420
[oracle@Xanbob1:/home/oracle>
----------------------------------------
SO: 0x7000001417a46a0, type: 4, owner: 0x7000001421bb628, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0x7000001421bb628, name=session, file=ksu.h LINE:12624 ID:, pg=0
(session) sid: 838 ser: 19 trans: 0x0, creator: 0x7000001421bb628
flags: (0x41) USR/- flags_idl: (0x1) BSY/-/-/-/-/-
flags2: (0x9) -/-/INC
DID: , short-term DID:
txn branch: 0x0
oct: 0, prv: 0, sql: 0x0, psql: 0x0, user: 0/SYS
ksuxds FALSE at location: 0
service name: SYS$USERS
client details:
O/S info: user: oracle, term: , ospid: 40373526
machine: Xanbob1 program: oracle@Xanbob1 (TNS V1-V3)
application name: oracle@Xanbob1 (TNS V1-V3), hash value=2834275364
Current Wait Stack:
1: waiting for 'ASM file metadata operation'
msgop=0x19, locn=0x2, =0x0
wait_id=3031433093 seq_num=59721 snap_id=1
wait times: snap=3.413248 sec, exc=3.413248 sec, total=3.413248 sec
wait times: max=infinite, heur=3.413248 sec
wait counts: calls=0 os=0
in_wait=1 iflags=0x520
----------------------------------------
SO: 0x70000012919e930, type: 130, owner: 0x7000001417a46a0, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0x7000001421bb628, name=ASM db client, file=kfn2.h LINE:1353 ID:, pg=0
(kfncl) netnm: anbob1:anbob, proc: 0x7000001421bb628, serial: 10
state: 0x1 type: 257 compat: 11020003 version: 11020003 hbeat: 1590092178 (3) asmb:
----------------------------------------
SO: 0x70000012a41f510, type: 125, owner: 0x70000012919e930, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0x7000001421bb628, name=KFG state obj, file=kfg2.h LINE:1178 ID:, pg=0
(kfgso) flags: 00000000 clt: 4 err: 0 hint: 29193b70
(kfgpn) rpi: 23 itrn:0 gst:0 usrp:0
busy: 0 rep: 0 grp: 0 check: 0/0 glink: 70000012a41f5d0 70000012a41f5d0
----------------------------------------
SO: 0x700000129193b70, type: 126, owner: 0x70000012a41f510, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0x7000001421bb628, name=KFG SO child, file=kfg2.h LINE:1181 ID:, pg=0
(kfgsc) pwr: 0 flag: 0 op: 0 recur: 0
(kfgpn) rpi: 3891 itrn:0 gst:0 usrp:0
----------------------------------------
SO: 0x7000001177b8c30, type: 132, owner: 0x700000129193b70, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0x7000001421bb628, name=ASM file, file=kff2.h LINE:855 ID:, pg=0
(kffil) netnm: anbob1:anbob, mapid: 4294967295
gnum: 2.1165624170, fnum: 1135.963253681, flgs: 0x182
family: 0.0, parent: 0.0
opennm: +DATADG/rzwb_redo12
openflags: 0x80000000
fullnm: +datadg/rzwb_redo12
redun: 0x11, fdflg: 0x0, blksiz: 512, fsiz: 9172993
ftype: 3, extsz: [4294967295,0,0]
extents: 4480, start: 60, count: 4420, xp: 0x0
base: 2754, lxcnt: 1
enq: 0x70000013b03deb0, cod: 0x0
unlock[0].au: 0, unlock[0].disk: 0, unlock[0].flags 0x0
SQL> @dec 4294967295
DEC HEX
----------------------------------- --------------------
4294967295.000000 FFFFFFFF
Note:
We can find the “MAPID” has reached the maximum value.
The mapid I think is a sequence number mapped to ASM FILE id in each process, and the same as the file handle number called in the program.Due to a bug, a larger span of the serial number jumps. Search in MOS, hit Bug 16357438.