From nobody Sun Oct 16 16:40:35 2022 X-Original-To: freebsd-fs@mlmmj.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mlmmj.nyi.freebsd.org (Postfix) with ESMTP id 4Mr5VN3Pmvz4fb6k for ; Sun, 16 Oct 2022 16:41:16 +0000 (UTC) (envelope-from void@f-m.fm) Received: from wout2-smtp.messagingengine.com (wout2-smtp.messagingengine.com [64.147.123.25]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 4Mr5VM4zKJz3kn4 for ; Sun, 16 Oct 2022 16:41:15 +0000 (UTC) (envelope-from void@f-m.fm) Received: from compute3.internal (compute3.nyi.internal [10.202.2.43]) by mailout.west.internal (Postfix) with ESMTP id 6F0413200583 for ; Sun, 16 Oct 2022 12:41:13 -0400 (EDT) Received: from imap46 ([10.202.2.96]) by compute3.internal (MEProxy); Sun, 16 Oct 2022 12:41:13 -0400 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=f-m.fm; h=cc :content-type:date:date:from:from:in-reply-to:in-reply-to :message-id:mime-version:references:reply-to:sender:subject :subject:to:to; s=fm3; t=1665938473; x=1666024873; bh=nWTWir13Wy kWqHpbg9ZB4PwE+/Kmr+PC0KSfEFza4Ts=; b=Iy5BtkJE8StrfAZl111KS2p5G3 nlP8XoQCrJmbgNoe0SOlf4Tmo1Ouss8IEgLWEgce91VnPzLRQcpx3kfVgu5dWKuu qWP2qBW8uuB/IXxxKaa/I/EccJ+spQ/OfQamIER1l3C+l3MgnzG+3JHG9/YMmpoS G8Fu+WO5H0pemnnH0z+OKG2zJAJYD6v7zErguxB/oMlw3+rH8F/JxBrbTcfQUE9h UbBPIy3GzdrLoxuP9u+Y54GJIKzL84oJa1FQuFz8A3dO6PTdCy6RAIT+kFCYdKwY BSMa34ZHLVFBDCxH34WRQ9uPCVjDb0HO/T23GCwL9aSaLK2x5AzeZ5DaHNtw== DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d= messagingengine.com; h=cc:content-type:date:date:feedback-id :feedback-id:from:from:in-reply-to:in-reply-to:message-id :mime-version:references:reply-to:sender:subject:subject:to:to :x-me-proxy:x-me-proxy:x-me-sender:x-me-sender:x-sasl-enc; s= fm3; t=1665938473; x=1666024873; bh=nWTWir13WykWqHpbg9ZB4PwE+/Km r+PC0KSfEFza4Ts=; b=exwUA3odqxJ9QtsitIpQ0eUsxNhAa2giRLpkNI5KIA7O qRttKgOP72QzOrlmFOuRS4xunBcLB3N8YM+vhJwxyDErZju7wamc5xZwdqGlDGZZ U6HuaXTrnKLa+WsHR/7C0sxH/JICrxmzm/zNbQa28oaX/6Ei08R0HZi1CKSOle9L K+0FzfEy6YGl2ceZs4OVTOlxgfsp/xociQzYftJ1p7kasLBnPWEgTNZbkKqAEZFh gPzAfDF9vG1BgdaZhO12sPe5maRDqq9KrMyo7Roo2CMgFyEnPLntO0iTcrfcgXAA tlu5ACULPCwyoXfHx/k2HqGv4rJZL1VqsuQNejL71A== X-ME-Sender: X-ME-Proxy-Cause: gggruggvucftvghtrhhoucdtuddrgedvfedrfeekjedguddthecutefuodetggdotefrod ftvfcurfhrohhfihhlvgemucfhrghsthforghilhdpqfgfvfdpuffrtefokffrpgfnqfgh necuuegrihhlohhuthemuceftddtnecunecujfgurhepofgfggfkjghffffhvffutgesth dtredtreertdenucfhrhhomhepvhhoihguuceovhhoihgusehfqdhmrdhfmheqnecuggft rfgrthhtvghrnhepieetvdeuhedthedtvdfhuefhveehvdeiledvieffheevleehgeefud eljedukedvnecuvehluhhsthgvrhfuihiivgeptdenucfrrghrrghmpehmrghilhhfrhho mhepvhhoihgusehfqdhmrdhfmh X-ME-Proxy: Feedback-ID: i2541463c:Fastmail Received: by mailuser.nyi.internal (Postfix, from userid 501) id CE2F12A20079; Sun, 16 Oct 2022 12:41:12 -0400 (EDT) X-Mailer: MessagingEngine.com Webmail Interface User-Agent: Cyrus-JMAP/3.7.0-alpha0-1047-g9e4af4ada4-fm-20221005.001-g9e4af4ad List-Id: Filesystems List-Archive: https://lists.freebsd.org/archives/freebsd-fs List-Help: List-Post: List-Subscribe: List-Unsubscribe: Sender: owner-freebsd-fs@freebsd.org Mime-Version: 1.0 Message-Id: <64a0af42-630d-4f42-8b8c-921b68b03078@app.fastmail.com> In-Reply-To: References: <1625dc7b-81c4-4350-8f86-1b65f5a860d9@app.fastmail.com> Date: Sun, 16 Oct 2022 16:40:35 +0000 From: void To: freebsd-fs Subject: Re: zfs with operations like rm -rf takes a very long time recently Content-Type: text/plain X-Rspamd-Queue-Id: 4Mr5VM4zKJz3kn4 X-Spamd-Bar: ---- Authentication-Results: mx1.freebsd.org; dkim=pass header.d=f-m.fm header.s=fm3 header.b=Iy5BtkJE; dkim=pass header.d=messagingengine.com header.s=fm3 header.b=exwUA3od; dmarc=pass (policy=none) header.from=f-m.fm; spf=pass (mx1.freebsd.org: domain of void@f-m.fm designates 64.147.123.25 as permitted sender) smtp.mailfrom=void@f-m.fm X-Spamd-Result: default: False [-4.56 / 15.00]; NEURAL_HAM_MEDIUM(-1.00)[-1.000]; DWL_DNSWL_LOW(-1.00)[messagingengine.com:dkim]; NEURAL_HAM_LONG(-1.00)[-1.000]; NEURAL_HAM_SHORT(-0.97)[-0.967]; DMARC_POLICY_ALLOW(-0.50)[f-m.fm,none]; MV_CASE(0.50)[]; R_SPF_ALLOW(-0.20)[+ip4:64.147.123.25]; R_DKIM_ALLOW(-0.20)[f-m.fm:s=fm3,messagingengine.com:s=fm3]; RCVD_IN_DNSWL_LOW(-0.10)[64.147.123.25:from]; MIME_GOOD(-0.10)[text/plain]; XM_UA_NO_VERSION(0.01)[]; FROM_HAS_DN(0.00)[]; TO_MATCH_ENVRCPT_ALL(0.00)[]; RCPT_COUNT_ONE(0.00)[1]; PREVIOUSLY_DELIVERED(0.00)[freebsd-fs@freebsd.org]; ARC_NA(0.00)[]; RCVD_TLS_LAST(0.00)[]; ASN(0.00)[asn:29838, ipnet:64.147.123.0/24, country:US]; TO_DN_ALL(0.00)[]; RCVD_COUNT_THREE(0.00)[4]; FREEMAIL_FROM(0.00)[f-m.fm]; MLMMJ_DEST(0.00)[freebsd-fs@freebsd.org]; DKIM_TRACE(0.00)[f-m.fm:+,messagingengine.com:+]; MIME_TRACE(0.00)[0:+]; FROM_EQ_ENVFROM(0.00)[]; FREEMAIL_ENVFROM(0.00)[f-m.fm]; RWL_MAILSPIKE_POSSIBLE(0.00)[64.147.123.25:from] X-ThisMailContainsUnwantedMimeParts: N On Sun, 16 Oct 2022, at 16:07, Alan Somers wrote: > Gstat is showing that your disk is fully busy. It's also showing read > latency as high as 128 ms, which is extremely slow. I ran another gstat with -I 5s and have omitted -d as per your last email. How did you calculate latency? There's zfs-stats installed too. Would pasting some output here be useful? # gstat -opC -I 5s timestamp,name,q-depth,total_ops/s,read/s,read-KiB/s,ms/read,write/s,write-KiB/s,ms/write,other/s,ms/other,%busy 2022-10-16 17:23:47.080118413,da0,3,0,0,0,0.0,0,0,0.0,0,0.0,0.0 2022-10-16 17:23:52.088745392,da0,4,93,45,246,26.4,49,3974,12.7,0,154.4,97.8 2022-10-16 17:23:57.167503039,da0,3,82,41,164,25.5,40,3193,17.3,1,153.2,99.2 2022-10-16 17:24:02.176759152,da0,3,81,43,176,22.8,38,2704,13.3,0,252.6,98.6 2022-10-16 17:24:07.189364538,da0,2,90,35,140,27.9,55,3371,15.9,1,146.9,99.4 2022-10-16 17:24:12.190874083,da0,3,95,42,170,23.3,52,3486,13.2,0,167.0,96.6 2022-10-16 17:24:17.212769876,da0,4,85,33,134,30.6,52,3508,22.3,1,164.9,100.7 2022-10-16 17:24:22.286986167,da0,3,89,42,168,23.2,46,3149,12.7,1,127.3,97.2 2022-10-16 17:24:27.295992137,da0,3,88,40,160,25.4,48,3978,15.6,0,147.4,101.3 2022-10-16 17:24:32.406662934,da0,2,90,46,254,27.1,44,3554,12.9,0,159.3,97.9 2022-10-16 17:24:37.426033077,da0,3,87,42,177,23.3,45,2835,15.4,1,112.8,98.0 2022-10-16 17:24:42.455203661,da0,3,95,43,170,23.1,52,3770,11.9,0,153.5,98.8 2022-10-16 17:24:47.468741642,da0,3,71,36,144,27.9,35,2510,19.7,1,243.7,99.3 2022-10-16 17:24:52.471973107,da0,3,80,34,138,29.1,46,3630,17.6,0,266.6,99.2 2022-10-16 17:24:57.490425268,da0,3,79,35,141,28.1,43,3372,18.6,1,297.8,98.3 2022-10-16 17:25:02.589730547,da0,4,68,30,123,32.7,36,2318,22.4,3,105.2,97.9 ^C > I suspect a > problem with your disk. FYI, ZFS naturally has a 5-second rhythm > (unless you changed vfs.zfs.txg.timeout), # sysctl vfs.zfs.txg.timeout vfs.zfs.txg.timeout: 5 > so gstat's output is > sometimes more consistent if you use "-I 5s". You can also omit "-d" > for magnetic HDDs, since they don't have anything like TRIM. > I suggest checking dmesg to see if there are any messages about errors > from da0. It would also be worth running "smartctl -a /dev/da0", from > sysutils/smartmontools. Unfortunately, no errors seen in either dmesg or smartctl. there's been a long smartctl test relatively recently, also came back clean. SMART Self-test log structure revision number 1 Num Test_Description Status Remaining LifeTime(hours) LBA_of_first_error # 1 Short offline Completed without error 00% 39253 - # 2 Extended offline Completed without error 00% 39176 - # 3 Short offline Completed without error 00% 39172 - ID# ATTRIBUTE_NAME FLAG VALUE WORST THRESH TYPE UPDATED WHEN_FAILED RAW_VALUE 1 Raw_Read_Error_Rate 0x000b 100 100 050 Pre-fail Always - 0 2 Throughput_Performance 0x0005 100 100 050 Pre-fail Offline - 0 3 Spin_Up_Time 0x0027 100 100 001 Pre-fail Always - 2595 4 Start_Stop_Count 0x0032 100 100 000 Old_age Always - 1487 5 Reallocated_Sector_Ct 0x0033 100 100 050 Pre-fail Always - 0 7 Seek_Error_Rate 0x000b 100 100 050 Pre-fail Always - 0 8 Seek_Time_Performance 0x0005 100 100 050 Pre-fail Offline - 0 9 Power_On_Hours 0x0032 002 002 000 Old_age Always - 39254 10 Spin_Retry_Count 0x0033 128 100 030 Pre-fail Always - 0 12 Power_Cycle_Count 0x0032 100 100 000 Old_age Always - 1263 191 G-Sense_Error_Rate 0x0032 100 100 000 Old_age Always - 4 192 Power-Off_Retract_Count 0x0032 100 100 000 Old_age Always - 426 193 Load_Cycle_Count 0x0032 029 029 000 Old_age Always - 710616 194 Temperature_Celsius 0x0022 100 100 000 Old_age Always - 54 (Min/Max 16/65) 196 Reallocated_Event_Count 0x0032 100 100 000 Old_age Always - 0 197 Current_Pending_Sector 0x0032 100 100 000 Old_age Always - 0 198 Offline_Uncorrectable 0x0030 100 100 000 Old_age Offline - 0 199 UDMA_CRC_Error_Count 0x0032 200 200 000 Old_age Always - 0 220 Disk_Shift 0x0002 100 100 000 Old_age Always - 0 222 Loaded_Hours 0x0032 075 075 000 Old_age Always - 10367 223 Load_Retry_Count 0x0032 100 100 000 Old_age Always - 0 224 Load_Friction 0x0022 100 100 000 Old_age Always - 0 226 Load-in_Time 0x0026 100 100 000 Old_age Always - 260 240 Head_Flying_Hours 0x0001 100 100 001 Pre-fail Offline - 0 SMART Error Log Version: 1 No Errors Logged