From owner-freebsd-fs@freebsd.org Tue Dec 3 22:28:54 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 149671BFCA5 for ; Tue, 3 Dec 2019 22:28:54 +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 47SGq72CSbz42rV for ; Tue, 3 Dec 2019 22:28:50 +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 91CCA4000A for ; Tue, 3 Dec 2019 23:28:48 +0100 (CET) Received: from [192.168.1.132] (h-201-140.A785.priv.bahnhof.se [98.128.201.140]) (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 5414A40006 for ; Tue, 3 Dec 2019 23:28:48 +0100 (CET) From: Peter Eriksson Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable 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: Tue, 3 Dec 2019 23:28:48 +0100 References: <20191202225424.GG43802@raichu> <3b71fe37-c29f-e3e5-ff96-5dce15cc7553@FreeBSD.org> <20191203162219.GI43802@raichu> <247C6990-BC6E-4E3D-8CEF-5A861D8A25EC@lysator.liu.se> To: FreeBSD FS In-Reply-To: <247C6990-BC6E-4E3D-8CEF-5A861D8A25EC@lysator.liu.se> Message-Id: <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: 47SGq72CSbz42rV X-Spamd-Bar: ----- Authentication-Results: mx1.freebsd.org; dkim=none; dmarc=pass (policy=none) header.from=liu.se; spf=pass (mx1.freebsd.org: domain of pen@lysator.liu.se designates 130.236.254.3 as permitted sender) smtp.mailfrom=pen@lysator.liu.se X-Spamd-Result: default: False [-6.00 / 15.00]; ARC_NA(0.00)[]; RCVD_VIA_SMTP_AUTH(0.00)[]; NEURAL_HAM_MEDIUM(-1.00)[-1.000,0]; FROM_HAS_DN(0.00)[]; R_SPF_ALLOW(-0.20)[+a:mail.lysator.liu.se]; TO_MATCH_ENVRCPT_ALL(0.00)[]; MIME_GOOD(-0.10)[text/plain]; PREVIOUSLY_DELIVERED(0.00)[freebsd-fs@freebsd.org]; NEURAL_HAM_LONG(-1.00)[-1.000,0]; RCPT_COUNT_ONE(0.00)[1]; RCVD_COUNT_THREE(0.00)[3]; RCVD_TLS_LAST(0.00)[]; TO_DN_ALL(0.00)[]; RCVD_IN_DNSWL_MED(-0.20)[3.254.236.130.list.dnswl.org : 127.0.11.2]; DMARC_POLICY_ALLOW(-0.50)[liu.se,none]; MV_CASE(0.50)[]; IP_SCORE(-3.50)[ip: (-9.17), ipnet: 130.236.0.0/16(-4.60), asn: 2843(-3.68), country: SE(-0.03)]; FROM_EQ_ENVFROM(0.00)[]; R_DKIM_NA(0.00)[]; MIME_TRACE(0.00)[0:+]; ASN(0.00)[asn:2843, ipnet:130.236.0.0/16, country:SE]; MID_RHS_MATCH_FROM(0.00)[] 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: Tue, 03 Dec 2019 22:28:54 -0000 =E2=80=A6 and X levels deeper it gives this (not all filesystems mounted = - I rebooted fairly quickly): 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 Hmm=E2=80=A6 I wonder if it isn=E2=80=99t this code I = /usr/src/sys/sys/queue.h: > #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) Combined with this in /usr/src/sys/vm/uma_core.c: keg_drain(): > finished: > KEG_UNLOCK(keg); > > while ((slab =3D SLIST_FIRST(&freeslabs)) !=3D NULL) { > SLIST_REMOVE(&freeslabs, slab, uma_slab, us_hlink); > keg_free_slab(keg, slab, keg->uk_ipers); > } (The keg_drain print above is the time for the while() loop). 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. Hmmm=E2=80=A6 It feels like this code could be optimised at bit. - Peter > On 3 Dec 2019, at 18:31, Peter Eriksson wrote: >=20 > zio_fini: kmem_cache_destroy(zio_buf_cache & zio_data_buf_cache): >=20 > zone_free_item(zone=3DUMA Zones): zone->uz_dtor() took 16 seconds > uma_zdestroy(zio_buf_12288) took 16 seconds > kmem_cache_destroy: uma_zdestroy(0xfffff8034678e980) [zio_buf_12288] = took 16 seconds > kmem_cache_destroy(zio_buf_cache[20]) took 16 seconds >=20 > zone_free_item(zone=3DUMA Zones): zone->uz_dtor() took 60 seconds > uma_zdestroy(zio_buf_16384) took 60 seconds > kmem_cache_destroy: uma_zdestroy(0xfffff8034678e880) [zio_buf_16384] = took 60 seconds > kmem_cache_destroy(zio_buf_cache[28]) took 60 seconds >=20 >=20 > Looks like it is the call to zone->uz_dtor that is taking time (added = time check around the various parts of zone_free_item(). >=20 > - Peter >=20 >> Indeed, looking at the vmstat -z output this doesn't really make = sense. >> It would be useful to confirm that we are in fact spending most of = the >> time reclaiming items. >=20 > _______________________________________________ > freebsd-fs@freebsd.org mailing list > https://lists.freebsd.org/mailman/listinfo/freebsd-fs > To unsubscribe, send any mail to "freebsd-fs-unsubscribe@freebsd.org"