NVMe IO error due to abort..

NVMe IO error due to abort..

[Linus Torvalds]

Ok, so my nice XPS13 just failed to boot into the most recent git
kernel, and I initially thought that it was the usernamespace changes
that made systemd unhappy.

But after looking some more, it was actually that /home didn't mount
cleanly, and systemd was just being a complete ass about not making
that clear.

Why didn't /home mount cleanly? Odd. Journaling filesystems and all that jazz..

But it wasn't some unclean shutdown, it turned out to be an IO error
on shutdown:

  Feb 24 11:57:13 xps13.linux-foundation.org kernel: nvme nvme0: I/O 1
QID 2 timeout, aborting
  Feb 24 11:57:13 xps13.linux-foundation.org kernel: nvme nvme0: Abort
status: 0x0
  Feb 24 11:57:43 xps13.linux-foundation.org kernel: nvme nvme0: I/O 1
QID 2 timeout, reset controller
  Feb 24 11:57:43 xps13.linux-foundation.org kernel: nvme nvme0:
completing aborted command with status: fffffffc
  Feb 24 11:57:43 xps13.linux-foundation.org kernel:
blk_update_request: I/O error, dev nvme0n1, sector 953640304
  Feb 24 11:57:43 xps13.linux-foundation.org kernel: Aborting journal
on device dm-3-8.
  Feb 24 11:57:43 xps13.linux-foundation.org kernel: EXT4-fs error
(device dm-3): ext4_journal_check_start:60: Detected aborted journal
  Feb 24 11:57:43 xps13.linux-foundation.org kernel: EXT4-fs (dm-3):
Remounting filesystem read-only
  Feb 24 11:57:43 xps13.linux-foundation.org kernel: EXT4-fs error
(device dm-3): ext4_journal_check_start:60: Detected aborted journal

The XPS13 has a Toshiba nvme controller:

  NVME Identify Controller:
  vid     : 0x1179
  ssvid   : 0x1179
  sn      :         86CS102VT3MT
  mn      : THNSN51T02DU7 NVMe TOSHIBA 1024GB

and doing a "nvme smart-log" doesn't show any errors. What can I do to
help debug this? It's only happened once, but it's obviously a scary
situation.

I doubt the SSD is going bad, unless the smart data is entirely
useless. So I'm more thinking this might be a driver issue - I may
have made a mistake in enabling mq-deadline for both single and
multi-queue?

Are there known issues? Is there some logging/reporting outside of the
smart data I can do (there's a "nvme get-log" command, but I'm not
finding any information about how that would work).

I got it all working after a fsck, but having an unreliable disk in my
laptop is not a good feeling.

Help me, Obi-NVMe Kenobi, you're my only hope.

              Linus

NVMe IO error due to abort..

[Linus Torvalds]

On Fri, Feb 24, 2017 at 12:39 PM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
>
> But it wasn't some unclean shutdown, it turned out to be an IO error
> on shutdown:

I take that "on shutdown" part back.

It was close to when I ended up rebooting (which was unrelated to the
IO error - I didn't notice that IO error until several boots later),
but it seems to have been a couple of minutes before.

So it might have been during my compiling the kernel, although looking
at the logs the error actually seems to have affected the chrome
browser database file, because there are "Cookie sqlite error XYZ"
messages in the system log right after the kernel error messages.

Maybe triggered by something like flush command associated with fsync
on the sqlite file, while there was a fair amount of disk activity
from the kernel build?

I dunno. My logs have nothing like this happening before on this
machine, which together with the lack of smart errors from the disk is
why I'd be inclined to blame something new during this merge window.

                   Linus

NVMe IO error due to abort..

[Jens Axboe]

On 02/24/2017 01:39 PM, Linus Torvalds wrote:
> Ok, so my nice XPS13 just failed to boot into the most recent git
> kernel, and I initially thought that it was the usernamespace changes
> that made systemd unhappy.
> 
> But after looking some more, it was actually that /home didn't mount
> cleanly, and systemd was just being a complete ass about not making
> that clear.
> 
> Why didn't /home mount cleanly? Odd. Journaling filesystems and all that jazz..
> 
> But it wasn't some unclean shutdown, it turned out to be an IO error
> on shutdown:
> 
>   Feb 24 11:57:13 xps13.linux-foundation.org kernel: nvme nvme0: I/O 1
> QID 2 timeout, aborting
>   Feb 24 11:57:13 xps13.linux-foundation.org kernel: nvme nvme0: Abort
> status: 0x0
>   Feb 24 11:57:43 xps13.linux-foundation.org kernel: nvme nvme0: I/O 1
> QID 2 timeout, reset controller
>   Feb 24 11:57:43 xps13.linux-foundation.org kernel: nvme nvme0:
> completing aborted command with status: fffffffc
>   Feb 24 11:57:43 xps13.linux-foundation.org kernel:
> blk_update_request: I/O error, dev nvme0n1, sector 953640304
>   Feb 24 11:57:43 xps13.linux-foundation.org kernel: Aborting journal
> on device dm-3-8.
>   Feb 24 11:57:43 xps13.linux-foundation.org kernel: EXT4-fs error
> (device dm-3): ext4_journal_check_start:60: Detected aborted journal
>   Feb 24 11:57:43 xps13.linux-foundation.org kernel: EXT4-fs (dm-3):
> Remounting filesystem read-only
>   Feb 24 11:57:43 xps13.linux-foundation.org kernel: EXT4-fs error
> (device dm-3): ext4_journal_check_start:60: Detected aborted journal
> 
> The XPS13 has a Toshiba nvme controller:
> 
>   NVME Identify Controller:
>   vid     : 0x1179
>   ssvid   : 0x1179
>   sn      :         86CS102VT3MT
>   mn      : THNSN51T02DU7 NVMe TOSHIBA 1024GB
> 
> and doing a "nvme smart-log" doesn't show any errors. What can I do to
> help debug this? It's only happened once, but it's obviously a scary
> situation.
> 
> I doubt the SSD is going bad, unless the smart data is entirely
> useless. So I'm more thinking this might be a driver issue - I may
> have made a mistake in enabling mq-deadline for both single and
> multi-queue?
> 
> Are there known issues? Is there some logging/reporting outside of the
> smart data I can do (there's a "nvme get-log" command, but I'm not
> finding any information about how that would work).
> 
> I got it all working after a fsck, but having an unreliable disk in my
> laptop is not a good feeling.
> 
> Help me, Obi-NVMe Kenobi, you're my only hope.

Very strange... The current series has seen literally weeks of
continuous testing on NVMe, both on my test box (with 4 different
drives) and I run it on my X1 laptop with nvme-as-root constantly too.
I'm running -git as if this morning on it now, with for-linus pulled in.

You should be fine with mq-deadline running the drive, even if it is
multiqueue. That's what I run on my laptop as well for test purposes,
and the majority of the runtime testing has been that configuration as
well, regardless of number of queues.

Is it reproducible? If so, you could try with mq-deadline. In testing,
the only oddness I've seen has been when we inadvertently issue a
request on the wrong hardware queue. And if that is the case, then
moving away from mq-deadline could change that behavior for you.

As to your flush theory, at least my laptop drive claims write back
caching and should see full flushes as well. I've seen nothing like this
on it, it's been rock solid. It would be useful if we dumped more about
the request on abort, though...

-- 
Jens Axboe

NVMe IO error due to abort..

[Linus Torvalds]

On Fri, Feb 24, 2017 at 12:56 PM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
>
> I dunno. My logs have nothing like this happening before on this
> machine, which together with the lack of smart errors from the disk is
> why I'd be inclined to blame something new during this merge window.

.. and literally within a minute of sending that email, it happened again.

And it was just after the kernel compile finished.

I think I'll go back to an older kernel and make sure I don't have
that mq-deadline enabled.

                 Linus

NVMe IO error due to abort..

[Linus Torvalds]

On Fri, Feb 24, 2017 at 1:02 PM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
>
> And it was just after the kernel compile finished.

Timing-wise, it might be the IO flushing after the biggest final link
or something. Still, that's really not all that heavy IO, but it might
trigger something.

Maybe it's even the same use-after-free with md that Bart has seen.
That's new to this merge window, isn't it?

                    Linus

NVMe IO error due to abort..

[Jens Axboe]

On Feb 24, 2017,@2:09 PM, Linus Torvalds <torvalds@linux-foundation.org> wrote:
> 
> On Fri, Feb 24, 2017 at 1:02 PM, Linus Torvalds
> <torvalds@linux-foundation.org> wrote:
>> 
>> And it was just after the kernel compile finished.
> 
> Timing-wise, it might be the IO flushing after the biggest final link
> or something. Still, that's really not all that heavy IO, but it might
> trigger something.
> 
> Maybe it's even the same use-after-free with md that Bart has seen.
> That's new to this merge window, isn't it?

Yes, that one is a regression in this window. And you are using dm... You could try and pull my for-linus and see if that changes anything for you?

NVMe IO error due to abort..

[Jens Axboe]

On 02/24/2017 02:16 PM, Jens Axboe wrote:
> 
> On Feb 24, 2017,@2:09 PM, Linus Torvalds <torvalds@linux-foundation.org> wrote:
>>
>> On Fri, Feb 24, 2017 at 1:02 PM, Linus Torvalds
>> <torvalds@linux-foundation.org> wrote:
>>>
>>> And it was just after the kernel compile finished.
>>
>> Timing-wise, it might be the IO flushing after the biggest final link
>> or something. Still, that's really not all that heavy IO, but it might
>> trigger something.
>>
>> Maybe it's even the same use-after-free with md that Bart has seen.
>> That's new to this merge window, isn't it?
> 
> Yes, that one is a regression in this window. And you are using dm...
> You could try and pull my for-linus and see if that changes anything
> for you?

BTW, when/if you do that, note that you would now have to set
mq-deadline as the scheduler. Might be worth running with the default
first, then switch to mq-deadline to see if it reproduces, once you are
confident that it didn't trigger without.

# echo mq-deadline > /sys/block/nvme0n1/queue/scheduler

And below is the branch info. I was going to send this in pretty soon
anyway, but lets see what happens.


  git://git.kernel.dk/linux-block.git for-linus


----------------------------------------------------------------
Andy Lutomirski (2):
      nvme: Add a quirk mechanism that uses identify_ctrl
      nvme: Enable autonomous power state transitions

Christoph Hellwig (1):
      scsi: zero per-cmd driver data before each I/O

Christophe JAILLET (1):
      nvmet-rdma: Fix error handling

Colin Ian King (1):
      nvme: admin-cmd: fix spelling mistake: "Counld" -> "Could"

Daniel Roschka (1):
      nvme: detect NVMe controller in recent MacBooks

James Smart (2):
      nvmet_fc: cleanup of abort flag processing in fcp_op_done
      nvme-fc: don't bother to validate ioccsz and iorcsz

Jan Kara (3):
      block: Move bdev_unhash_inode() after invalidate_partition()
      block: Unhash also block device inode for the whole device
      block: Revalidate i_bdev reference in bd_aquire()

Jens Axboe (2):
      block: get rid of blk-mq default scheduler choice Kconfig entries
      dm-rq: don't dereference request payload after ending request

Johannes Thumshirn (1):
      nvme: make nvmf_register_transport require a create_ctrl callback

Jon Derrick (4):
      block/sed: Use ssize_t on atom parsers to return errors
      block/sed: Add helper to qualify response tokens
      block/sed: Check received header lengths
      block/sed: Embed function data into the function sequence

Josef Bacik (3):
      nbd: cleanup ioctl handling
      nbd: set the logical and physical blocksize properly
      nbd: cleanup workqueue on error properly

Keith Busch (3):
      nvme/pci: Disable on removal when disconnected
      nvme/core: Fix race kicking freed request_queue
      nvme/pci: No special case for queue busy on IO

Max Gurtovoy (5):
      nvmet: avoid dereferencing nvmet_req
      nvme: add semicolon in nvme_command setting
      nvme-rdma: move nvme cm status helper to .h file
      nvmet-rdma: use nvme cm status helper
      nvme-rdma: add support for host_traddr

Omar Sandoval (3):
      scsi_transport_sas: fix BSG ioctl memory corruption
      blk-mq: use sbq wait queues instead of restart for driver tags
      blk-mq-sched: separate mark hctx and queue restart operations

Parav Pandit (1):
      nvme: Use CNS as 8-bit field and avoid endianness conversion

Sagi Grimberg (2):
      nvmet: Make cntlid globally unique
      nvme: Make controller state visible via sysfs

Scott Bauer (3):
      block/sed-opal: Introduce free_opal_dev to free the structure and clean up state
      nvme/pci: re-check security protocol support after reset
      block/sed-opal: Propagate original error message to userland.

Tobin C. Harding (3):
      cciss: Fix checkpatch TRAILING_WHITESPACE
      cciss: Fix checkpatch OPEN_BRACE
      cciss: Remove kmalloc cast

 block/Kconfig.iosched             |  44 ---
 block/blk-mq-sched.c              |  29 +-
 block/blk-mq-sched.h              |  26 +-
 block/blk-mq.c                    |  64 ++++-
 block/elevator.c                  |  19 +-
 block/genhd.c                     |   4 +-
 block/sed-opal.c                  | 577 +++++++++++++++++---------------------
 drivers/block/cciss_scsi.c        | 182 ++++++------
 drivers/block/nbd.c               | 307 ++++++++++----------
 drivers/md/dm-rq.c                |   6 +-
 drivers/nvme/host/core.c          | 257 ++++++++++++++++-
 drivers/nvme/host/fabrics.c       |   7 +-
 drivers/nvme/host/fabrics.h       |   2 +-
 drivers/nvme/host/fc.c            |  15 +-
 drivers/nvme/host/nvme.h          |  12 +
 drivers/nvme/host/pci.c           |  27 +-
 drivers/nvme/host/rdma.c          |  48 ++--
 drivers/nvme/target/admin-cmd.c   |   4 +-
 drivers/nvme/target/core.c        |  10 +-
 drivers/nvme/target/discovery.c   |   4 +-
 drivers/nvme/target/fabrics-cmd.c |   6 +-
 drivers/nvme/target/fc.c          |   8 +-
 drivers/nvme/target/loop.c        |   3 +-
 drivers/nvme/target/nvmet.h       |   1 -
 drivers/nvme/target/rdma.c        |   7 +-
 drivers/scsi/scsi_lib.c           |   2 +-
 drivers/scsi/scsi_transport_sas.c |  24 +-
 fs/block_dev.c                    |  11 +-
 include/linux/blk-mq.h            |   2 +
 include/linux/nvme-rdma.h         |  24 ++
 include/linux/nvme.h              |  10 +-
 include/linux/sed-opal.h          |   5 +
 32 files changed, 986 insertions(+), 761 deletions(-)

-- 
Jens Axboe

NVMe IO error due to abort..

[Linus Torvalds]

On Fri, Feb 24, 2017@1:35 PM, Jens Axboe <axboe@kernel.dk> wrote:
>
> And below is the branch info. I was going to send this in pretty soon
> anyway, but lets see what happens.
>
>   git://git.kernel.dk/linux-block.git for-linus

Can you give me an overview of this all for the merge message. Might
as well merge this properly regardless.

I'm currently just building things in a loop on the old Fedora kernel,
just to verify stability (I had already pruned away my own 4.10 kernel
due to the earlier "git bisect" I did on that machine due to the
touchpad issue earlier in the merge window, so I'm using the distro
kernel just to verify that it really isn't any new hw issue).

I'm pretty sure the hw is fine, but I'll do that a bit more, before I
go back to current head of git for testing.

But that means I might as well just have this all already merged
(which I do on my main desktop that has so far not shown any signs of
this issue).

                   Linus

NVMe IO error due to abort..

[Jens Axboe]

On 02/24/2017 02:55 PM, Linus Torvalds wrote:
> On Fri, Feb 24, 2017@1:35 PM, Jens Axboe <axboe@kernel.dk> wrote:
>>
>> And below is the branch info. I was going to send this in pretty soon
>> anyway, but lets see what happens.
>>
>>   git://git.kernel.dk/linux-block.git for-linus
> 
> Can you give me an overview of this all for the merge message. Might
> as well merge this properly regardless.

Yes sure, this pull request contains:

- NVMe updates and fixes that missed the first pull request. This
  includes bug fixes, and support for autonomous power management.

- Fix from Christoph for missing clear of the request payload,
  causing a problem with (at least) the storvsc driver.

- Further fixes for the queue/bdi life time issues from Jan.

- The Kconfig mq scheduler update from me.

- Fixing a use-after-free in dm-rq, spotted by Bart, introduced
  in this merge window.

- Three fixes for nbd from Josef.

- Bug fix from Omar, fixing a bug in sas transport code that
  oopses when bsg ioctls were used. From Omar.

- Improvements to the queue restart and tag wait from from
  Omar.

- Set of fixes for the sed/opal code from Scott.

- Three trivial patches to cciss from Tobin

> I'm currently just building things in a loop on the old Fedora kernel,
> just to verify stability (I had already pruned away my own 4.10 kernel
> due to the earlier "git bisect" I did on that machine due to the
> touchpad issue earlier in the merge window, so I'm using the distro
> kernel just to verify that it really isn't any new hw issue).
> 
> I'm pretty sure the hw is fine, but I'll do that a bit more, before I
> go back to current head of git for testing.
> 
> But that means I might as well just have this all already merged
> (which I do on my main desktop that has so far not shown any signs of
> this issue).

It's a puzzling issue. Let me know how it goes with the above merge, and
I can add some debug code to try and narrow this down.

-- 
Jens Axboe

NVMe IO error due to abort..

[Jens Axboe]

Hi,

Since I might not be too available later in the day, here's a debug
patch that might help us figure out where things are going wrong.
It's against master+for-linus. It has two parts:

- Debug check to see if we are issuing a request on the wrong hw
  queue for nvme.

- Timeout patch from Keith, that shows if we missed a completion
  or not.


diff --git a/block/blk-core.c b/block/blk-core.c
index b9e857f4afe8..64ace6095f40 100644
--- a/block/blk-core.c
+++ b/block/blk-core.c
@@ -147,15 +147,18 @@ static void req_bio_endio(struct request *rq, struct bio *bio,
 
 void blk_dump_rq_flags(struct request *rq, char *msg)
 {
-	printk(KERN_INFO "%s: dev %s: flags=%llx\n", msg,
+	printk(KERN_INFO "%s: dev %s: flags=%llx/%llx\n", msg,
 		rq->rq_disk ? rq->rq_disk->disk_name : "?",
-		(unsigned long long) rq->cmd_flags);
+		(unsigned long long) rq->cmd_flags,
+		(unsigned long long) rq->rq_flags);
 
 	printk(KERN_INFO "  sector %llu, nr/cnr %u/%u\n",
 	       (unsigned long long)blk_rq_pos(rq),
 	       blk_rq_sectors(rq), blk_rq_cur_sectors(rq));
 	printk(KERN_INFO "  bio %p, biotail %p, len %u\n",
 	       rq->bio, rq->biotail, blk_rq_bytes(rq));
+	printk(KERN_INFO "  tag=%d, internal_tag=%d\n",
+		rq->tag, rq->internal_tag);
 }
 EXPORT_SYMBOL(blk_dump_rq_flags);
 
diff --git a/drivers/nvme/host/pci.c b/drivers/nvme/host/pci.c
index 57a1af52b06e..dd38a814c721 100644
--- a/drivers/nvme/host/pci.c
+++ b/drivers/nvme/host/pci.c
@@ -46,6 +46,7 @@
 #include <linux/sed-opal.h>
 
 #include "nvme.h"
+#include "../../block/blk-mq.h"
 
 #define NVME_Q_DEPTH		1024
 #define NVME_AQ_DEPTH		256
@@ -582,6 +583,9 @@ static int nvme_queue_rq(struct blk_mq_hw_ctx *hctx,
 	struct nvme_command cmnd;
 	int ret = BLK_MQ_RQ_QUEUE_OK;
 
+	if (WARN_ON_ONCE(hctx != blk_mq_map_queue(req->q, req->mq_ctx->cpu)))
+		blk_dump_rq_flags(req, "nvme hctx mismatch");
+
 	/*
 	 * If formated with metadata, require the block layer provide a buffer
 	 * unless this namespace is formated such that the metadata can be
@@ -745,10 +749,8 @@ static irqreturn_t nvme_irq_check(int irq, void *data)
 	return IRQ_NONE;
 }
 
-static int nvme_poll(struct blk_mq_hw_ctx *hctx, unsigned int tag)
+static int __nvme_poll(struct nvme_queue *nvmeq, unsigned int tag)
 {
-	struct nvme_queue *nvmeq = hctx->driver_data;
-
 	if (nvme_cqe_valid(nvmeq, nvmeq->cq_head, nvmeq->cq_phase)) {
 		spin_lock_irq(&nvmeq->q_lock);
 		__nvme_process_cq(nvmeq, &tag);
@@ -761,6 +763,13 @@ static int nvme_poll(struct blk_mq_hw_ctx *hctx, unsigned int tag)
 	return 0;
 }
 
+static int nvme_poll(struct blk_mq_hw_ctx *hctx, unsigned int tag)
+{
+	struct nvme_queue *nvmeq = hctx->driver_data;
+
+	return __nvme_poll(nvmeq, tag);
+}
+
 static void nvme_pci_submit_async_event(struct nvme_ctrl *ctrl, int aer_idx)
 {
 	struct nvme_dev *dev = to_nvme_dev(ctrl);
@@ -859,6 +868,16 @@ static enum blk_eh_timer_return nvme_timeout(struct request *req, bool reserved)
 	struct nvme_command cmd;
 
 	/*
+	 * Did we miss an interrupt?
+	 */
+	if (__nvme_poll(nvmeq, req->tag)) {
+		dev_warn(dev->ctrl.device,
+			 "I/O %d QID %d timeout, completion polled\n",
+			 req->tag, nvmeq->qid);
+		return BLK_EH_HANDLED;
+	}
+
+	/*
 	 * Shutdown immediately if controller times out while starting. The
 	 * reset work will see the pci device disabled when it gets the forced
 	 * cancellation error. All outstanding requests are completed on

-- 
Jens Axboe

NVMe IO error due to abort..

[Linus Torvalds]

On Fri, Feb 24, 2017@3:03 PM, Jens Axboe <axboe@kernel.dk> wrote:
>
> Since I might not be too available later in the day, here's a debug
> patch that might help us figure out where things are going wrong.
> It's against master+for-linus.

Ok, applied. I'm building and starting to test now. Couldn't see
anything strange with an older kernel, so I continue to believe that
the hardware is fine.

Of course, in the meantime the default scheduler has also changed, so
I won't be testing just the fixes and this extended debug patch. We'll
see what happens. I'll leave the scheduler at NOOP for a while.

I may have been able to reproduce it once, but I'm not sure how easily
I'll repro it again, so..

                  Linus

NVMe IO error due to abort..

[Linus Torvalds]

On Fri, Feb 24, 2017 at 3:08 PM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
> I may have been able to reproduce it once, but I'm not sure how easily
> I'll repro it again, so..

I'm not seeing it with current git and the NOOP scheduler, at least
with a few builds and trying to do what I did to get it to happen last
time.

But I think I'll continue to use this configuration for the rest of
the merge window just to make sure it's stable. I may not have hit the
right trigger for the problem.

                   Linus

NVMe IO error due to abort..

[Jens Axboe]

On 02/24/2017 05:47 PM, Linus Torvalds wrote:
> On Fri, Feb 24, 2017 at 3:08 PM, Linus Torvalds
> <torvalds@linux-foundation.org> wrote:
>> I may have been able to reproduce it once, but I'm not sure how easily
>> I'll repro it again, so..
> 
> I'm not seeing it with current git and the NOOP scheduler, at least
> with a few builds and trying to do what I did to get it to happen last
> time.
> 
> But I think I'll continue to use this configuration for the rest of
> the merge window just to make sure it's stable. I may not have hit the
> right trigger for the problem.

I have an XPS13 sitting that I don't use anymore. It's nvme as well, but
I don't think it's a Toshiba drive (nor is it 1TB). I will fire that up
with the new kernel as well and see if I catch anything. But it's most
puzzling if this is related to the drive, since I've run this on lots of
other nvme drives. I'm more inclined to think it's related to your dm
setup.

It's fine if you run the rest of the merge window like that, hopefully
I'll get something concrete out of some testing with dm.

-- 
Jens Axboe

NVMe IO error due to abort..

[Aurelien ROUGEMONT]