From nobody Sun Feb 6 19:11:01 2022 X-Original-To: freebsd-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 CA4B119AC911 for ; Sun, 6 Feb 2022 19:11:00 +0000 (UTC) (envelope-from wlosh@bsdimp.com) Received: from mail-ua1-x933.google.com (mail-ua1-x933.google.com [IPv6:2607:f8b0:4864:20::933]) (using TLSv1.3 with cipher TLS_AES_128_GCM_SHA256 (128/128 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256 client-signature RSA-PSS (2048 bits) client-digest SHA256) (Client CN "smtp.gmail.com", Issuer "GTS CA 1D4" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 4JsJlS0r4wz4hpx for ; Sun, 6 Feb 2022 19:11:00 +0000 (UTC) (envelope-from wlosh@bsdimp.com) Received: by mail-ua1-x933.google.com with SMTP id b37so19574425uad.12 for ; Sun, 06 Feb 2022 11:11:00 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=bsdimp-com.20210112.gappssmtp.com; s=20210112; h=mime-version:references:in-reply-to:from:date:message-id:subject:to :cc; bh=OuEhUbD4Qes5muSSVLX+LqPMW3xMQ/NO1vqrO2KQIyo=; b=c/EC8QO5PVQ1ryQiCocEzi5b3BgAhweosIJ0W96dmupt/h8DwZ3AEBfiD7MLYBllCt 4VnYWY5bOyo0lOcIj9CK53D/xnDc0AUaPQNYEO6T1nMnmzj1MwCOGzNJAZysgHDxwk0/ i0/yDv/QlmDfeoCTrxORkqutAHUelb9jxGANCAJ1G3tUSBTFi7LyrAX7ES5bsw/ylNeD OQrHfR99wtKyhJFvV/XjVnay7GYRyCQ0chDlXfQ2bWoeuSzyWbbSdbO8Nd2j2SHWxMqL APPTMBK2bWWw28LBrxKzZx/KtGUL7uoJY8UGYBl+dnwTLJZevJ/Ci/e88xQJWNEzp4Zd VlXQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to:cc; bh=OuEhUbD4Qes5muSSVLX+LqPMW3xMQ/NO1vqrO2KQIyo=; b=stInNFLf25kjqALND7WBZrx5nWMJdxkBmtRzeNM+AYcDhCTFHgP7nD2Ao/TOyYDQlM XFF9KTybB66dwEzri2WKnG1SwIAwx4P2ajfEasOCHaY57QcOJqq1SRW9flquAUJXGRaE QfzTwqNoclHSacnnQ1+CCIiLOctuV7tiKJ8gGb9Iwdcw7XxlF/rblfepq9C9M51kR2ro kaShtDnSmZiEVeUeid14ktgNDEd0das1Ly8UnMbyVQlE7AA8qkWZZQelymJuCGfOjjRX bnr+YOi3T61eJXq+R13M9i7zWv3/xq409iLLSl6BvhhlGiQmY4LVqw1JI8xJFMwq5FxX vRfA== X-Gm-Message-State: AOAM533yhnvXuuvV+LfhJB/yGnkdZpiWhI2PU+oe03zpL1BzeGBpoiyB xgIBrDJnJJGB0e4feXBSne5M8GrAEvu+8GHKGWnWZ2f/s7QUyw== X-Google-Smtp-Source: ABdhPJwSFXuqA8Kbi2t2BDxsqdEDpgAAbiEg9fb4MDm3oPrs/7ezgwYH349qdz8Vya/WviWt9UkfH9cW84G448ycM00= X-Received: by 2002:a67:33c9:: with SMTP id z192mr3597651vsz.42.1644174659557; Sun, 06 Feb 2022 11:10:59 -0800 (PST) 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 References: <7e8459e4-d708-7750-402c-cda2adf6199f@freebsd.org> <60ebd011-c2b8-3524-1476-123f11128ffe@freebsd.org> In-Reply-To: <60ebd011-c2b8-3524-1476-123f11128ffe@freebsd.org> From: Warner Losh Date: Sun, 6 Feb 2022 12:11:01 -0700 Message-ID: Subject: Re: USB Disk Stalls on -current To: Sean Bruno Cc: freebsd-current Content-Type: multipart/alternative; boundary="00000000000088342d05d75e3e91" X-Rspamd-Queue-Id: 4JsJlS0r4wz4hpx X-Spamd-Bar: -- Authentication-Results: mx1.freebsd.org; dkim=pass header.d=bsdimp-com.20210112.gappssmtp.com header.s=20210112 header.b="c/EC8QO5"; dmarc=none; spf=none (mx1.freebsd.org: domain of wlosh@bsdimp.com has no SPF policy when checking 2607:f8b0:4864:20::933) smtp.mailfrom=wlosh@bsdimp.com X-Spamd-Result: default: False [-2.76 / 15.00]; ARC_NA(0.00)[]; NEURAL_HAM_MEDIUM(-1.00)[-0.997]; R_DKIM_ALLOW(-0.20)[bsdimp-com.20210112.gappssmtp.com:s=20210112]; FROM_HAS_DN(0.00)[]; NEURAL_HAM_LONG(-1.00)[-1.000]; MIME_GOOD(-0.10)[multipart/alternative,text/plain]; PREVIOUSLY_DELIVERED(0.00)[freebsd-current@freebsd.org]; DMARC_NA(0.00)[bsdimp.com]; TO_MATCH_ENVRCPT_SOME(0.00)[]; TO_DN_ALL(0.00)[]; DKIM_TRACE(0.00)[bsdimp-com.20210112.gappssmtp.com:+]; RCPT_COUNT_TWO(0.00)[2]; RCVD_IN_DNSWL_NONE(0.00)[2607:f8b0:4864:20::933:from]; NEURAL_HAM_SHORT(-0.77)[-0.767]; MLMMJ_DEST(0.00)[freebsd-current]; FORGED_SENDER(0.30)[imp@bsdimp.com,wlosh@bsdimp.com]; R_SPF_NA(0.00)[no SPF record]; MIME_TRACE(0.00)[0:+,1:+,2:~]; ASN(0.00)[asn:15169, ipnet:2607:f8b0::/32, country:US]; FROM_NEQ_ENVFROM(0.00)[imp@bsdimp.com,wlosh@bsdimp.com]; RCVD_TLS_ALL(0.00)[]; RCVD_COUNT_TWO(0.00)[2] X-ThisMailContainsUnwantedMimeParts: N --00000000000088342d05d75e3e91 Content-Type: text/plain; charset="UTF-8" On Sun, Feb 6, 2022 at 12:02 PM Sean Bruno wrote: > > > > > > > > So there's some tools you can use. For usb, there's usbdump that can > > get you the USB transactions. I've not used it enough to give more > details > > here. This will let you know what's going on, and when, on the USB > endpoint. > > > > You can also enable the CAM_IOSCHED stuff. This will allow you to get > > latency > > measurements for 'requests in the sim' which basically will tell you > > what your > > latency spread is for the drives. This will tell you if things are > > getting caught > > up in the USB layer, or after CAM's da driver completes the I/O request > > (granted, that's almost certainly not happening, but it will help you > > figure out > > what's going on and put numbers to the oddities you are seeing). > > > > Also, make sure you have good cables. I've had lots of hicups over the > > years from dodgy USB cables. Also make sure you have good, high quality > > enclosures. Many from the USB2 time-period are sketchy at best and I > > went through several at one point trying to find a good one. I'd be > > tempted to > > get USB 3 enclosures. I've had better luck with USB3 gear than USB2 gear > > here, but you need a USB-3 controller to get USB-3 speeds which might not > > be compatible with the NUC's built-in stuff (though my NUC has one USB3 > > port, there's lots of different models). > > > > Usually, though, I see weirdness associated with dmesg messages from > > usb, cam, etc when the hardware is on the sketch end. > > > > Warner > > I'm assuming that I have a fairly dodgy USB device, as the pauses seem > to correspond to this from CAM being emitted: > > Feb 6 11:56:43 alice kernel: (da0:umass-sim1:1:0:0): READ(10). CDB: 28 > 00 36 69 02 6e 00 00 80 00 > Feb 6 11:56:43 alice kernel: (da0:umass-sim1:1:0:0): CAM status: CCB > request completed with an error > Feb 6 11:56:43 alice kernel: (da0:umass-sim1:1:0:0): Retrying command, > 2 more tries remain > > > Things resume after this is emitted, but there is a substantial > (multiple minutes) pause here. I would assume that timeouts would fire > much quicker. > The default timeout is 60s. You can reduce that substantially by setting kern.cam.da.default_timeout to a smaller level. Disk operations completed within 5s these days, except spin ups. Heck, nearly all complete within 500ms. You might try setting this value to maybe 3 or 5 or 10 to see if that helps the hiccups without introducing extra retries when the load is heavy. The smaller values give a faster recovery, but too small a number may result in timeouts and errors under load. I think you need to set this as a tuneable. Warner --00000000000088342d05d75e3e91 Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable


=
On Sun, Feb 6, 2022 at 12:02 PM Sean = Bruno <sbruno@freebsd.org> = wrote:


>
>
> So there's some tools you can use. For usb, there's usbdump th= at can
> get you the USB transactions. I've not used it enough to give more= details
> here. This will let you know what's going on, and when, on the USB= endpoint.
>
> You can also enable the CAM_IOSCHED stuff. This will allow you to get =
> latency
> measurements for 'requests in the sim' which basically will te= ll you
> what your
> latency spread is for the drives. This will tell you if things are > getting caught
> up in the USB layer, or after CAM's da driver completes the I/O re= quest
> (granted, that's almost certainly not happening, but it will help = you
> figure out
> what's going on and put numbers to the oddities you are seeing). >
> Also, make sure you have good cables. I've had lots of hicups=C2= =A0over the
> years from dodgy USB cables. Also make sure you have good, high qualit= y
> enclosures. Many from the USB2 time-period are sketchy at best and I > went through several at one point trying to find a good one. I'd b= e
> tempted to
> get USB 3 enclosures. I've had better luck with USB3 gear than USB= 2 gear
> here, but you need a USB-3 controller to get USB-3 speeds which might = not
> be compatible with the NUC's built-in stuff (though my NUC has one= USB3
> port, there's lots of different models).
>
> Usually, though, I see weirdness associated with dmesg messages from > usb, cam, etc when the hardware is on the sketch end.
>
> Warner

I'm assuming that I have a fairly dodgy USB device, as the pauses seem =
to correspond to this from CAM being emitted:

Feb=C2=A0 6 11:56:43 alice kernel: (da0:umass-sim1:1:0:0): READ(10). CDB: 2= 8
00 36 69 02 6e 00 00 80 00
Feb=C2=A0 6 11:56:43 alice kernel: (da0:umass-sim1:1:0:0): CAM status: CCB =
request completed with an error
Feb=C2=A0 6 11:56:43 alice kernel: (da0:umass-sim1:1:0:0): Retrying command= ,
2 more tries remain


Things resume after this is emitted, but there is a substantial
(multiple minutes) pause here.=C2=A0 I would assume that timeouts would fir= e
much quicker.

The default timeout is 60= s.

You can reduce that substantially by setting ke= rn.cam.da.default_timeout
to a smaller level. Disk operations com= pleted within 5s these days,
except spin ups. Heck, nearly all co= mplete within 500ms. You
might try setting this value to maybe 3 = or 5 or 10 to see if that helps the
hiccups without introducing e= xtra retries when the load is heavy. The
smaller values give a fa= ster recovery, but too small a number may result
in timeouts and = errors under load. I think you need to set this as a tuneable.

Warner
--00000000000088342d05d75e3e91--