From nobody Wed Dec 29 15:35:31 2021 X-Original-To: current@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 3506F19147D4; Wed, 29 Dec 2021 15:35:34 +0000 (UTC) (envelope-from avg@FreeBSD.org) Received: from smtp.freebsd.org (smtp.freebsd.org [IPv6:2610:1c1:1:606c::24b:4]) (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-signature RSA-PSS (4096 bits) client-digest SHA256) (Client CN "smtp.freebsd.org", Issuer "R3" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 4JPFpt0MYXz4Rxd; Wed, 29 Dec 2021 15:35:34 +0000 (UTC) (envelope-from avg@FreeBSD.org) Received: from [192.168.0.88] (unknown [195.64.148.76]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client did not present a certificate) (Authenticated sender: avg/mail) by smtp.freebsd.org (Postfix) with ESMTPSA id 41B84245CE; Wed, 29 Dec 2021 15:35:33 +0000 (UTC) (envelope-from avg@FreeBSD.org) Message-ID: <4dfbdcce-43d8-3bfc-6858-939ab18d637d@FreeBSD.org> Date: Wed, 29 Dec 2021 17:35:31 +0200 List-Id: Discussions about the use of FreeBSD-current List-Archive: https://lists.freebsd.org/archives/freebsd-current List-Help: List-Post: List-Subscribe: List-Unsubscribe: Sender: owner-freebsd-current@freebsd.org MIME-Version: 1.0 User-Agent: Mozilla/5.0 (X11; FreeBSD amd64; rv:91.0) Gecko/20100101 Firefox/91.0 Thunderbird/91.4.1 Content-Language: en-US To: current@FreeBSD.org, geom@freebsd.org From: Andriy Gapon Subject: gmirror: read failed when one disk (of two) failed Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 7bit ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=freebsd.org; s=dkim; t=1640792134; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding; bh=xJlcs2YVdfjPBwkAjZh+cCsgzKEeXiMHfmcp+3d8MSc=; b=mZB+LQNg4Cb6UGnkhyAQ5BtsVCcY1w2GNVCVlfEEGENh9JTXAelhGIRT8ejGrFtBNdn0pn v2HWy//N9iGDENezQsvMYwiMwi7iBGAkIBXVZXkdpLck9RHjNPxuJl2N1E1Kouxo9YrBnG RTtqdBSzD+FvIjDDEvYU+eeahBl8+PKMZO8BQ0PtmrVlx9qnXEXDxZSq3ARaRwBcGRzY1A XZFIFYLi76CML2v3ksaKFpIlhUfD6Q8onvRbv7Amch0yB5A649VwPPUFTMysDyXmM7pSmA eyYc+H0zwQwG7TGPcZNJ0FjztRIoFvh/e9unV3r1ah0xGGlQnHV+6XkwaUV96w== ARC-Seal: i=1; s=dkim; d=freebsd.org; t=1640792134; a=rsa-sha256; cv=none; b=sbaHb2CfAZfzccCS+LtvllUd6VPVvkLq9ZNzRMYDki9WPfGOxUHT/T+STpZoF7sd0V32rQ dNTGu17U2oaeBKtd96FD/n/KCFIvTovJ976LeiLJf052mMXLloyaLbofoYa4fbSmcH8foW dhvfVg193YpXSa1bKKeqxCMdGm5EItTLcw3fS6De6Ph0V2TGb2pBYfS5b7q8HcCh6EAXMg G9qqJty/Oq85p3wVkDkA7E1sYB/d7PbiQdssbpyDOtRqsDc4CFCkniKAa+2lCPDY5Qll0c i3Sfe0UNfg2bCpWgDLctw9JokQ+kKOV1BzO9UGYRMqsfWe0KqfUuyL1v63WVvQ== ARC-Authentication-Results: i=1; mx1.freebsd.org; none X-ThisMailContainsUnwantedMimeParts: N I have a gmirror-ed swap partition: # swapinfo -h Device Size Used Avail Capacity /dev/mirror/swap 8.0G 2.6G 5.4G 33% # gmirror list Geom name: swap State: COMPLETE Components: 2 Balance: prefer Slice: 4096 Flags: NONE GenID: 4 SyncID: 20 ID: 1722474567 Type: AUTOMATIC Providers: 1. Name: mirror/swap Mediasize: 8589934080 (8.0G) Sectorsize: 512 Stripesize: 4096 Stripeoffset: 0 Mode: r1w1e0 Consumers: 1. Name: ada0p2 Mediasize: 8589934592 (8.0G) Sectorsize: 512 Stripesize: 4096 Stripeoffset: 0 Mode: r1w1e1 State: ACTIVE Priority: 0 Flags: (null) GenID: 4 SyncID: 20 ID: 1654937889 2. Name: ada1p2 Mediasize: 8589934592 (8.0G) Sectorsize: 512 Stripesize: 0 Stripeoffset: 655360 Mode: r1w1e1 State: ACTIVE Priority: 0 Flags: (null) GenID: 4 SyncID: 20 ID: 1289215755 Recently I had an accident where one of the disks got lost, with some "struggle". I see two things in the logs that concern me. One is mildly concerning and the other seems to be serious. The disk was known as ada1, it was attached to ahcich5. So, while the failing disk was struggling, I got messages like: ahcich5: AHCI reset: device not ready after 31000ms (tfd = 00000080) swap_pager: indefinite wait buffer: bufobj: 0, blkno: 1175296, size: 4096 swap_pager: indefinite wait buffer: bufobj: 0, blkno: 268223, size: 4096 swap_pager: indefinite wait buffer: bufobj: 0, blkno: 1175296, size: 4096 swap_pager: indefinite wait buffer: bufobj: 0, blkno: 268223, size: 4096 ahcich5: Timeout on slot 18 port 0 ahcich5: is 00000000 cs 00040000 ss 00000000 rs 00040000 tfd 80 serr 00000000 cmd 0020f217 (aprobe0:ahcich5:0:0:0): ATA_IDENTIFY. ACB: ec 00 00 00 00 40 00 00 00 00 00 00 (aprobe0:ahcich5:0:0:0): CAM status: Command timeout (aprobe0:ahcich5:0:0:0): Retrying command, 0 more tries remain swap_pager: indefinite wait buffer: bufobj: 0, blkno: 1175296, size: 4096 swap_pager: indefinite wait buffer: bufobj: 0, blkno: 268223, size: 4096 ahcich5: AHCI reset: device not ready after 31000ms (tfd = 00000080) swap_pager: indefinite wait buffer: bufobj: 0, blkno: 1175296, size: 4096 swap_pager: indefinite wait buffer: bufobj: 0, blkno: 268223, size: 4096 swap_pager: indefinite wait buffer: bufobj: 0, blkno: 1175296, size: 4096 swap_pager: indefinite wait buffer: bufobj: 0, blkno: 268223, size: 4096 ahcich5: Timeout on slot 19 port 0 ahcich5: is 00000000 cs 00080000 ss 00000000 rs 00080000 tfd 80 serr 00000000 cmd 0020f317 (aprobe0:ahcich5:0:0:0): ATA_IDENTIFY. ACB: ec 00 00 00 00 40 00 00 00 00 00 00 (aprobe0:ahcich5:0:0:0): CAM status: Command timeout (aprobe0:ahcich5:0:0:0): Error 5, Retries exhausted swap_pager: indefinite wait buffer: bufobj: 0, blkno: 1175296, size: 4096 swap_pager: indefinite wait buffer: bufobj: 0, blkno: 268223, size: 4096 Ideally, it would be nice if gmirror could instruct a chosen member disk to "fail fast", so that a different disk could be tried ASAP in case of any trouble. Only if all members cannot provide the requested data the mirror should switch to "try hard" mode. The more serious issue happened after the struggle was over: ada1 at ahcich5 bus 0 scbus6 target 0 lun 0 ada1: s/n GY3049963 detached GEOM_MIRROR: Request failed (error=6). ada1p2[READ(offset=1098641408, length=4096)] pass4 at ahcich5 bus 0 scbus6 target 0 lun 0 pass4: s/n GY3049963 detached GEOM_MIRROR: Device swap: provider ada1p2 disconnected. swap_pager: I/O error - pagein failed; blkno 1175296,size 4096, error 6 vm_fault: pager read error, pid 1310 (devd) pid 1310 (devd), jid 0, uid 0: exited on signal 10 (core dumped) It looks that the mirror did not do its job properly? It got ENXIO from one disk and it passed that up to a consumer (swap). I suspect that there wa a race between an I/O request getting ENXIO from a failed disk and an orphan event from the same disk. With only one member left the mirror may not realize that the ENXIO came from the detached disk, so it may think that there is no device left to re-try the request. -- Andriy Gapon