Guest Freeze: NMI watchdog: BUG: soft lockup - CPU#1 stuck for 22s! [firefox:3744]

[Tzahi]

I searched a lot for a similar problem and could not find one. The problem occurs with both 5.1.12 or 5.0.30 and also earlier versions for a few months now. I tried ubuntu 16.04 64bit VM and also Debian machine 32 bit with jessie and now stretch. I recompiled the kernel, 4.8.15 same thing. I am using docker to run the firefox so that is an important information. The freeze occurs after a while using the firefox. I don't have an idea why it happens or in what situation. Sometimes it can run for a long time, sometimes not. It is sporadic.

The problem is:

[ 2843.332258] INFO: rcu_sched detected stalls on CPUs/tasks: [ 2843.332297] (detected by 1, t=5252 jiffies, g=51771, c=51770, q=53) [ 2843.332312] All QSes seen, last rcu_sched kthread activity 5252 (636131-630879), jiffies_till_next_fqs=1, root ->qsmask 0x0 [ 2843.332319] firefox R running 0 3744 3681 0x00000108 [ 2843.332333] f77ee840 bbe57543 eccc7d20 c40c6ad3 c466b848 c473de80 00001484 0009b4e3 [ 2843.332488] 0009a05f 00000001 00000000 00000296 c473dbc0 00000035 f6e82040 00000000 [ 2843.332673] 00000000 0000ca3b f6e82040 00000000 00000296 eccc7d30 c40cbff8 eccc7df8 [ 2843.332777] Call Trace: [ 2843.332826] [<c40c6ad3>] ? rcu_check_callbacks+0x763/0x780 [ 2843.332843] [<c40cbff8>] ? update_process_times+0x28/0x50 [ 2843.332853] [<c40dd716>] ? tick_sched_handle.isra.11+0x26/0x60 [ 2843.332861] [<c40dd78a>] ? tick_sched_timer+0x3a/0x80 [ 2843.332869] [<c40cca8f>] ? remove_hrtimer+0x3f/0x80 [ 2843.332878] [<c40cccbe>] ? hrtimer_run_queues+0xce/0x2a0 [ 2843.333021] [<c40dd750>] ? tick_sched_handle.isra.11+0x60/0x60 [ 2843.333058] [<c40511f0>] ? do_flush_tlb_all+0x40/0x40 [ 2843.333080] [<c40cd583>] ? hrtimer_interrupt+0x93/0x1a0 [ 2843.333089] [<c40511f0>] ? do_flush_tlb_all+0x40/0x40 [ 2843.333098] [<c40511f0>] ? do_flush_tlb_all+0x40/0x40 [ 2843.333113] [<c4576fc3>] ? smp_apic_timer_interrupt+0x33/0x50 [ 2843.333163] [<c45767b8>] ? apic_timer_interrupt+0x34/0x3c [ 2843.333175] [<c40511f0>] ? do_flush_tlb_all+0x40/0x40 [ 2843.333188] [<c40e00d8>] ? futex_wait+0x248/0x270 [ 2843.333241] [<c42f00e0>] ? copy_to_iter+0x40/0x320 [ 2843.333261] [<c40e27d2>] ? smp_call_function_single+0xc2/0x120 [ 2843.333273] [<c40511f0>] ? do_flush_tlb_all+0x40/0x40 [ 2843.333281] [<c40515a4>] ? native_flush_tlb_others+0x54/0x110 [ 2843.333290] [<c405175d>] ? flush_tlb_mm_range+0x5d/0x170 [ 2843.333302] [<c418febe>] ? vma_adjust+0x2be/0x720 [ 2843.333312] [<c419382f>] ? change_protection+0x53f/0x590 [ 2843.333321] [<c419394c>] ? mprotect_fixup+0xcc/0x230 [ 2843.333330] [<c4193be9>] ? SyS_mprotect+0x139/0x230 [ 2843.333407] [<c40019ae>] ? do_int80_syscall_32+0x5e/0xc0 [ 2843.333430] [<c4575d89>] ? entry_INT80_32+0x31/0x31 [ 2843.333442] rcu_sched kthread starved for 5252 jiffies! g51771 c51770 f0x2 RCU_GP_WAIT_FQS(3) ->state=0x100 [ 2843.333452] rcu_sched W c40a9136 0 7 2 0x00000000 [ 2843.333548] f5119540 c4864940 f511bea0 c40a9136 f77db000 d459d540 c471da80 007d4fc0 [ 2843.333757] f511bec4 f511c000 f77d4fc0 0009a060 f511bec4 c4571e5d f511beec f511bf2c [ 2843.333935] c4574d00 00000000 d4713180 f425aa80 00000000 ffffffff 00000000 f77d4fc0 [ 2843.334027] Call Trace: [ 2843.334039] [<c40a9136>] ? raw_callee_save_pv_queued_spin_unlock+0x6/0x10 [ 2843.334049] [<c4571e5d>] ? schedule+0x2d/0x80 [ 2843.334058] [<c4574d00>] ? schedule_timeout+0x190/0x350 [ 2843.334066] [<c40ca680>] ? del_timer_sync+0x50/0x50 [ 2843.334075] [<c40c5261>] ? rcu_gp_kthread+0x4a1/0x7c0 [ 2843.334115] [<c40c4dc0>] ? rcu_note_context_switch+0xf0/0xf0 [ 2843.334130] [<c4079266>] ? kthread+0xa6/0xc0 [ 2843.334140] [<c4575ca2>] ? ret_from_kernel_thread+0xe/0x24 [ 2843.334163] [<c40791c0>] ? kthread_create_on_node+0x130/0x130 [ 2870.838266] NMI watchdog: BUG: soft lockup - CPU#1 stuck for 22s! [firefox:3744] [ 2870.838296] Modules linked in: nfnetlink_queue(E) nfnetlink_log(E) nfnetlink(E) bluetooth(E) rfkill(E) xt_nat(E) xt_tcpudp(E) veth(E) netconsole(E) configfs(E) nls_utf8(E) isofs(E) udf(E) crc_itu_t(E) fuse(E) ipt_MASQUERADE(E) nf_nat_masquerade_ipv4(E) xfrm_user(E) xfrm_algo(E) iptable_nat(E) nf_conntrack_ipv4(E) nf_defrag_ipv4(E) nf_nat_ipv4(E) xt_addrtype(E) iptable_filter(E) xt_conntrack(E) nf_nat(E) nf_conntrack(E) br_netfilter(E) bridge(E) stp(E) llc(E) overlay(E) vboxsf(OE) joydev(E) crc32_pclmul(E) snd_intel8x0(E) snd_ac97_codec(E) snd_pcm(E) vboxvideo(OE) ttm(E) snd_timer(E) drm_kms_helper(E) drm(E) evdev(E) snd(E) soundcore(E) ac97_bus(E) vboxguest(OE) pcspkr(E) serio_raw(E) fb_sys_fops(E) syscopyarea(E) sysfillrect(E) sysimgblt(E) battery(E) video(E) button(E) ac(E) acpi_cpufreq(E) sg(E) tpm_tis(E) tpm_tis_core(E) tpm(E) sunrpc(E) parport_pc(E) ppdev(E) lp(E) parport(E) ip_tables(E) x_tables(E) autofs4(E) ext4(E) crc16(E) jbd2(E) crc32c_generic(E) fscrypto(E) ecb(E) mbcache(E) hid_generic(E) usbhid(E) hid(E) sr_mod(E) cdrom(E) sd_mod(E) ata_generic(E) virtio_net(E) crc32c_intel(E) aesni_intel(E) xts(E) ahci(E) aes_i586(E) libahci(E) lrw(E) gf128mul(E) ata_piix(E) ablk_helper(E) cryptd(E) ohci_pci(E) ehci_pci(E) psmouse(E) ohci_hcd(E) ehci_hcd(E) libata(E) e1000(E) i2c_piix4(E) usbcore(E) virtio_pci(E) virtio_ring(E) usb_common(E) virtio(E) scsi_mod(E) [ 2870.839974] CPU: 1 PID: 3744 Comm: firefox Tainted: G OE 4.8.15 #1 [ 2870.839983] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006 [ 2870.839991] task: f6e82040 task.stack: eccc6000 [ 2870.839999] EIP: 0060:[<c40e27d5>] EFLAGS: 00000202 CPU: 1 [ 2870.840009] EIP is at smp_call_function_single+0xc5/0x120 [ 2870.840017] EAX: 00000000 EBX: 00000000 ECX: 000008fb EDX: 00000003 [ 2870.840025] ESI: c40511f0 EDI: a4396000 EBP: eccc7e58 ESP: eccc7e34 [ 2870.840033] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 [ 2870.840065] CR0: 80050033 CR2: a5f4b000 CR3: 3503a000 CR4: 000406d0 [ 2870.840202] Stack: [ 2870.840213] eccc7e68 00000001 00000000 c40511f0 eccc7e68 00000003 bbe57543 d446c574 [ 2870.840345] a4396000 eccc7e84 c40515a4 00000001 d446c574 d446c400 a4395000 a4396000 [ 2870.840437] bbe57543 d446c574 d446c400 a4396000 eccc7eac c405175d a4396000 eccc7ee4 [ 2870.840511] Call Trace: [ 2870.840540] [<c40511f0>] ? do_flush_tlb_all+0x40/0x40 [ 2870.840549] [<c40515a4>] ? native_flush_tlb_others+0x54/0x110 [ 2870.840559] [<c405175d>] ? flush_tlb_mm_range+0x5d/0x170 [ 2870.840600] [<c418febe>] ? vma_adjust+0x2be/0x720 [ 2870.840616] [<c419382f>] ? change_protection+0x53f/0x590 [ 2870.840626] [<c419394c>] ? mprotect_fixup+0xcc/0x230 [ 2870.840636] [<c4193be9>] ? SyS_mprotect+0x139/0x230 [ 2870.840644] [<c40019ae>] ? do_int80_syscall_32+0x5e/0xc0 [ 2870.840693] [<c4575d89>] ? entry_INT80_32+0x31/0x31 [ 2870.840701] Code: 5d c3 8d 74 26 00 8d 55 e4 89 0c 24 89 d8 89 f1 e8 61 fe ff ff 8b 55 f0 83 e2 01 74 13 89 f6 8d bc 27 00 00 00 00 f3 90 8b 55 f0 <83> e2 01 75 f6 eb bd 8d 74 26 00 8b 15 30 65 88 c4 85 d2 0f 85 [ 2898.821699] NMI watchdog: BUG: soft lockup - CPU#1 stuck for 22s! [firefox:3744] [ 2898.821744] Modules linked in: nfnetlink_queue(E) nfnetlink_log(E) nfnetlink(E) bluetooth(E) rfkill(E) xt_nat(E) xt_tcpudp(E) veth(E) netconsole(E) configfs(E) nls_utf8(E) isofs(E) udf(E) crc_itu_t(E) fuse(E) ipt_MASQUERADE(E) nf_nat_masquerade_ipv4(E) xfrm_user(E) xfrm_algo(E) iptable_nat(E) nf_conntrack_ipv4(E) nf_defrag_ipv4(E) nf_nat_ipv4(E) xt_addrtype(E) iptable_filter(E) xt_conntrack(E) nf_nat(E) nf_conntrack(E) br_netfilter(E) bridge(E) stp(E) llc(E) overlay(E) vboxsf(OE) joydev(E) crc32_pclmul(E) snd_intel8x0(E) snd_ac97_codec(E) snd_pcm(E) vboxvideo(OE) ttm(E) snd_timer(E) drm_kms_helper(E) drm(E) evdev(E) snd(E) soundcore(E) ac97_bus(E) vboxguest(OE) pcspkr(E) serio_raw(E) fb_sys_fops(E) syscopyarea(E) sysfillrect(E) sysimgblt(E) battery(E) video(E) button(E) ac(E) acpi_cpufreq(E) sg(E) tpm_tis(E) tpm_tis_core(E) tpm(E) sunrpc(E) parport_pc(E) ppdev(E) lp(E) parport(E) ip_tables(E) x_tables(E) autofs4(E) ext4(E) crc16(E) jbd2(E) crc32c_generic(E) fscrypto(E) ecb(E) mbcache(E) hid_generic(E) usbhid(E) hid(E) sr_mod(E) cdrom(E) sd_mod(E) ata_generic(E) virtio_net(E) crc32c_intel(E) aesni_intel(E) xts(E) ahci(E) aes_i586(E) libahci(E) lrw(E) gf128mul(E) ata_piix(E) ablk_helper(E) cryptd(E) ohci_pci(E) ehci_pci(E) psmouse(E) ohci_hcd(E) ehci_hcd(E) libata(E) e1000(E) i2c_piix4(E) usbcore(E) virtio_pci(E) virtio_ring(E) usb_common(E) virtio(E) scsi_mod(E) [ 2898.823363] CPU: 1 PID: 3744 Comm: firefox Tainted: G OEL 4.8.15 #1 [ 2898.823372] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006 [ 2898.823380] task: f6e82040 task.stack: eccc6000 [ 2898.823388] EIP: 0060:[<c40e27d5>] EFLAGS: 00000202 CPU: 1 [ 2898.823397] EIP is at smp_call_function_single+0xc5/0x120 [ 2898.823405] EAX: 00000000 EBX: 00000000 ECX: 000008fb EDX: 00000003 [ 2898.823482] ESI: c40511f0 EDI: a4396000 EBP: eccc7e58 ESP: eccc7e34 [ 2898.823491] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 [ 2898.823499] CR0: 80050033 CR2: a5f4b000 CR3: 3503a000 CR4: 000406d0 [ 2898.823508] Stack: [ 2898.823515] eccc7e68 00000001 00000000 c40511f0 eccc7e68 00000003 bbe57543 d446c574 [ 2898.823614] a4396000 eccc7e84 c40515a4 00000001 d446c574 d446c400 a4395000 a4396000 [ 2898.823791] bbe57543 d446c574 d446c400 a4396000 eccc7eac c405175d a4396000 eccc7ee4 [ 2898.823877] Call Trace: [ 2898.823926] [<c40511f0>] ? do_flush_tlb_all+0x40/0x40 [ 2898.823939] [<c40515a4>] ? native_flush_tlb_others+0x54/0x110 [ 2898.823948] [<c405175d>] ? flush_tlb_mm_range+0x5d/0x170 [ 2898.823958] [<c418febe>] ? vma_adjust+0x2be/0x720 [ 2898.823968] [<c419382f>] ? change_protection+0x53f/0x590 [ 2898.823977] [<c419394c>] ? mprotect_fixup+0xcc/0x230 [ 2898.824104] [<c4193be9>] ? SyS_mprotect+0x139/0x230 [ 2898.824148] [<c40019ae>] ? do_int80_syscall_32+0x5e/0xc0 [ 2898.824171] [<c4575d89>] ? entry_INT80_32+0x31/0x31 [ 2898.824180] Code: 5d c3 8d 74 26 00 8d 55 e4 89 0c 24 89 d8 89 f1 e8 61 fe ff ff 8b 55 f0 83 e2 01 74 13 89 f6 8d bc 27 00 00 00 00 f3 90 8b 55 f0 <83> e2 01 75 f6 eb bd 8d 74 26 00 8b 15 30 65 88 c4 85 d2 0f 85

[Tzahi]

VBOX log from a debian stretch with a custom kernel

[Tzahi]

the output from the netconsole log. The cannot be seen by /var/log/messages