From nobody Tue Oct 12 19:56:40 2021 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 D91ED17FD8DA for ; Tue, 12 Oct 2021 19:56:58 +0000 (UTC) (envelope-from wlosh@bsdimp.com) Received: from mail-vk1-xa2c.google.com (mail-vk1-xa2c.google.com [IPv6:2607:f8b0:4864:20::a2c]) (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 1O1" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 4HTRJT3JRxz4nMR for ; Tue, 12 Oct 2021 19:56:57 +0000 (UTC) (envelope-from wlosh@bsdimp.com) Received: by mail-vk1-xa2c.google.com with SMTP id x207so238209vke.2 for ; Tue, 12 Oct 2021 12:56:57 -0700 (PDT) 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=oJZkU06BwyU9+sTfuEQ9DMkavrdMjFyB6zmANmkCLOA=; b=wjJoa/3b2RHuO9ttJZJpmWig3sPe4vodkM6Xag1AJ2IduEV2woRG/rBnn+O+YPl2C1 wS7I6/Pt9COqFYMf85863//9Tn3EpyJ0wEecXp3JnGcyKAIRayRJMfguYstJuBdzwa6K hPhQr7Vbu+o271yLFhyCQ+RtAgpBGqnGg/SD5jxonlJ87fxFPOVl7WTYYJVTe8E/wXBb jp2viAf7iH0lQReH0DG9ziW0mNu1WgK5ohLrMI7y+cpk8C7anjRVB8bT/1tLduH7MouL yM+RGIVariJ5fhk9zkBkwEeYzKGiBtJuvNBI3sA74iczjweukPQfZc8L4vBiLq5nmlZe UWPA== 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=oJZkU06BwyU9+sTfuEQ9DMkavrdMjFyB6zmANmkCLOA=; b=Lp5Mv1F88LgyPhMxPkZH7504WZovPOjuhxfDgsC8kCRYRD/VAZvymInfq8gT7NUo76 U6L5FcozHn/GaA5MFGVTrEvt9quPaZ6RBDIoTe23/w1kp7lgH9fSGFrBKE4g3EHacGUL Vm+j0PbcqdPI0n/jylgKokZHcYccdTSIpo0dS8PAJmZ7rG5Nwr0tLBSUuzFuU3LnOn/q UXl+q2zF0Q1C8C2VclzyYAmgPoEvLIBQu6IF2RrDrhwuwiAyRRneF1HE15rYZXE6xct3 q962iHYhWQ2KNrx3VY6ofTSqzFQMHZFQdfQoWTtDm7TTYSh6W+4xVL9P+Z4BVIphmjGm +muw== X-Gm-Message-State: AOAM5328YlcVahzVMI4G4A4lxAwYF3zVegKY7hmvLGE+cNg/V7xTLO/+ apOi2E/BUK3YxJfkUUWzUaF562M5ILGwJEczP5iCAQ== X-Google-Smtp-Source: ABdhPJwBtwTXtN/vTe/6BMdKLXe9TRkHEFUHmm9Ud72HnpDuPtZa3HK4p/cSy6bL7KuCKA5Xth7ZlhA11yKacyHw+7E= X-Received: by 2002:a1f:2d83:: with SMTP id t125mr29159743vkt.23.1634068611364; Tue, 12 Oct 2021 12:56:51 -0700 (PDT) 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: In-Reply-To: From: Warner Losh Date: Tue, 12 Oct 2021 13:56:40 -0600 Message-ID: Subject: Re: Dell Latitude 7400 - nvme0: Missing interrupt To: Pavel Timofeev Cc: Chuck Tuffli , freebsd-current Content-Type: multipart/alternative; boundary="0000000000001e8fb705ce2d3faa" X-Rspamd-Queue-Id: 4HTRJT3JRxz4nMR X-Spamd-Bar: -- Authentication-Results: mx1.freebsd.org; dkim=pass header.d=bsdimp-com.20210112.gappssmtp.com header.s=20210112 header.b="wjJoa/3b"; dmarc=none; spf=none (mx1.freebsd.org: domain of wlosh@bsdimp.com has no SPF policy when checking 2607:f8b0:4864:20::a2c) smtp.mailfrom=wlosh@bsdimp.com X-Spamd-Result: default: False [-2.99 / 15.00]; ARC_NA(0.00)[]; NEURAL_HAM_MEDIUM(-1.00)[-1.000]; RCVD_COUNT_TWO(0.00)[2]; R_DKIM_ALLOW(-0.20)[bsdimp-com.20210112.gappssmtp.com:s=20210112]; FROM_HAS_DN(0.00)[]; RCPT_COUNT_THREE(0.00)[3]; 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:+]; NEURAL_HAM_SHORT(-0.99)[-0.995]; RCVD_IN_DNSWL_NONE(0.00)[2607:f8b0:4864:20::a2c:from]; R_SPF_NA(0.00)[no SPF record]; FREEMAIL_TO(0.00)[gmail.com]; FORGED_SENDER(0.30)[imp@bsdimp.com,wlosh@bsdimp.com]; 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)[]; FREEMAIL_CC(0.00)[gmail.com,freebsd.org] X-ThisMailContainsUnwantedMimeParts: Y --0000000000001e8fb705ce2d3faa Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable One piece of data that would be good to have: nvmecontrol identify nvme0 There's an optional feature that none of my drives have, but that the Linux driver does oddly weird things when enabled. The output of that command will help me understand if that may be in play. Maybe we need to do oddly weird things too :) Warner On Sun, Oct 10, 2021 at 11:00 PM Warner Losh wrote: > > > On Sun, Oct 10, 2021 at 10:48 PM Pavel Timofeev wrote: > >> =D1=81=D0=B1, 9 =D0=BE=D0=BA=D1=82. 2021 =D0=B3. =D0=B2 14:59, Warner Lo= sh : >> >>> >>> >>> On Sat, Oct 9, 2021, 8:44 AM Pavel Timofeev wrote: >>> >>>> >>>> >>>> =D0=BF=D1=82, 8 =D0=BE=D0=BA=D1=82. 2021 =D0=B3. =D0=B2 14:49, Warner = Losh : >>>> >>>>> >>>>> >>>>> On Fri, Oct 8, 2021 at 2:42 PM Pavel Timofeev >>>>> wrote: >>>>> >>>>>> >>>>>> >>>>>> =D1=81=D0=B1, 21 =D0=B0=D0=B2=D0=B3. 2021 =D0=B3. =D0=B2 15:22, Warn= er Losh : >>>>>> >>>>>>> >>>>>>> >>>>>>> On Sat, Aug 21, 2021 at 3:06 PM Pavel Timofeev >>>>>>> wrote: >>>>>>> >>>>>>>> >>>>>>>> >>>>>>>> Warner Losh : >>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>>> On Fri, Aug 20, 2021 at 10:42 PM Pavel Timofeev >>>>>>>>> wrote: >>>>>>>>> >>>>>>>>>> Pavel Timofeev : >>>>>>>>>> >>>>>>>>>> > >>>>>>>>>> > Chuck Tuffli : >>>>>>>>>> > >>>>>>>>>> >> On Mon, Aug 16, 2021 at 7:43 PM Pavel Timofeev < >>>>>>>>>> timp87@gmail.com> wrote: >>>>>>>>>> >> > >>>>>>>>>> >> > Hello >>>>>>>>>> >> > I've got a Dell Latitude 7400 and tried installing the late= st >>>>>>>>>> >> 14.0-CURRENT >>>>>>>>>> >> > (main-n248636-d20e9e02db3) on it. >>>>>>>>>> >> > Despite other things the weird one which concerns me is >>>>>>>>>> >> > nvme0: Missing interrupt >>>>>>>>>> >> > message I get sometimes on the console. >>>>>>>>>> >> > It seems like I get it only after the reboot of the laptop, >>>>>>>>>> i. e. not >>>>>>>>>> >> > getting that message if I power cycle the laptop, at least = I >>>>>>>>>> haven't >>>>>>>>>> >> seen >>>>>>>>>> >> > them for now in such cases. >>>>>>>>>> >> > So when the laptop is rebooted I can't even take advantage = of >>>>>>>>>> >> > nvmecontrol(8) quickly. >>>>>>>>>> >> > Well, it still works, but it takes tens of seconds to retur= n >>>>>>>>>> the output. >>>>>>>>>> >> ... >>>>>>>>>> >> > dmesg when power cycled - >>>>>>>>>> >> > >>>>>>>>>> https://drive.google.com/file/d/1dB27oB1O2CcnZy6DvOOhmFO8SN8V8Sw= J >>>>>>>>>> >> > dmesg when rebooted - >>>>>>>>>> >> > >>>>>>>>>> https://drive.google.com/file/d/1DsKTMkihp_OmUcirByLaVO4o2mU38Bx= h >>>>>>>>>> >> >>>>>>>>>> >> I'm sort of curious about the time stamps for the log message= s >>>>>>>>>> in the >>>>>>>>>> >> failing case. Something like: >>>>>>>>>> >> >>>>>>>>>> >> $ grep "nv\(me\|d\)" /var/log/messages >>>>>>>>>> >> >>>>>>>>>> >> --chuck >>>>>>>>>> >> >>>>>>>>>> > >>>>>>>>>> > Well, I can't see timestamps in the verbose boot log. Am I >>>>>>>>>> missing some >>>>>>>>>> > configuration for that? >>>>>>>>>> > >>>>>>>>>> > $ grep "nv\(me\|d\)" /var/log/messages >>>>>>>>>> > nvme0: mem >>>>>>>>>> > >>>>>>>>>> 0xcc100000-0xcc103fff,0xcc105000-0xcc105fff,0xcc104000-0xcc104ff= f at device >>>>>>>>>> > 0.0 on pci6 >>>>>>>>>> > nvme0: attempting to allocate 5 MSI-X vectors (17 supported) >>>>>>>>>> > nvme0: using IRQs 133-137 for MSI-X >>>>>>>>>> > nvme0: CapLo: 0x140103ff: MQES 1023, CQR, TO 20 >>>>>>>>>> > nvme0: CapHi: 0x00000030: DSTRD 0, NSSRS, CSS 1, MPSMIN 0, >>>>>>>>>> MPSMAX 0 >>>>>>>>>> > nvme0: Version: 0x00010300: 1.3 >>>>>>>>>> > nvme0: Missing interrupt >>>>>>>>>> > nvme0: Missing interrupt >>>>>>>>>> > nvme0: Missing interrupt >>>>>>>>>> > nvme0: Missing interrupt >>>>>>>>>> > nvme0: Missing interrupt >>>>>>>>>> > nvme0: Missing interrupt >>>>>>>>>> > nvme0: Missing interrupt >>>>>>>>>> > nvme0: Missing interrupt >>>>>>>>>> > nvme0: Missing interrupt >>>>>>>>>> > nvme0: Missing interrupt >>>>>>>>>> > nvme0: Missing interrupt >>>>>>>>>> > nvme0: Missing interrupt >>>>>>>>>> > nvd0: NVMe namespace >>>>>>>>>> > GEOM: new disk nvd0 >>>>>>>>>> > nvd0: 488386MB (1000215216 512 byte sectors) >>>>>>>>>> > >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> Ah, sorry, provided wrong output. >>>>>>>>>> Here is what you requested: >>>>>>>>>> $ grep "nv\(me\|d\)" /var/log/messages >>>>>>>>>> Aug 21 04:34:36 nostromo kernel: nvme0: me= m >>>>>>>>>> 0xcc100000-0xcc103fff,0xcc105000-0xcc105fff,0xcc104000-0xcc104ff= f >>>>>>>>>> at device >>>>>>>>>> 0.0 on pci6 >>>>>>>>>> Aug 21 04:34:36 nostromo kernel: nvme0: attempting to allocate 5 >>>>>>>>>> MSI-X >>>>>>>>>> vectors (17 supported) >>>>>>>>>> Aug 21 04:34:36 nostromo kernel: nvme0: using IRQs 133-137 for >>>>>>>>>> MSI-X >>>>>>>>>> Aug 21 04:34:36 nostromo kernel: nvme0: CapLo: 0x140103ff: MQES >>>>>>>>>> 1023, CQR, >>>>>>>>>> TO 20 >>>>>>>>>> Aug 21 04:34:36 nostromo kernel: nvme0: CapHi: 0x00000030: DSTRD >>>>>>>>>> 0, NSSRS, >>>>>>>>>> CSS 1, MPSMIN 0, MPSMAX 0 >>>>>>>>>> Aug 21 04:34:36 nostromo kernel: nvme0: Version: 0x00010300: 1.3 >>>>>>>>>> Aug 21 04:34:36 nostromo kernel: nvme0: Missing interrupt >>>>>>>>>> Aug 21 04:34:36 nostromo kernel: nvme0: Missing interrupt >>>>>>>>>> Aug 21 04:34:36 nostromo kernel: nvme0: Missing interrupt >>>>>>>>>> Aug 21 04:34:36 nostromo kernel: nvd0: >>>>>>>>> 512GB> NVMe >>>>>>>>>> namespace >>>>>>>>>> Aug 21 04:34:36 nostromo kernel: GEOM: new disk nvd0 >>>>>>>>>> Aug 21 04:34:36 nostromo kernel: nvd0: 488386MB (1000215216 512 >>>>>>>>>> byte >>>>>>>>>> sectors) >>>>>>>>>> Aug 21 04:34:42 nostromo kernel: nvme0: Missing interrupt >>>>>>>>>> Aug 21 04:35:36 nostromo kernel: nvme0: Missing interrupt >>>>>>>>>> Aug 21 04:35:50 nostromo kernel: nvme0: Missing interrupt >>>>>>>>>> >>>>>>>>> >>>>>>>>> What happens if you set hw.nvme.use_nvd=3D0 and >>>>>>>>> hw.cam.nda.nvd_compat=3D1 >>>>>>>>> in the boot loader and reboot? Same thing except nda where nvd >>>>>>>>> was? Or does >>>>>>>>> it work? >>>>>>>>> >>>>>>>>> Something weird is going on in the interrupt assignment, I think, >>>>>>>>> but I >>>>>>>>> wanted to get any nvd vs nda issues out of the way first. >>>>>>>>> >>>>>>>>> Warner >>>>>>>>> >>>>>>>> >>>>>>>> Do you mean kern.cam.nda.nvd_compat instead >>>>>>>> of hw.cam.nda.nvd_compat? >>>>>>>> kern.cam.nda.nvd_compat is 1 by default now. >>>>>>>> >>>>>>>> So I tried to set hw.nvme.use_nvd to 1 as suggested, but I still >>>>>>>> see >>>>>>>> nvme0: Missing interrupt >>>>>>>> and now also >>>>>>>> Root mount waiting for: CAM >>>>>>>> messages besides those >>>>>>>> >>>>>>> >>>>>>> OK. That all makes sense. I'd forgotten that nvd_compat=3D1 by defa= ult >>>>>>> these >>>>>>> days. >>>>>>> >>>>>>> I'll take a look on monday starting at the differences in interrupt >>>>>>> assignment that >>>>>>> are apparent when you cold boot vs reboot. >>>>>>> >>>>>>> Thanks for checking... I'd hoped this was a cheap fix, but also >>>>>>> didn't really >>>>>>> expect it to be. >>>>>>> >>>>>>> Warner >>>>>>> >>>>>>> >>>>>> I've recently upgraded to main-n249974-17f790f49f5 and it got even >>>>>> worse now. >>>>>> So clean poweron works as before. >>>>>> But if rebooted nvme drive refuses to work, while before the code >>>>>> upgrade it was just complaining about missing interrupts. >>>>>> >>>>>> currently dmesg show this: >>>>>> nvme0: mem >>>>>> 0xcc100000-0xcc103fff,0xcc105000-0xcc105fff,0xcc104000-0xcc104fff at= device >>>>>> 0.0 on pci6 >>>>>> nvd0: NVMe namespace >>>>>> nvd0: 488386MB (1000215216 512 byte sectors) >>>>>> nvme0: mem >>>>>> 0xcc100000-0xcc103fff,0xcc105000-0xcc105fff,0xcc104000-0xcc104fff at= device >>>>>> 0.0 on pci6 >>>>>> >>>>> >>>>> Why is this showing up twice? Or is everything above this line left >>>>> over from the first, working boot? >>>>> >>>>> >>>>>> nvme0: RECOVERY_START 9585870784 vs 9367036288 >>>>>> nvme0: timeout with nothing complete, resetting >>>>>> nvme0: Resetting controller due to a timeout. >>>>>> nvme0: RECOVERY_WAITING >>>>>> nvme0: resetting controller >>>>>> nvme0: aborting outstanding admin command >>>>>> nvme0: IDENTIFY (06) sqid:0 cid:15 nsid:0 cdw10:00000001 >>>>>> cdw11:00000000 >>>>>> nvme0: ABORTED - BY REQUEST (00/07) sqid:0 cid:15 cdw0:0 >>>>>> nvme0: nvme_identify_controller failed! >>>>>> nvme0: waiting >>>>>> >>>>> >>>>> Clearly something bad is going on with the drive here... We looked >>>>> into the completion queues when we didn't get an interrupt and there = was >>>>> nothing complete there.... >>>>> >>>>> The only thing I can think of is that this means there's a phase erro= r >>>>> between the drive and the system. I recently removed a second reset a= nd >>>>> made it an option NVME_2X_RESET. Can you see if adding >>>>> 'options NVME_2X_RESET' to your kernel config fixes this? >>>>> >>>>> Warner >>>>> >>>>> >>>>>> nvme0: mem >>>>>> 0xcc100000-0xcc103fff,0xcc105000-0xcc105fff,0xcc104000-0xcc104fff at= device >>>>>> 0.0 on pci6 >>>>>> nvme0: RECOVERY_START 9362778467 vs 9361830561 >>>>>> nvme0: timeout with nothing complete, resetting >>>>>> nvme0: Resetting controller due to a timeout. >>>>>> nvme0: RECOVERY_WAITING >>>>>> nvme0: resetting controller >>>>>> nvme0: aborting outstanding admin command >>>>>> nvme0: IDENTIFY (06) sqid:0 cid:15 nsid:0 cdw10:00000001 >>>>>> cdw11:00000000 >>>>>> nvme0: ABORTED - BY REQUEST (00/07) sqid:0 cid:15 cdw0:0 >>>>>> nvme0: nvme_identify_controller failed! >>>>>> nvme0: waiting >>>>>> >>>>>> >>>> >>>> Sorry, it's showing twice due to multiple reboots. For one boot it's >>>> like: >>>> nvme0: mem >>>> 0xcc100000-0xcc103fff,0xcc105000-0xcc105fff,0xcc104000-0xcc104fff at d= evice >>>> 0.0 on pci6 >>>> nvme0: RECOVERY_START 9633303481 vs 9365971423 >>>> nvme0: timeout with nothing complete, resetting >>>> nvme0: Resetting controller due to a timeout. >>>> nvme0: RECOVERY_WAITING >>>> nvme0: resetting controller >>>> nvme0: aborting outstanding admin command >>>> nvme0: IDENTIFY (06) sqid:0 cid:15 nsid:0 cdw10:00000001 cdw11:0000000= 0 >>>> nvme0: ABORTED - BY REQUEST (00/07) sqid:0 cid:15 cdw0:0 >>>> nvme0: nvme_identify_controller failed! >>>> nvme0: waiting >>>> >>>> Well, neither Windows not Linux have any problems with the device. I >>>> understand they may be hiding it or workaround somehow. >>>> >>> >>> Yea, I'm trying to figure out why your machine is different than mine, >>> and what Windows or Linux do that is different. It may be dodgy hardwar= e, >>> but others have no trouble... >>> >>> I'll try setting NVME_2X_RESET in the kernel config and report back in = a >>>> while. >>>> >>> >>> Thanks. If it helps, that tells me something. If it doesn't, that tells >>> me something else. >>> >>> I suspect that it is somewhere else in the system, tbh, but I need to >>> find it systematically. >>> >>> Warner >>> >> >> Surprisingly, setting NVME_2X_RESET in the kernel config hasn't changed >> anything. I. e it didn't help. >> > > While it would have been nice to have this be the fix, I'm not that > surprised either. > It was the biggest change of late, apart from the big re-arrangement that > I'd done. > > So the other changes have moved from the occasional missing interrupt > message > (which the old code would get when a command wasn't completed in the > timeout > period, but that we found to be done when we scanned the completion queue= . > Now > the device is detected fine (as before), but then doesn't do I/O at all > (including not > completing the identify command!) and is worse. This is unexpected and I'= m > trying > understand what happens on reboot that 'changes'the working state and why > the > new code behaves so differently. > > Warner > --0000000000001e8fb705ce2d3faa--