From owner-freebsd-fs@freebsd.org Mon Dec 2 14:32:44 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 5644E1AB981 for ; Mon, 2 Dec 2019 14:32:44 +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 47RSJB6yjfz3QY2 for ; Mon, 2 Dec 2019 14:32:42 +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 0455D40015 for ; Mon, 2 Dec 2019 15:32:40 +0100 (CET) Received: from [IPv6:2001:6b0:17:f002:cd44:8234:6c47:5d2e] (unknown [IPv6:2001:6b0:17:f002:cd44:8234:6c47:5d2e]) (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 DF8D240011 for ; Mon, 2 Dec 2019 15:32:39 +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: Slow reboots due to ZFS cleanup in kern_shutdown() .. zio_fini() Message-Id: Date: Mon, 2 Dec 2019 15:32:39 +0100 To: freebsd-fs@freebsd.org X-Mailer: Apple Mail (2.3601.0.10) X-Virus-Scanned: ClamAV using ClamSMTP X-Rspamd-Queue-Id: 47RSJB6yjfz3QY2 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 [-4.12 / 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]; TO_DN_NONE(0.00)[]; RCPT_COUNT_ONE(0.00)[1]; NEURAL_HAM_LONG(-1.00)[-1.000,0]; RCVD_COUNT_THREE(0.00)[3]; RCVD_TLS_LAST(0.00)[]; MV_CASE(0.50)[]; 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]; IP_SCORE(-1.62)[ipnet: 130.236.0.0/16(-4.50), asn: 2843(-3.60), 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: Mon, 02 Dec 2019 14:32:44 -0000 I=E2=80=99ve been looking at trying to figure out why our servers take = so long to reboot, where the most time is spent doing a =E2=80=9Cshutdown=E2= =80=9D. We=E2=80=99ve seen examples where it has taken 10-20 minutes (or = more). This is Dell PowerEdge R730xd servers with 256GB RAM and ~140TB of = disks. FreeBSD 11.3. With ~24000 filsystems per server. We normally cap ARC to 128GB RAM. Adding a lot of debugging printf() calls to relevant parts of the code = points to: kern_shutdown() -> EVENTHANDLER_INVOKE(shutdown_post_sync) -> zfsshutdown() ->=20 zfs__fini() ->=20 spa_fini() ->=20 zio_fini(): Debug output from a test run: zio_fini: kmem_cache_destroy(zio_buf_cache & zio_data_buf_cache): kmem_cache_destroy: uma_zfree_arg(0xfffff803465eec00) [zio_buf_12288] = took 16 seconds kmem_cache_destroy(zio_buf_cache[20]) took 16 seconds kmem_cache_destroy: uma_zfree_arg(0xfffff803465eeb00) [zio_buf_16384] = took 61 seconds kmem_cache_destroy(zio_buf_cache[28]) took 61 seconds kmem_cache_destroy: uma_zfree_arg(0xfffff8034c9018c0) [zio_buf_131072] = took 87 seconds kmem_cache_destroy(zio_buf_cache[224]) took 87 seconds kmem_cache_destroy: uma_zfree_arg(0xfffff8034c901880) = [zio_data_buf_131072] took 5 seconds kmem_cache_destroy(zio_data_buf_cache[224]) took 5 seconds (I modified the code here to print the time spent if it took 2 seconds = or more) This is on a newly rebooted server (with all filesystems mounted). Seems = like uma_zfree_arg() is taking really long to execute. Now that code = isn=E2=80=99t exactly easy to read (for me atleast)=E2=80=A6 Lot=E2=80=99s= of barrier/locks and stuff. I wonder why this code should take so long? There shouldn=E2=80=99t be = any disk I/O involved and it=E2=80=99s just a cache so I wonder if there = might be some way to get rid of it quicker? Any UMA experts online? :-) Reason for this is that I=E2=80=99d like to be able to make sure a = server reboots more quickly in case of problems. Now with the parallell = ZFS mount stuff being done at boot time that part is much quicker :-). - Peter