NVMe Poll CQ on timeout

NVMe Poll CQ on timeout

[Bharat Kumar Gogada]

Hi All,

We are testing NVMe cards on ARM64 platform, the card uses MSI-X interrupts.
We are hitting following case in drivers/nvme/host/pci.c
/*
         * 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_DONE;
        }

Can anyone tell when does nvme_timeout gets invoked ?
In what cases we see this interrupt miss ?

We are seeing this issue only for reads with following fio command 
fio --name=randwrite --ioengine=libaio --iodepth=1 --rw=randread --bs=128k --direct=0 \
--size=128M --numjobs=3 --group_reporting --filename=/dev/nvme0n1

We are not seeing issue with --rw=randwrite for same size.

Please let us know what can cause this issue. 

Regards,
Bharat

Re: NVMe Poll CQ on timeout

[Keith Busch]

On Thu, Sep 19, 2019 at 01:47:50PM +0000, Bharat Kumar Gogada wrote:
> Hi All,
> 
> We are testing NVMe cards on ARM64 platform, the card uses MSI-X interrupts.
> We are hitting following case in drivers/nvme/host/pci.c
> /*
>          * 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_DONE;
>         }
> 
> Can anyone tell when does nvme_timeout gets invoked ?

Timeout is invoked when the driver didn't see a completion to a
submitted command.

> In what cases we see this interrupt miss ?

That usually happens for one of two reasons:

 1. The device didn't send any MSIx message for a CQE

 2. The device sent the MSIx message before posting the CQE

I've also seen h/w errata where the MSIx and CQE are re-ordered, which
can also lead to this.

A hardware trace would provide the most detailed view of what's
happening. You might be able to infer if you carefully account for
commands sent, interrupts received, and spurious interrupts detected.

> We are seeing this issue only for reads with following fio command 
> fio --name=randwrite --ioengine=libaio --iodepth=1 --rw=randread --bs=128k --direct=0 \
> --size=128M --numjobs=3 --group_reporting --filename=/dev/nvme0n1
> 
> We are not seeing issue with --rw=randwrite for same size.
> 
> Please let us know what can cause this issue. 

RE: NVMe Poll CQ on timeout

[Bharat Kumar Gogada]

> I recall we did observe issues like this when legacy interrupts were used, so
> the driver does try to use MSI/MSIx if possible.
> 
> The nvme_timeout() is called from the block layer when the driver didn't
> provide a completion within the timeout (default is 30 seconds for IO,
> 60 seconds for admin).
> 
> This message you're seeing means the device did indeed post a completion
> queue entry for the timed out command, but the driver believes it was never
> notified via interrupt to check the completion queue.
> 
> This means either one of two things happened: the interrupt was raised prior
> to the completion queue entry being written, or the interrupt was never
> raised in the first place.
> 
> It might be possible to determine which if you can read the values from
> /proc/irq/<irq#>/spurious and see if the "last_unhandled" aligns with the
> expected completion time.
> 
Thanks keith. We are seeing the condition for transactions greater than 256 KB.
We did try increase IO timeout to 60sec but we still see issue. 

We do see spurious interrupts as following:
count 53224
unhandled 15890
last_unhandled 4294917520 ms

If there are spurious interrupts, isn't the EP handler called more times 
and this might help EP driver to process pending completions. (Because as per the code in 4.14 EP
driver isn't checking any interrupt status register, it starts processing completion queues immediately
in interrupt handler)

If we have spurious why do we still see completion polled ?

Regards,
Bharat


> > > Hi,
> > >
> > > We are testing NVMe cards on ARM64 platform, the card uses legacy
> > > interrupts.
> > > Intermittently we are hitting following case in drivers/nvme/host/pci.c
> > >        /*
> > >          * 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;
> > >         }
> > >
> > > Can anyone tell when does nvme_timeout gets invoked ?
> > > What does "Did we miss an interrupt mean" ? Does it mean host
> > > missing to service a interrupt raised by EP card ?
> > >
> > > Regards,
> > > Bharat

Re: NVMe Poll CQ on timeout

[Keith Busch]

On Mon, May 07, 2018 at 06:57:54AM +0000, Bharat Kumar Gogada wrote:
> Hi,
> 
> Does anyone have any inputs ?

Hi,

I recall we did observe issues like this when legacy interrupts were
used, so the driver does try to use MSI/MSIx if possible.

The nvme_timeout() is called from the block layer when the driver didn't
provide a completion within the timeout (default is 30 seconds for IO,
60 seconds for admin).

This message you're seeing means the device did indeed post a completion
queue entry for the timed out command, but the driver believes it was
never notified via interrupt to check the completion queue.

This means either one of two things happened: the interrupt was raised
prior to the completion queue entry being written, or the interrupt was
never raised in the first place.

It might be possible to determine which if you can read the values from
/proc/irq/<irq#>/spurious and see if the "last_unhandled" aligns with
the expected completion time.

Thanks,
Keith

> > Hi,
> > 
> > We are testing NVMe cards on ARM64 platform, the card uses legacy
> > interrupts.
> > Intermittently we are hitting following case in drivers/nvme/host/pci.c
> >        /*
> >          * 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;
> >         }
> > 
> > Can anyone tell when does nvme_timeout gets invoked ?
> > What does "Did we miss an interrupt mean" ? Does it mean host missing to
> > service a interrupt raised by EP card ?
> > 
> > Regards,
> > Bharat

RE: NVMe Poll CQ on timeout

[Bharat Kumar Gogada]

Hi,

Does anyone have any inputs ?

Regards,
Bharat

> Hi,
> 
> We are testing NVMe cards on ARM64 platform, the card uses legacy
> interrupts.
> Intermittently we are hitting following case in drivers/nvme/host/pci.c
>        /*
>          * 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;
>         }
> 
> Can anyone tell when does nvme_timeout gets invoked ?
> What does "Did we miss an interrupt mean" ? Does it mean host missing to
> service a interrupt raised by EP card ?
> 
> Regards,
> Bharat
> 

NVMe Poll CQ on timeout

[Bharat Kumar Gogada]

Hi,

We are testing NVMe cards on ARM64 platform, the card uses legacy interrupts.
Intermittently we are hitting following case in drivers/nvme/host/pci.c
       /*
         * 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;
        }

Can anyone tell when does nvme_timeout gets invoked ?
What does "Did we miss an interrupt mean" ? Does it mean host missing
to service a interrupt raised by EP card ?

Regards,
Bharat