My Oracle Support Banner

Oracle Linux: System Crashed with Many "oracleacfs" Functions in the Stack Trace (Doc ID 2615787.1)

Last updated on SEPTEMBER 21, 2021

Applies to:

Linux OS - Version Oracle Linux 6.7 with Unbreakable Enterprise Kernel [3.8.13] and later
Linux x86-64

Symptoms

One of six-RAC-cluster nodes suddenly crashed generating the following stack trace prior to the system reboot.

Nov 14 16:02:55 node2 kernel: BUG: scheduling while atomic: swapper/7/0/0x10000100
Nov 14 16:02:55 node2 kernel: Modules linked in: iptable_filter ip_tables tcp_diag inet_diag oracleacfs(POF) oracleadvm(POF) oracleoks(POF) oracleasm cpufreq_ondemand ipv6 dm_round_robin dm_multipath uinput iTCO_wdt iTCO_vendor_support cdc_ether usbnet mii be2net coretemp hwmon acpi_cpufreq freq_tabl e mperf intel_powerclamp kvm_intel kvm crc32c_intel ghash_clmulni_intel microcode pcspkr i2c_i801 i2c_core lpc_ich mfd_core ioatdma dca sg shpchp ext4 jbd2 mbcache sd_mod crc_t10dif qla2xxx scsi_transport_fc scsi_tgt mpt2sas scsi_transport_sas raid_class wmi aesni_intel ablk_helper cryptd lrw aes_x86_64 xts gf128mul dm_mirror dm_region_hash dm_log dm_mod
Nov 14 16:02:55 node2 kernel: Pid: 0, comm: swapper/7 Tainted: PF       W  O 3.8.13-68.3.4.el6uek.x86_64 #2
Nov 14 16:02:55 node2 kernel: Call Trace:
Nov 14 16:02:55 node2 kernel: <IRQ>  [<ffffffff810929a0>] __schedule_bug+0x50/0x60
Nov 14 16:02:55 node2 kernel: [<ffffffff815998d7>] __schedule+0x647/0x720
Nov 14 16:02:55 node2 kernel: [<ffffffff81096c1a>] __cond_resched+0x2a/0x40
Nov 14 16:02:55 node2 kernel: [<ffffffff81599a40>] _cond_resched+0x30/0x40
Nov 14 16:02:55 node2 kernel: [<ffffffff8159844e>] mutex_lock+0x1e/0x50
Nov 14 16:02:55 node2 kernel: [<ffffffffa0588b16>] ofs_fsync_1+0x46/0x70 [oracleacfs]
Nov 14 16:02:55 node2 kernel: [<ffffffff810848a7>] ? bit_waitqueue+0x17/0xd0
Nov 14 16:02:55 node2 kernel: [<ffffffff811c325e>] vfs_fsync_range+0x2e/0x30
Nov 14 16:02:55 node2 kernel: [<ffffffff811c32c1>] generic_write_sync+0x41/0x50
Nov 14 16:02:55 node2 kernel: [<ffffffff811ceb8b>] dio_complete+0x11b/0x140
Nov 14 16:02:55 node2 kernel: [<ffffffff811cec2a>] dio_bio_end_aio+0x7a/0x100
Nov 14 16:02:55 node2 kernel: [<ffffffff811c9fed>] bio_endio+0x1d/0x40
Nov 14 16:02:55 node2 kernel: [<ffffffffa0467d22>] asmVolIoDone+0x16e/0x198 [oracleadvm]
Nov 14 16:02:55 node2 kernel: [<ffffffffa04571cd>] Asm_completeIo+0x316/0x31b [oracleadvm]
Nov 14 16:02:55 node2 kernel: [<ffffffffa0457bc9>] AsmVolIoDone+0x691/0x72f [oracleadvm]
Nov 14 16:02:55 node2 kernel: [<ffffffffa0468421>] asmEndIo_1+0x12e/0x13d [oracleadvm]
Nov 14 16:02:55 node2 kernel: [<ffffffffa0468463>] asmEndIo_2+0x33/0x35 [oracleadvm]
Nov 14 16:02:55 node2 kernel: [<ffffffff811c9fed>] bio_endio+0x1d/0x40
Nov 14 16:02:55 node2 kernel: [<ffffffffa0003273>] dec_pending+0x173/0x2b0 [dm_mod]
Nov 14 16:02:55 node2 kernel: [<ffffffffa0003a36>] clone_endio+0x76/0xa0 [dm_mod]
Nov 14 16:02:55 node2 kernel: [<ffffffff811c9fed>] bio_endio+0x1d/0x40
Nov 14 16:02:55 node2 kernel: [<ffffffff812669c3>] req_bio_endio+0xa3/0xe0
Nov 14 16:02:55 node2 kernel: [<ffffffff812680ff>] blk_update_request+0x10f/0x4b0
Nov 14 16:02:55 node2 kernel: [<ffffffff81132fb7>] ? mempool_free_slab+0x17/0x20
Nov 14 16:02:55 node2 kernel: [<ffffffffa0001b6a>] end_clone_bio+0x5a/0x90 [dm_mod]
Nov 14 16:02:55 node2 kernel: [<ffffffff811c9fed>] bio_endio+0x1d/0x40
Nov 14 16:02:55 node2 kernel: [<ffffffff812669c3>] req_bio_endio+0xa3/0xe0
Nov 14 16:02:55 node2 kernel: [<ffffffff812680ff>] blk_update_request+0x10f/0x4b0
Nov 14 16:02:55 node2 kernel: [<ffffffff812684c7>] blk_update_bidi_request+0x27/0xb0
Nov 14 16:02:55 node2 kernel: [<ffffffff8126970f>] blk_end_bidi_request+0x2f/0x80
Nov 14 16:02:55 node2 kernel: [<ffffffff812697b0>] blk_end_request+0x10/0x20
Nov 14 16:02:55 node2 kernel: [<ffffffff813cc830>] scsi_end_request+0x40/0xb0
Nov 14 16:02:55 node2 kernel: [<ffffffff813ccbaf>] scsi_io_completion+0x9f/0x6a0
Nov 14 16:02:55 node2 kernel: [<ffffffff810480a9>] ? default_spin_lock_flags+0x9/0x10
Nov 14 16:02:55 node2 kernel: [<ffffffff813c3f59>] scsi_finish_command+0xc9/0x130
Nov 14 16:02:55 node2 kernel: [<ffffffff813cd317>] scsi_softirq_done+0x147/0x170
Nov 14 16:02:55 node2 kernel: [<ffffffff8126fca2>] blk_done_softirq+0x82/0xa0
Nov 14 16:02:55 node2 kernel: [<ffffffff81067407>] __do_softirq+0xd7/0x240
Nov 14 16:02:55 node2 kernel: [<ffffffff810b91b4>] ? clockevents_program_event+0x74/0x120
Nov 14 16:02:55 node2 kernel: [<ffffffff81088fde>] ? hrtimer_interrupt+0x13e/0x240
Nov 14 16:02:55 node2 kernel: [<ffffffff815a4c1c>] call_softirq+0x1c/0x30
Nov 14 16:02:55 node2 kernel: [<ffffffff81017415>] do_softirq+0x65/0xa0
Nov 14 16:02:55 node2 kernel: [<ffffffff810671ed>] irq_exit+0xbd/0xe0
Nov 14 16:02:55 node2 kernel: [<ffffffff815a59be>] smp_apic_timer_interrupt+0x6e/0x99
Nov 14 16:02:55 node2 kernel: [<ffffffff815a44dd>] apic_timer_interrupt+0x6d/0x80
Nov 14 16:02:55 node2 kernel: <EOI>  [<ffffffff81089472>] ? __hrtimer_start_range_ns+0x172/0x410
Nov 14 16:02:55 node2 kernel: [<ffffffff81477140>] ? cpuidle_wrap_enter+0x50/0x90
Nov 14 16:02:55 node2 kernel: [<ffffffff81477139>] ? cpuidle_wrap_enter+0x49/0x90
Nov 14 16:02:55 node2 kernel: [<ffffffff810bb760>] ? tick_nohz_stop_sched_tick+0x280/0x2d0
Nov 14 16:02:55 node2 kernel: [<ffffffff8147882e>] ? menu_select+0x28e/0x410
Nov 14 16:02:55 node2 kernel: [<ffffffff81477190>] cpuidle_enter_tk+0x10/0x20
Nov 14 16:02:55 node2 kernel: [<ffffffff81476b97>] cpuidle_enter_state+0x17/0x50
Nov 14 16:02:55 node2 kernel: [<ffffffff814773da>] cpuidle_idle_call+0xaa/0x110
Nov 14 16:02:55 node2 kernel: [<ffffffff8101dc3f>] cpu_idle+0xcf/0x120
Nov 14 16:02:55 node2 kernel: [<ffffffff8159022c>] start_secondary+0xc8/0xca
Nov 14 16:12:22 node2 kernel: imklog 5.8.10, log source = /proc/kmsg started.
Nov 14 16:12:22 node2 rsyslogd: [origin software="rsyslogd" swVersion="5.8.10" x-pid="17682" x-info="http://www.rsyslog.com"] start
Nov 14 16:12:22 node2 kernel: Initializing cgroup subsys cpuset
Nov 14 16:12:22 node2 kernel: Initializing cgroup subsys cpu
Nov 14 16:12:22 node2 kernel: Linux version 3.8.13-68.3.4.el6uek.x86_64 (mockbuild@x86-ol6-builder-06) (gcc version 4.4.7 20120313 (Red Hat 4.4.7-3) (GCC) ) #2 SMP Tue Jul 14 15:03:36 PDT 2015
Nov 14 16:12:22 node2 kernel: Command line: ro root=/dev/mapper/vg00-root rd_NO_LUKS rd_LVM_LV=vg00/swap LANG=en_US.UTF-8 rd_LVM_LV=vg00/root crashkernel=128M nomodeset rd_NO_MD SYSFONT=latarcyrheb-sun16  KEYBOARDTYPE=pc KEYTABLE=us rd_NO_DM quiet numa=off transparent_hugepage=never
 

The rest of the nodes shows when the affected node has been removed of the cluster due to the crash on /var/log/messages logs:

Nov 14 16:05:08 node1 kernel: [Oracle OKS] Cluster Membership change - Current  incarn 0x19
Nov 14 16:05:08 node1 kernel: [Oracle OKS] Nodes in cluster:
Nov 14 16:05:08 node1 kernel: [Oracle OKS]   Node 1 (IP xxxxxxxx) Node 3 (IP xxxxxxxx) [Oracle OKS]
Nov 14 16:05:08 node1 kernel:    Node 4 (IP xxxxxxxx) Node 5 (IP xxxxxxxx) Node 6 (IP xxxxxxxx) [Oracle OKS]
Nov 14 16:05:08 node1 kernel:
Nov 14 16:05:08 node1 kernel: [Oracle OKS] Node count 5, Local node number 1
Nov 14 16:05:08 node1 kernel: ADVMK-00013: Cluster reconfiguration started.
Nov 14 16:05:23 node1 kernel: ADVMK-00014: Cluster reconfiguration completed.
Nov 14 16:05:23 node1 kernel: ADVMK-00014: Cluster reconfiguration completed.
Nov 14 16:18:51 node1 kernel: [Oracle OKS] Cluster Membership change - Current  incarn 0x1c
Nov 14 16:18:51 node1 kernel: [Oracle OKS] Nodes in cluster:
Nov 14 16:18:51 node1 kernel: [Oracle OKS]   Node 1 (IP xxxxxxxx) Node 2 (IP 0xa9fe1393) Node 3 (IP xxxxxxxx) [Oracle OKS]
Nov 14 16:18:51 node1 kernel:    Node 4 (IP xxxxxxxx) Node 5 (IP xxxxxxxx) Node 6 (IP xxxxxxxx) [Oracle OKS]
Nov 14 16:18:51 node1 kernel:
Nov 14 16:18:51 node1 kernel: [Oracle OKS] Node count 6, Local node number 1
Nov 14 16:18:51 node1 kernel: ADVMK-00013: Cluster reconfiguration started.
Nov 14 16:18:56 node1 kernel: ADVMK-00014: Cluster reconfiguration completed.
Nov 14 16:18:56 node1 kernel: ADVMK-00014: Cluster reconfiguration completed.


Nov 14 16:05:08 node3 kernel: [Oracle OKS] Cluster Membership change - Current  incarn 0x19
Nov 14 16:05:08 node3 kernel: [Oracle OKS] Nodes in cluster:
Nov 14 16:05:08 node3 kernel: [Oracle OKS]   Node 1 (IP xxxxxxxx) Node 3 (IP xxxxxxxx) [Oracle OKS]
Nov 14 16:05:08 node3 kernel:    Node 4 (IP xxxxxxxx) Node 5 (IP xxxxxxxx) Node 6 (IP xxxxxxxx) [Oracle OKS]
Nov 14 16:05:08 node3 kernel:
Nov 14 16:05:08 node3 kernel: [Oracle OKS] Node count 5, Local node number 3
Nov 14 16:05:08 node3 kernel: ADVMK-00013: Cluster reconfiguration started.
Nov 14 16:05:23 node3 kernel: ADVMK-00014: Cluster reconfiguration completed.
Nov 14 16:05:23 node3 kernel: ADVMK-00014: Cluster reconfiguration completed.
Nov 14 16:05:23 node3 kernel: OKSK-00009: Cluster Membership change setup complete.
Nov 14 16:18:51 node3 kernel: [Oracle OKS] Cluster Membership change - Current  incarn 0x1c
Nov 14 16:18:51 node3 kernel: [Oracle OKS] Nodes in cluster:
Nov 14 16:18:51 node3 kernel: [Oracle OKS]   Node 1 (IP xxxxxxxx) Node 2 (IP 0xa9fe1393) Node 3 (IP xxxxxxxx) [Oracle OKS]
Nov 14 16:18:51 node3 kernel:    Node 4 (IP xxxxxxxx) Node 5 (IP xxxxxxxx) Node 6 (IP xxxxxxxx) [Oracle OKS]
Nov 14 16:18:51 node3 kernel:
Nov 14 16:18:51 node3 kernel: [Oracle OKS] Node count 6, Local node number 3
Nov 14 16:18:51 node3 kernel: ADVMK-00013: Cluster reconfiguration started.
Nov 14 16:18:56 node3 kernel: ADVMK-00014: Cluster reconfiguration completed.
Nov 14 16:18:56 node3 kernel: ADVMK-00014: Cluster reconfiguration completed.
Nov 14 16:18:56 node3 kernel: OKSK-00009: Cluster Membership change setup complete.


Nov 14 16:05:08 node4 kernel: [Oracle OKS] Cluster Membership change - Current  incarn 0x19
Nov 14 16:05:08 node4 kernel: [Oracle OKS] Nodes in cluster:
Nov 14 16:05:08 node4 kernel: [Oracle OKS]   Node 1 (IP xxxxxxxx) Node 3 (IP xxxxxxxx) [Oracle OKS]
Nov 14 16:05:08 node4 kernel:    Node 4 (IP xxxxxxxx) Node 5 (IP xxxxxxxx) Node 6 (IP xxxxxxxx) [Oracle OKS]
Nov 14 16:05:08 node4 kernel:
Nov 14 16:05:08 node4 kernel: [Oracle OKS] Node count 5, Local node number 4
Nov 14 16:05:08 node4 kernel: ADVMK-00013: Cluster reconfiguration started.
Nov 14 16:05:23 node4 kernel: ADVMK-00014: Cluster reconfiguration completed.
Nov 14 16:05:23 node4 kernel: ADVMK-00014: Cluster reconfiguration completed.


Nov 14 16:05:08 node5 kernel: [Oracle OKS] Cluster Membership change - Current  incarn 0x19
Nov 14 16:05:08 node5 kernel: [Oracle OKS] Nodes in cluster:
Nov 14 16:05:08 node5 kernel: [Oracle OKS]   Node 1 (IP xxxxxxxx) Node 3 (IP xxxxxxxx) [Oracle OKS]
Nov 14 16:05:08 node5 kernel:    Node 4 (IP xxxxxxxx) Node 5 (IP xxxxxxxx) Node 6 (IP xxxxxxxx) [Oracle OKS]
Nov 14 16:05:08 node5 kernel:
Nov 14 16:05:08 node5 kernel: [Oracle OKS] Node count 5, Local node number 5
Nov 14 16:05:08 node5 kernel: ADVMK-00013: Cluster reconfiguration started.
Nov 14 16:05:23 node5 kernel: ADVMK-00014: Cluster reconfiguration completed.
Nov 14 16:05:23 node5 kernel: ADVMK-00014: Cluster reconfiguration completed.


Nov 14 16:05:08 node6 kernel: [Oracle OKS] Cluster Membership change - Current  incarn 0x19
Nov 14 16:05:08 node6 kernel: [Oracle OKS] Nodes in cluster:
Nov 14 16:05:08 node6 kernel: [Oracle OKS]   Node 1 (IP xxxxxxxx) Node 3 (IP xxxxxxxx) [Oracle OKS]
Nov 14 16:05:08 node6 kernel:    Node 4 (IP xxxxxxxx) Node 5 (IP xxxxxxxx) Node 6 (IP xxxxxxxx) [Oracle OKS]
Nov 14 16:05:08 node6 kernel:
Nov 14 16:05:08 node6 kernel: [Oracle OKS] Node count 5, Local node number 6
Nov 14 16:05:08 node6 kernel: ADVMK-00013: Cluster reconfiguration started.
Nov 14 16:05:23 node6 kernel: ADVMK-00014: Cluster reconfiguration completed.
Nov 14 16:05:23 node6 kernel: ADVMK-00014: Cluster reconfiguration completed.
 
NOTE: In above example the affected node is represented with name "node2"
 

Changes

 No changes were made to the system.

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
References


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