From owner-freebsd-virtualization@freebsd.org Thu Nov 30 21:29:39 2017 Return-Path: Delivered-To: freebsd-virtualization@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 668D9DBB529 for ; Thu, 30 Nov 2017 21:29:39 +0000 (UTC) (envelope-from k@free.de) Received: from smtp.free.de (smtp.free.de [91.204.6.103]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 131FF76D9A for ; Thu, 30 Nov 2017 21:29:38 +0000 (UTC) (envelope-from k@free.de) Received: from [127.0.0.1] (localhost [127.0.0.1]) by smtp.free.de (Postfix) with ESMTPSA id 1953D153FC for ; Thu, 30 Nov 2017 22:29:36 +0100 (CET) From: Kai Gallasch To: freebsd-virtualization@freebsd.org Subject: Linux lockups inside bhyve VM on FreeBSD 11.1 Message-ID: <5b1166b2-0b8c-248c-9a3b-b5c9685e4f37@free.de> Date: Thu, 30 Nov 2017 22:29:35 +0100 Mime-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Language: en-US Content-Transfer-Encoding: 7bit X-BeenThere: freebsd-virtualization@freebsd.org X-Mailman-Version: 2.1.25 Precedence: list List-Id: "Discussion of various virtualization techniques FreeBSD supports." List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 30 Nov 2017 21:29:39 -0000 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] [] ? __schedule+0x233/0x6d0 [1594985.017131] [] ? prepare_to_wait_event+0xf0/0xf0 [1594985.017132] [] ? schedule+0x32/0x80 [1594985.017165] [] ? jbd2_journal_commit_transaction+0x25f/0x17a0 [jbd2] [1594985.017171] [] ? update_curr+0xe1/0x160 [1594985.017172] [] ? account_entity_dequeue+0xa4/0xc0 [1594985.017173] [] ? prepare_to_wait_event+0xf0/0xf0 [1594985.017176] [] ? kjournald2+0xc2/0x260 [jbd2] [1594985.017177] [] ? prepare_to_wait_event+0xf0/0xf0 [1594985.017180] [] ? commit_timeout+0x10/0x10 [jbd2] [1594985.017186] [] ? do_group_exit+0x3a/0xa0 [1594985.017191] [] ? kthread+0xd7/0xf0 [1594985.017192] [] ? kthread_park+0x60/0x60 [1594985.017198] [] ? 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] [] ? __schedule+0x233/0x6d0 [1594985.019125] [] ? schedule+0x32/0x80 [1594985.019129] [] ? wait_transaction_locked+0x86/0xc0 [jbd2] [1594985.019130] [] ? prepare_to_wait_event+0xf[1599459.680158] serial8250: too much work for irq4 0/0xf0 [1594985.019132] [] ? add_transaction_credits+0x1b8/0x290 [jbd2] [1594985.019142] [] ? __switch_to+0x2c1/0x6d0 [1594985.019145] [] ? start_this_handle+0x105/0x400 [jbd2] [1594985.019146] [] ? __schedule+0x23b/0x6d0 [1594985.019147] [] ? check_preempt_wakeup+0x103/0x210 [1594985.019150] [] ? jbd2__journal_start+0xd9/0x1e0 [jbd2] [1594985.019238] [] ? ext4_dirty_inode+0x2d/0x60 [ext4] [1594985.019253] [] ? __mark_inode_dirty+0x165/0x350 [1594985.019258] [] ? generic_update_time+0x79/0xd0 [1594985.019259] [] ? current_time+0x36/0x70 [1594985.019260] [] ? file_update_time+0xbc/0x110 [1594985.019271] [] ? __generic_file_write_iter+0x99/0x1b0 [1594985.019278] [] ? ext4_file_write_iter+0x90/0x370 [ext4] [1594985.019288] [] ? do_futex+0x2c9/0xb00 [1594985.019294] [] ? fsnotify+0x381/0x4e0 [1594985.019299] [] ? new_sync_write+0xda/0x130 [1594985.019305] [] ? vfs_write+0xb0/0x190 [1594985.019307] [] ? SyS_write+0x52/0xc0 [1594985.019309] [] ? 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)