From owner-freebsd-scsi@freebsd.org Tue Oct 3 06:19:08 2017 Return-Path: Delivered-To: freebsd-scsi@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 8F143E31FC7; Tue, 3 Oct 2017 06:19:08 +0000 (UTC) (envelope-from ben.rubson@gmail.com) Received: from mail-wr0-x242.google.com (mail-wr0-x242.google.com [IPv6:2a00:1450:400c:c0c::242]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client CN "smtp.gmail.com", Issuer "Google Internet Authority G2" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 22C4A6635B; Tue, 3 Oct 2017 06:19:08 +0000 (UTC) (envelope-from ben.rubson@gmail.com) Received: by mail-wr0-x242.google.com with SMTP id y44so171951wry.2; Mon, 02 Oct 2017 23:19:08 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:subject:from:in-reply-to:date :content-transfer-encoding:message-id:references:to; bh=srKBKlqL0bm2QIKPSKpGYiCm8msLDkbMXNIiZt3xkus=; b=SI3hpRxnRCyREQkUT9I+JfvlDqAa1VAeiCefJkz4U3eIdsgLT+LvaDHUv4VdtsObGi hdKwajyoRODQNKjCYcffYAu/0YrlQ55gn+qIxUmM4T9Msz4kbmI3ZdC2zOqDhpWdrtL6 qGw5caG8B0nI/H0GEnf0og6Tx64uUB3hS7US4horNQTuydh10N69nUrT802fjToOlbEo Mi472MJLGyqoqlFJEgQwQnnVA5xHrCVjwixwr6yim+T348OLkW4xmF+3mohXd0ED7Jtw 9X2b2F6kgLGZqJzotBH+LgglgnT2MnojL8Lbgv64eUHXp6VTnFh4iGSikjqa6pd3f5+r 9q6g== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:subject:from:in-reply-to:date :content-transfer-encoding:message-id:references:to; bh=srKBKlqL0bm2QIKPSKpGYiCm8msLDkbMXNIiZt3xkus=; b=B1CgA+DE3UABMyiRT7MY0l1k0QG4yQmBW99n3cH31B97kh9RvbAWVXBOtuTM71AAfQ Ocff8oZP8YjnzuzZBKb7o7Y9LABBWH62RJGpxapx3HOoLuLFtQkIKh/tjD2VWpleqHp/ 5q736Z/jrvyalRsthASW5oAssAkCu0ym2opdoPorfvcNLDTJsKEcOSGsfabZTg+2laSP 48q/sBPmR57tDI3zE7icCHbijJrRtvmSFUvEsra7ZRGwRXkR58AXhTteeP9mm0MB1YXo uNKYTcjuE5n885iYmBzj6LJ6Ed93J/oC2x1MwOsQ3vNVG+yUorFzOjJqIUEC1d8v19TG FC6g== X-Gm-Message-State: AHPjjUizU8/T0VgGVi7Ea7OIHdC5NScN1gZiCvFaNcvGDy1ayABs+mGR xsM87m5P4iTGSO5B9rBsiIZtrBFh X-Google-Smtp-Source: AOwi7QDp5dVRcwq413co87jY/pCsZXU2soA4q0HWK9xlxejqtdPydqL4CUSW5Ak9R8BapLy1oYcRew== X-Received: by 10.223.198.15 with SMTP id n15mr10905748wrg.200.1507011546433; Mon, 02 Oct 2017 23:19:06 -0700 (PDT) Received: from bens-mac.home (LFbn-MAR-1-445-220.w2-15.abo.wanadoo.fr. [2.15.38.220]) by smtp.gmail.com with ESMTPSA id 4sm12162741wmg.20.2017.10.02.23.19.04 (version=TLS1 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Mon, 02 Oct 2017 23:19:05 -0700 (PDT) Content-Type: text/plain; charset=us-ascii Mime-Version: 1.0 (Mac OS X Mail 9.3 \(3124\)) Subject: Re: ZFS stalled after some mirror disks were lost From: Ben RUBSON In-Reply-To: <4A0E9EB8-57EA-4E76-9D7E-3E344B2037D2@gmail.com> Date: Tue, 3 Oct 2017 08:19:04 +0200 Content-Transfer-Encoding: quoted-printable Message-Id: References: <4A0E9EB8-57EA-4E76-9D7E-3E344B2037D2@gmail.com> To: Freebsd fs , FreeBSD-scsi X-Mailer: Apple Mail (2.3124) X-BeenThere: freebsd-scsi@freebsd.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: SCSI subsystem List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 03 Oct 2017 06:19:08 -0000 Hi, Putting scsi list as it could be related. > On 02 Oct 2017, at 20:12, Ben RUBSON wrote: >=20 > Hi, >=20 > On a FreeBSD 11 server, the following online/healthy zpool : >=20 > home > mirror-0 > label/local1 > label/local2 > label/iscsi1 > label/iscsi2 > mirror-1 > label/local3 > label/local4 > label/iscsi3 > label/iscsi4 > cache > label/local5 > label/local6 >=20 > A sustained read throughput of 180 MB/s, 45 MB/s on each iscsi disk > according to "zpool iostat", nothing on local disks (strange but I > noticed that IOs always prefer iscsi disks to local disks). > No write IOs. >=20 > Let's disconnect all iSCSI disks : > iscsictl -Ra >=20 > Expected behavior : > IO activity flawlessly continue on local disks. >=20 > What happened : > All IOs stalled, server only answers to IOs made to its zroot pool. > All commands related to the iSCSI disks (iscsictl), or to ZFS = (zfs/zpool), > don't return. >=20 > Questions : > Why this behavior ? > How to know what happens ? (/var/log/messages says almost nothing) >=20 > I already disconnected the iSCSI disks without any issue in the past, > several times, but there were almost no IOs running. >=20 > Thank you for your help ! >=20 > Ben > On 02 Oct 2017, at 22:55, Andriy Gapon wrote: >=20 >> On 02/10/2017 22:13, Ben RUBSON wrote: >>=20 >>> On 02 Oct 2017, at 20:45, Andriy Gapon wrote: >>>=20 >>>> On 02/10/2017 21:17, Ben RUBSON wrote: >>>>=20 >>>> Unfortunately the zpool command stalls / does not return :/ >>>=20 >>> Try to take procstat -kk -a. >>=20 >> Here is the procstat output : >> https://benrubson.github.io/zfs/procstat01.log >=20 > First, it seems that there are some iscsi threads stuck on a lock = like: > 0 100291 kernel iscsimt mi_switch+0xd2 = sleepq_wait+0x3a > _sx_xlock_hard+0x592 iscsi_maintenance_thread+0x316 fork_exit+0x85 > fork_trampoline+0xe >=20 > or like >=20 > 8580 102077 iscsictl - mi_switch+0xd2 = sleepq_wait+0x3a > _sx_slock_hard+0x325 iscsi_ioctl+0x7ea devfs_ioctl_f+0x13f = kern_ioctl+0x2d4 > sys_ioctl+0x171 amd64_syscall+0x4ce Xfast_syscall+0xfb >=20 > Also, there is a thread in cam_sim_free(): > 0 100986 kernel iscsimt mi_switch+0xd2 = sleepq_wait+0x3a > _sleep+0x2a1 cam_sim_free+0x48 iscsi_session_cleanup+0x1bd > iscsi_maintenance_thread+0x388 fork_exit+0x85 fork_trampoline+0xe >=20 > So, it looks like there could be a problem is the iscsi teardown path. >=20 > Maybe that caused a domino effect in ZFS code. I see a lot of threads = waiting > either for spa_namespace_lock or a spa config lock (a highly = specialized ZFS > lock). But it is hard to untangle their inter-dependencies. >=20 > Some of ZFS I/O threads are also affected, for example: > 0 101538 kernel zio_write_issue_ mi_switch+0xd2 = sleepq_wait+0x3a > _cv_wait+0x194 spa_config_enter+0x9b zio_vdev_io_start+0x1c2 = zio_execute+0x236 > taskqueue_run_locked+0x14a taskqueue_thread_loop+0xe8 fork_exit+0x85 > fork_trampoline+0xe > 8716 101319 sshd - mi_switch+0xd2 = sleepq_wait+0x3a > _cv_wait+0x194 spa_config_enter+0x9b zio_vdev_io_start+0x1c2 = zio_execute+0x236 > zio_nowait+0x49 arc_read+0x8e4 dbuf_read+0x6c2 = dmu_buf_hold_array_by_dnode+0x1d3 > dmu_read_uio_dnode+0x41 dmu_read_uio_dbuf+0x3b zfs_freebsd_read+0x5fc > VOP_READ_APV+0x89 vn_read+0x157 vn_io_fault1+0x1c2 vn_io_fault+0x197 > dofileread+0x98 > 71181 101141 encfs - mi_switch+0xd2 = sleepq_wait+0x3a > _cv_wait+0x194 spa_config_enter+0x9b zio_vdev_io_start+0x1c2 = zio_execute+0x236 > zio_nowait+0x49 arc_read+0x8e4 dbuf_read+0x6c2 dmu_buf_hold+0x3d > zap_lockdir+0x43 zap_cursor_retrieve+0x171 zfs_freebsd_readdir+0x3f3 > VOP_READDIR_APV+0x8f kern_getdirentries+0x21b sys_getdirentries+0x28 > amd64_syscall+0x4ce Xfast_syscall+0xfb > 71181 101190 encfs - mi_switch+0xd2 = sleepq_wait+0x3a > _cv_wait+0x194 spa_config_enter+0x9b zio_vdev_io_start+0x1c2 = zio_execute+0x236 > zio_nowait+0x49 arc_read+0x8e4 dbuf_prefetch_indirect_done+0xcc = arc_read+0x425 > dbuf_prefetch+0x4f7 dmu_zfetch+0x418 dmu_buf_hold_array_by_dnode+0x34d > dmu_read_uio_dnode+0x41 dmu_read_uio_dbuf+0x3b zfs_freebsd_read+0x5fc > VOP_READ_APV+0x89 vn_read+0x157 >=20 > Note that the first of these threads executes a write zio. >=20 > It would be nice to determine an owner of spa_namespace_lock. > If you have debug symbols then it can be easily done in kgdb on the = live system: > (kgdb) p spa_namespace_lock So as said a few minutes ago I lost access to the server and had to = recycle it. Thankfully I managed to reproduce the issue, re-playing exactly the same = steps. Curious line in /var/log/messages : kernel: g_access(918): provider da18 has error (da18 is the remaining iSCSI target device which did not disconnect = properly) procstat -kk -a : https://benrubson.github.io/zfs/procstat02.log (kgdb) p spa_namespace_lock $1 =3D -2110867066 Thank you ! Ben