Linux lockups inside bhyve VM on FreeBSD 11.1

[Kai Gallasch]

Hello.

Last day an apache 2.4 running inside a Debian9 linux bhyve VM locked up
on one of my servers (FreeBSD 11.1-RELENG, GENERIC kernel) overloading
the VM.

The VM uses a ZFS zvol blockdevice on top of a zpool, consisting of two
mirrored SSDs.

I was able to enter the VM through the bhyve console, kill and restart
the stuck apache process and regain stability inside the VM.

I found below output in the Linux dmesg and suspect the ext4 journaling
to be the culprit.

Has anyone experienced similar lockups running Linux inside a bhyve VM?
At the time when this happened there was no high I/O on the VM zpool.

Cheers,
K.


[1594985.015199] INFO: task jbd2/vda1-8:161 blocked for more than 120
seconds.
[1594985.015841]       Not tainted 4.9.0-4-amd64 #1 Debian 4.9.51-1
[1594985.016375] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[1594985.017074] jbd2/vda1-8     D    0   161      2 0x00000000
[1594985.017078]  ffff885477ec5400 0000000000000000 ffff88547620e280
ffff88547fc18240
[1594985.017080]  ffffffff8e00e500 ffffb056c0957ca0 ffffffff8da038e3
ffff8854765bd088
[1594985.017081]  0000000000000246 ffff88547fc18240 ffffb056c0957d80
ffff88547620e280
[1594985.017082] Call Trace:
[1594985.017116]  [<ffffffff8da038e3>] ? __schedule+0x233/0x6d0
[1594985.017131]  [<ffffffff8d4b8e80>] ? prepare_to_wait_event+0xf0/0xf0
[1594985.017132]  [<ffffffff8da03db2>] ? schedule+0x32/0x80
[1594985.017165]  [<ffffffffc03ae26f>] ?
jbd2_journal_commit_transaction+0x25f/0x17a0 [jbd2]
[1594985.017171]  [<ffffffff8d4abef1>] ? update_curr+0xe1/0x160
[1594985.017172]  [<ffffffff8d4aad04>] ? account_entity_dequeue+0xa4/0xc0
[1594985.017173]  [<ffffffff8d4b8e80>] ? prepare_to_wait_event+0xf0/0xf0
[1594985.017176]  [<ffffffffc03b3bc2>] ? kjournald2+0xc2/0x260 [jbd2]
[1594985.017177]  [<ffffffff8d4b8e80>] ? prepare_to_wait_event+0xf0/0xf0
[1594985.017180]  [<ffffffffc03b3b00>] ? commit_timeout+0x10/0x10 [jbd2]
[1594985.017186]  [<ffffffff8d47bb2a>] ? do_group_exit+0x3a/0xa0
[1594985.017191]  [<ffffffff8d496697>] ? kthread+0xd7/0xf0
[1594985.017192]  [<ffffffff8d4965c0>] ? kthread_park+0x60/0x60
[1594985.017198]  [<ffffffff8da08835>] ? ret_from_fork+0x25/0x30
[1594985.017202] INFO: task rs:main Q:Reg:407 blocked for more than 120
seconds.
[1594985.017841]       Not tainted 4.9.0-4-amd64 #1 Debian 4.9.51-1
[1594985.018373] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[1594985.019116] rs:main Q:Reg   D    0   407      1 0x00000000
[1594985.019118]  ffff885476928000 0000000000000000 ffff885479283140
ffff88547fc18240
[1594985.019119]  ffffffff8e00e500 ffffb056c0c1fb48 ffffffff8da038e3
2406f83c84b44b0f
[1594985.019121]  00ff8853c8784380 ffff88547fc18240 ffffb056c0c1fb68
ffff885479283140
[1594985.019122] Call Trace:
[1594985.019124]  [<ffffffff8da038e3>] ? __schedule+0x233/0x6d0
[1594985.019125]  [<ffffffff8da03db2>] ? schedule+0x32/0x80
[1594985.019129]  [<ffffffffc03ab086>] ?
wait_transaction_locked+0x86/0xc0 [jbd2]
[1594985.019130]  [<ffffffff8d4b8e80>] ?
prepare_to_wait_event+0xf[1599459.680158] serial8250: too much work for irq4
0/0xf0
[1594985.019132]  [<ffffffffc03ab2a8>] ?
add_transaction_credits+0x1b8/0x290 [jbd2]
[1594985.019142]  [<ffffffff8d424761>] ? __switch_to+0x2c1/0x6d0
[1594985.019145]  [<ffffffffc03ab4d5>] ? start_this_handle+0x105/0x400
[jbd2]
[1594985.019146]  [<ffffffff8da038eb>] ? __schedule+0x23b/0x6d0
[1594985.019147]  [<ffffffff8d4ac343>] ? check_preempt_wakeup+0x103/0x210
[1594985.019150]  [<ffffffffc03ab9f9>] ? jbd2__journal_start+0xd9/0x1e0
[jbd2]
[1594985.019238]  [<ffffffffc04560ad>] ? ext4_dirty_inode+0x2d/0x60 [ext4]
[1594985.019253]  [<ffffffff8d631705>] ? __mark_inode_dirty+0x165/0x350
[1594985.019258]  [<ffffffff8d61f059>] ? generic_update_time+0x79/0xd0
[1594985.019259]  [<ffffffff8d61f1b6>] ? current_time+0x36/0x70
[1594985.019260]  [<ffffffff8d61f2ac>] ? file_update_time+0xbc/0x110
[1594985.019271]  [<ffffffff8d57e609>] ?
__generic_file_write_iter+0x99/0x1b0
[1594985.019278]  [<ffffffffc0448180>] ? ext4_file_write_iter+0x90/0x370
[ext4]
[1594985.019288]  [<ffffffff8d4f86f9>] ? do_futex+0x2c9/0xb00
[1594985.019294]  [<ffffffff8d645cd1>] ? fsnotify+0x381/0x4e0
[1594985.019299]  [<ffffffff8d60254a>] ? new_sync_write+0xda/0x130
[1594985.019305]  [<ffffffff8d602cb0>] ? vfs_write+0xb0/0x190
[1594985.019307]  [<ffffffff8d6040a2>] ? SyS_write+0x52/0xc0
[1594985.019309]  [<ffffffff8da085bb>] ?
system_call_fast_compare_end+0xc/0x9b
[1594985.019344] INFO: task kworker/u8:2:19882 blocked for more than 120
seconds.
[1594985.019985]       Not tainted 4.9.0-4-amd64 #1 Debian 4.9.51-1
[1594985.020512] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[1594985.021215] kworker/u8:2    D    0 19882      2 0x00000000
[1594985.021220] Workqueue: writeback wb_workfn (flush-254:0)