From owner-freebsd-fs@freebsd.org Wed Dec 4 10:13:48 2019 Return-Path: Delivered-To: freebsd-fs@mailman.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.nyi.freebsd.org (Postfix) with ESMTP id 241C01CFBC7 for ; Wed, 4 Dec 2019 10:13:48 +0000 (UTC) (envelope-from pen@lysator.liu.se) Received: from mail.lysator.liu.se (mail.lysator.liu.se [130.236.254.3]) (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 47SZSW66psz4gDc; Wed, 4 Dec 2019 10:13:47 +0000 (UTC) (envelope-from pen@lysator.liu.se) Received: from mail.lysator.liu.se (localhost [127.0.0.1]) by mail.lysator.liu.se (Postfix) with ESMTP id 2859B40017; Wed, 4 Dec 2019 11:13:44 +0100 (CET) Received: from [IPv6:2001:6b0:17:f002:8d12:4cc9:4751:6d43] (unknown [IPv6:2001:6b0:17:f002:8d12:4cc9:4751:6d43]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mail.lysator.liu.se (Postfix) with ESMTPSA id 0846F4000D; Wed, 4 Dec 2019 11:13:44 +0100 (CET) From: Peter Eriksson Message-Id: Mime-Version: 1.0 (Mac OS X Mail 13.0 \(3601.0.10\)) Subject: Re: Slow reboots due to ZFS cleanup in kern_shutdown() .. zio_fini() Date: Wed, 4 Dec 2019 11:13:43 +0100 In-Reply-To: Cc: Andriy Gapon To: FreeBSD FS References: <20191202225424.GG43802@raichu> <3b71fe37-c29f-e3e5-ff96-5dce15cc7553@FreeBSD.org> <20191203162219.GI43802@raichu> <247C6990-BC6E-4E3D-8CEF-5A861D8A25EC@lysator.liu.se> <4D44B25E-2F15-4536-A653-DA242051C8A9@lysator.liu.se> X-Mailer: Apple Mail (2.3601.0.10) X-Virus-Scanned: ClamAV using ClamSMTP X-Rspamd-Queue-Id: 47SZSW66psz4gDc X-Spamd-Bar: ----- Authentication-Results: mx1.freebsd.org; none X-Spamd-Result: default: False [-5.99 / 15.00]; NEURAL_HAM_MEDIUM(-0.99)[-0.993,0]; NEURAL_HAM_LONG(-1.00)[-0.998,0]; REPLY(-4.00)[] Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-Content-Filtered-By: Mailman/MimeDel 2.1.29 X-BeenThere: freebsd-fs@freebsd.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Filesystems List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 04 Dec 2019 10:13:48 -0000 Yeah, I noticed that after I sent that email (should send stuff just = before you go to bed :-) Anyway, some more timing/debug printfs point to the keg->uk_freef(mem) = call in keg_free_slab() which sometimes take about a second to execute. (Should probably switch to some other time source with greater = resolution than 1s next :-) keg_free_slab: keg->uk_freef(mem) took 1 seconds keg_free_slab: keg->uk_freef(mem) took 1 seconds keg_free_slab: keg->uk_freef(mem) took 1 seconds keg_free_slab: keg->uk_freef(mem) took 1 seconds keg_free_slab: keg->uk_freef(mem) took 1 seconds keg_free_slab: keg->uk_freef(mem) took 1 seconds keg_free_slab: keg->uk_freef(mem) took 1 seconds - Peter > On 4 Dec 2019, at 10:48, Andriy Gapon wrote: >=20 > On 04/12/2019 00:28, Peter Eriksson wrote: >> =E2=80=A6 and X levels deeper it gives this (not all filesystems = mounted - I rebooted fairly quickly): >>=20 >> keg_drain: while (SLIST_FIRST/SLIST_REMOVE)-loop took 14 seconds = [20021 loops] >> zone_drain_wait(): zone_foreach_keg(zone, &keg_drain) took 14 seconds >> zone_dtor(): zone_drain_wait(zone, M_WAITOK) took 14 seconds >> zone_free_item(zone=3DUMA Zones): zone->uz_dtor() took 14 seconds >> uma_zdestroy(zio_buf_12288) took 14 seconds >> kmem_cache_destroy: uma_zdestroy(0xfffff803467c8ac0) [zio_buf_12288] = took 14 seconds >> kmem_cache_destroy(zio_buf_cache[20]) took 14 seconds >>=20 >>=20 >> Hmm=E2=80=A6 I wonder if it isn=E2=80=99t this code I = /usr/src/sys/sys/queue.h: >>=20 >>> #define SLIST_REMOVE(head, elm, type, field) do { = \ >>> QMD_SAVELINK(oldnext, (elm)->field.sle_next); = \ >>> if (SLIST_FIRST((head)) =3D=3D (elm)) { = \ >>> SLIST_REMOVE_HEAD((head), field); = \ >>> } = \ >>> else { = \ >>> QUEUE_TYPEOF(type) *curelm =3D SLIST_FIRST(head); = \ >>> while (SLIST_NEXT(curelm, field) !=3D (elm)) = \ >>> curelm =3D SLIST_NEXT(curelm, field); = \ >>> SLIST_REMOVE_AFTER(curelm, field); = \ >>> } = \ >>> TRASHIT(*oldnext); = \ >>> } while (0) >>=20 >> Combined with this in /usr/src/sys/vm/uma_core.c: keg_drain(): >>=20 >>> finished: >>> KEG_UNLOCK(keg); >>>=20 >>> while ((slab =3D SLIST_FIRST(&freeslabs)) !=3D NULL) { >>> SLIST_REMOVE(&freeslabs, slab, uma_slab, us_hlink); >>> keg_free_slab(keg, slab, keg->uk_ipers); >>> } >>=20 >> (The keg_drain print above is the time for the while() loop). >>=20 >> If I=E2=80=99m reading this right it looks like it=E2=80=99s = potentially doing a linear search through a (long) linked list, for = every entry in the free slabs list. 20000 entries in 14 seconds is 1400 = entries per second. >=20 > It's not a search. The loop is removing *all* items. There is no = other way to > do it :-) > Expanding your calculations, it takes on the order of a millisecond to = process a > single slab. I bet that the time is spent in keg_free_slab() and it's = a lot of > time. >=20 > I wonder if the OR should actually be AND in this condition: > if (!uma_dbg_kskip(keg, slab->us_data + (keg->uk_rsize = * i)) || > keg->uk_fini !=3D trash_fini) > Looks like there is a "ton" of memory reading done here. >=20 > --=20 > Andriy Gapon