Persistent Crashes in Multiple VMs

brando56894 · 2016-12-07 05:23:05

Hopefully you guys can help us out with this one: I've been testing out FreeNAS 10 nightlies (it'll be released in about 2.5 months) and I currently have 3 Arch VMs running under bhyve (FreeNAS is FreeBSD 10 in case you didn't know) and they all work well up to a point. I've seen multiple "hangs" in dmesg where the CPU timer or whatever hangs and causes things like systemd-journald to crash. Each VM runs something different but the crashes/hang even happen when the VMs are under light load.

Here are multiple crash dumps from the 3 VMs: https://drive.google.com/file/d/0B5ma-a … sp=sharing

Here's an example of one of them

Mon Dec  5 16:49:06 2016] Key type dns_resolver registered
[Mon Dec  5 16:49:06 2016] NFS: Registering the id_resolver key type
[Mon Dec  5 16:49:06 2016] Key type id_resolver registered
[Mon Dec  5 16:49:06 2016] Key type id_legacy registered
[Mon Dec  5 17:56:38 2016] INFO: rcu_preempt detected stalls on CPUs/tasks:
[Mon Dec  5 17:56:38 2016]      2-...: (0 ticks this GP) idle=638/0/0 softirq=12167/12167 fqs=0
[Mon Dec  5 17:56:38 2016]      (detected by 3, t=18002 jiffies, g=9636, c=9635, q=273)
[Mon Dec  5 17:56:38 2016] Task dump for CPU 2:
[Mon Dec  5 17:56:38 2016] swapper/2       R  running task        0     0      1 0x00000000
[Mon Dec  5 17:56:38 2016]  ffffffff810ac1b0 ffff88013a407eb8 ffffffff810fc861 ffffffff81c58aa0
[Mon Dec  5 17:56:38 2016]  0000000000000001 0000000000000000 ffff88013a407ea8 ffffffff81037c50
[Mon Dec  5 17:56:38 2016]  ffff88013a408000 0000000000000000 ffffffff81afcdd0 ffff88013a407eb8
[Mon Dec  5 17:56:38 2016] Call Trace:
[Mon Dec  5 17:56:38 2016]  [<ffffffff810ac1b0>] ? sched_clock_idle_sleep_event+0x10/0x20
[Mon Dec  5 17:56:38 2016]  [<ffffffff810fc861>] ? __tick_nohz_idle_enter+0x111/0x400
[Mon Dec  5 17:56:38 2016]  [<ffffffff81037c50>] ? default_idle+0x20/0x110
[Mon Dec  5 17:56:38 2016]  [<ffffffff8103841f>] ? arch_cpu_idle+0xf/0x20
[Mon Dec  5 17:56:38 2016]  [<ffffffff810c0aea>] ? default_idle_call+0x2a/0x40
[Mon Dec  5 17:56:38 2016]  [<ffffffff810c0e11>] ? cpu_startup_entry+0x311/0x380
[Mon Dec  5 17:56:38 2016]  [<ffffffff81050e78>] ? start_secondary+0x158/0x1a0
[Mon Dec  5 17:56:38 2016] rcu_preempt kthread starved for 18002 jiffies! g9636 c9635 f0x0 RCU_GP_WAIT_FQS(3) ->stat[Mon Dec  5 17:56:38 2016] rcu_preempt     S ffff88013abe3d78     0     7      2 0x00000000
[Mon Dec  5 17:56:38 2016]  ffff88013abe3d78 00ff88013ab84740 ffff88013abee3c0 ffff88013ab84740
[Mon Dec  5 17:56:38 2016]  ffff88013abe3dc0 ffff88013abe4000 ffff88013abe3dc0 ffff88013fd0fc40
[Mon Dec  5 17:56:38 2016]  0000000000000000 0000000000000000 ffff88013abe3d90 ffffffff815f40dc
[Mon Dec  5 17:56:38 2016] Call Trace:
[Mon Dec  5 17:56:38 2016]  [<ffffffff815f40dc>] schedule+0x3c/0x90
[Mon Dec  5 17:56:38 2016]  [<ffffffff815f6f48>] schedule_timeout+0x1f8/0x3d0
[Mon Dec  5 17:56:38 2016]  [<ffffffff810a3277>] ? finish_task_switch+0x77/0x1e0
[Mon Dec  5 17:56:38 2016]  [<ffffffff810eb630>] ? del_timer_sync+0x50/0x50
[Mon Dec  5 17:56:38 2016]  [<ffffffff810e5e6f>] rcu_gp_kthread+0x5ef/0x910
[Mon Dec  5 17:56:38 2016]  [<ffffffff810e5880>] ? rcu_process_callbacks+0x600/0x600
[Mon Dec  5 17:56:38 2016]  [<ffffffff8109be38>] kthread+0xd8/0xf0
[Mon Dec  5 17:56:38 2016]  [<ffffffff8102c782>] ? __switch_to+0x2d2/0x630
[Mon Dec  5 17:56:38 2016]  [<ffffffff815f81ff>] ret_from_fork+0x1f/0x40
[Mon Dec  5 17:56:38 2016]  [<ffffffff8109bd60>] ? kthread_worker_fn+0x170/0x170

and another

[Tue Dec  6 16:06:08 2016] Key type id_legacy registered
[Tue Dec  6 16:37:01 2016] systemd[1]: systemd-journald.service: State 'stop-sigabrt' timed out. Terminating.
[Tue Dec  6 16:38:32 2016] systemd[1]: systemd-journald.service: State 'stop-sigterm' timed out. Killing.
[Tue Dec  6 16:38:32 2016] systemd[1]: systemd-journald.service: Killing process 158 (systemd-journal) with signal SIGKILL.
[Tue Dec  6 16:40:02 2016] systemd[1]: systemd-journald.service: Processes still around after SIGKILL. Ignoring.
[Tue Dec  6 16:41:32 2016] systemd[1]: systemd-journald.service: State 'stop-final-sigterm' timed out. Killing.
[Tue Dec  6 16:41:32 2016] systemd[1]: systemd-journald.service: Killing process 158 (systemd-journal) with signal SIGKILL.
[Tue Dec  6 16:43:02 2016] systemd[1]: systemd-journald.service: Processes still around after final SIGKILL. Entering failed mode.
[Tue Dec  6 16:43:02 2016] systemd[1]: systemd-journald.service: Unit entered failed state.
[Tue Dec  6 16:43:02 2016] systemd[1]: systemd-journald.service: Failed with result 'watchdog'.
[Tue Dec  6 16:43:02 2016] systemd[1]: systemd-journald.service: Service has no hold-off time, scheduling restart.
[Tue Dec  6 16:43:02 2016] systemd[1]: Stopped Flush Journal to Persistent Storage.
[Tue Dec  6 16:43:02 2016] systemd[1]: Stopping Flush Journal to Persistent Storage...
[Tue Dec  6 16:43:02 2016] systemd[1]: Stopped Journal Service.
[Tue Dec  6 16:43:02 2016] systemd[1]: Starting Journal Service...
[Tue Dec  6 16:43:02 2016] clocksource: timekeeping watchdog on CPU1: Marking clocksource 'tsc' as unstable because the skew is too large:
[Tue Dec  6 16:43:02 2016] clocksource:                       'hpet' wd_now: 54567b7c wd_last: 4062ac mask: ffffffff
[Tue Dec  6 16:43:02 2016] clocksource:                       'tsc' cs_now: 292e01bbbdc8a cs_last: 291d6b8e89b43 mask: ffffffffffffffff
[Tue Dec  6 16:43:03 2016] clocksource: Switched to clocksource hpet
[Tue Dec  6 16:43:03 2016] systemd[1]: Started Journal Service.

While researching this I found this thread over at kernel.org which is all about the hangs and has been going on for about a year or so: https://bugzilla.kernel.org/show_bug.cgi?id=109051 interestingly enough there are a lot of Arch users reporting the issue and a small amount of other distro users. I tried adding the max_cstate = 1 kernel parameter as mentioned in the thread but that didn't help at all.

All my VMs are running 4.8.11-1-Arch and are up to date as of like 2 or 3 days ago. The CTO (Jordan) over at IX Systems (makers of FreeNAS) said he's been beating one of his systems with a bunch of Arch VMs and huge computational workloads and not a single one has crashed in hours, when it usually happens within the first hour for me. Funny thing is that when whatever it is crashes it doesn't bring everything down, things just screw up for a second and all is well. One VM is an Emby Media server and when that hangs/crashes it just causes the media to stop playing then the stream quits, once I hit play again all is well up until the next hang. His CPU is a Xeon E5-2620 and mine is a Xeon D 1540.

Jordan also recommended that I give this a try on an Ubuntu VM, so I have a 16.04 server install running which is currently scanning in my massive media library into Emby and I haven't seen a similar hiccup in about two hours or so. I was also running Arch with ZFS on Linux for about 6 months a few months ago on this same hardware and I don't remember any such issues.

Any ideas?

mich41 · 2016-12-07 10:50:13

[Tue Dec  6 16:43:02 2016] clocksource: timekeeping watchdog on CPU1: Marking clocksource 'tsc' as unstable because the skew is too large:
[Tue Dec  6 16:43:02 2016] clocksource:                       'hpet' wd_now: 54567b7c wd_last: 4062ac mask: ffffffff
[Tue Dec  6 16:43:02 2016] clocksource:                       'tsc' cs_now: 292e01bbbdc8a cs_last: 291d6b8e89b43 mask: ffffffffffffffff

No harm in trying clocksource=hpet or hpet=disable I guess

ewaller · 2016-12-07 15:34:31

One very generic suggestion. Have you installed and configured your processor's microcode updates?

brando56894 · 2016-12-07 17:10:06

I did see that mentioned in the bugs and people saying it doesn't really help. Would that really even matter since these CPUs are emulated?

mich41 wrote:

[Tue Dec  6 16:43:02 2016] clocksource: timekeeping watchdog on CPU1: Marking clocksource 'tsc' as unstable because the skew is too large:
[Tue Dec  6 16:43:02 2016] clocksource:                       'hpet' wd_now: 54567b7c wd_last: 4062ac mask: ffffffff
[Tue Dec  6 16:43:02 2016] clocksource:                       'tsc' cs_now: 292e01bbbdc8a cs_last: 291d6b8e89b43 mask: ffffffffffffffff

No harm in trying clocksource=hpet or hpet=disable I guess

I'll give that a try, can't hurt haha

ewaller · 2016-12-07 17:22:05

They are not emulated. The machines and their peripherals are emulated, but the code runs on a real core. (Hyper Visor / VM)
Now, if you were looking at running code for, say an Apple II, then you would be emulating a 6502.
http://stackoverflow.com/questions/6234 … al-machine

I did see that mentioned in the bugs and people saying it doesn't really help

It never hurts

Last edited by ewaller (2016-12-07 17:54:15)

brando56894 · 2016-12-07 17:43:54

Ah thanks for the quick explanation, I know you can emulate other X86 processors in things like libvirt and ESXi but I wasn't sure if that is what is happening in my case, I guess it's just using host-passthrough. I believe I did apply it once upon, but I'll give it a try again just for the hell of it.

brando56894 · 2016-12-07 20:33:39

It looks like there aren't any microcode updates for my CPU

 [root@emby ~]# dmesg -HT|grep microcode
[Wed Dec  7 15:27:13 2016] microcode: sig=0x50662, pf=0x1, revision=0x0
[Wed Dec  7 15:27:13 2016] microcode: Microcode Update Driver: v2.01 <tigran@aivazian.fsnet.co.uk>, Peter Oruba

It does seem that setting clocksource=hpet has completely stopped the crashes. I'm running the system now without it just to make sure.

brando56894 · 2016-12-07 23:27:32

And just like that, they're gone.... I tweaked some things in one VM that seemed to stop the crashes, but once I reverted them it also no longer crashed. None of them did! I updated FreeNAS earlier, then I upgraded all 3 Arch VMs an hour or three after that. Since then they've all been fine....

Arch Linux

#1 2016-12-07 05:23:05

Persistent Crashes in Multiple VMs

#2 2016-12-07 10:50:13

Re: Persistent Crashes in Multiple VMs

#3 2016-12-07 15:34:31

Re: Persistent Crashes in Multiple VMs

#4 2016-12-07 17:10:06

Re: Persistent Crashes in Multiple VMs

#5 2016-12-07 17:22:05

Re: Persistent Crashes in Multiple VMs

#6 2016-12-07 17:43:54

Re: Persistent Crashes in Multiple VMs

#7 2016-12-07 20:33:39

Re: Persistent Crashes in Multiple VMs

#8 2016-12-07 23:27:32

Re: Persistent Crashes in Multiple VMs

Board footer