Hi there,

I've been debugging since a few days a situation where the NVMe CQ interrupt
remains asserted, but the host does not issue an MMIO write if doorbell buffering
is enabled. I've been tracing this back to what I believe is a missing CQ event
index update. We ran into this issue on Linux 7.1 with an older Qemu version
(v7.1 with backported fixes). I couldn't reproduce the issue with upstream Qemu
which makes me suspicious whether/where my observation based on a trace log
is flawed.

Regarding the Qemu version [1] we use, we are on a v7.1 fork where we backported
the following NVMe fixes:
* 5fb65529ef2ad: hw/nvme: Change alignment in dma functions for nvme_blk_*
* 248761f9c850f: hw/nvme: fix missing cq eventidx update
Other than that, there are no NVMe related changes on top of v7.1. We run
Qemu with the NVMe as Xilinx PCIe endpoint with level-triggered legacy-PCI
interrupts. So our cli args look like this:
-drive file=./my-rootfs.wic,if=none,id=nvme1,format=raw \
-device nvme,serial=1234,drive=nvme1,bus=pcie.0 \

The situation I believe to observe is:
---- from the commit message of the attached fix ----
Assume a situation where the interrupt is deasserted, so cq->head ==
cq->tail == x. A first CQE is posted, so cq->tail becomes x + 1 and the
interrupt is asserted as cq->tail != cq->head. The host is handling the
CQE and writes x + 1 to it its shadow doorbell. Before the host issues an
mmio doorbell write, another CQE is posted, so event index remains x,
cq->head becomes x + 1, cq->tail becomes x + 2 and the IRQ remains
asserted. Just after the CQE has been posted, the host checks if the
condition to issue an mmio doorbell write applies:
  new_shadow_db - event_idx <= old_shadow_db - new_shadow_db
with new_shadow_db == x + 1, event_idx == x and old_shadow_db == x.
So the host issues an mmio to write x + 1 to the doorbell. As cq->tail is
x + 2, the interrupt remains asserted. But now, after the host is done
with processing the second CQE, it won't issue another doorbell mmio write
as the above condition is not met due to the CQ event_idx still being x.
Thus, the interrupt remains pending.
---- end of from the commit message of the attached fix ----

Here is a trace of the situation where I believe above happens:
...
pci_nvme_rw_complete_cb cid 37025 blk 'nvme1'
pci_nvme_enqueue_req_completion cid 37025 cqid 1 dw0 0x0 dw1 0x0 status 0x0
pci_nvme_update_cq_eventidx cqid 1 new_eventidx 92  <---- First CQE gets posted
pci_nvme_shadow_doorbell_cq cqid 1 new_shadow_doorbell 92
pci_nvme_irq_pin pulsing IRQ pin    <---- interrupt gets asserted
pci_nvme_mmio_write addr 0x1008 data 0x5e size 4
pci_nvme_mmio_doorbell_sq sqid 1 new_tail 94
pci_nvme_shadow_doorbell_sq sqid 1 new_shadow_doorbell 94
...
pci_nvme_eventidx_sq sqid 1 new_eventidx 94
pci_nvme_shadow_doorbell_sq sqid 1 new_shadow_doorbell 94
pci_nvme_rw_cb cid 37178 blk 'nvme1'
pci_nvme_rw_complete_cb cid 37178 blk 'nvme1'
pci_nvme_enqueue_req_completion cid 37178 cqid 1 dw0 0x0 dw1 0x0 status 0x0
pci_nvme_update_cq_eventidx cqid 1 new_eventidx 92  <---- Second CQE, event index unchanged
pci_nvme_shadow_doorbell_cq cqid 1 new_shadow_doorbell 93  <---- CQ shadow doorbell has been updated by host
pci_nvme_irq_pin pulsing IRQ pin   <---- interrupt remains asserted
pci_nvme_mmio_write addr 0x100c data 0x5d size 4
pci_nvme_mmio_doorbell_cq cqid 1 new_head 93           <---- CQ doorbell mmio access updating doorbell
pci_nvme_mmio_write addr 0x1008 data 0x5f size 4
pci_nvme_mmio_doorbell_sq sqid 1 new_tail 95
...

The issue causes the NVMe interrupt to be disabled by Linux due to being
asserted:

[   24.829513] irq 15: nobody cared (try booting with the "irqpoll"
option)
[   24.830575] CPU: 0 UID: 0 PID: 0 Comm: swapper/0 Not tainted
7.1.0-gd8bb0e727297-dirty #
23 PREEMPT
[   24.831145] Hardware name: riscv-virtio,qemu (DT)
[   24.831402] Call Trace:
[   24.831810] [<ffffffff80027ff0>] dump_backtrace+0x30/0x50
[   24.832359] [<ffffffff80001802>] show_stack+0x42/0x60
[   24.832569] [<ffffffff80020e5a>] __dump_stack+0x2a/0x40
[   24.832763] [<ffffffff80020df8>] dump_stack_lvl+0x68/0xa0
[   24.832958] [<ffffffff80020e88>] dump_stack+0x18/0x20
[   24.833148] [<ffffffff80003e2e>] __report_bad_irq+0x4e/0x1c0
[   24.833348] [<ffffffff800df0b8>] note_interrupt+0x188/0x210
[   24.833544] [<ffffffff800db07a>] handle_irq_event+0x7a/0xb0
[   24.833736] [<ffffffff800e0b74>] handle_fasteoi_irq+0x154/0x260
[   24.833939] [<ffffffff800d9568>] generic_handle_domain_irq+0x38/0x60
[   24.834130] [<ffffffff805c40f4>] plic_handle_irq+0xf4/0x170
[   24.834322] [<ffffffff800d9568>] generic_handle_domain_irq+0x38/0x60
[   24.834514] [<ffffffff805bf632>] riscv_intc_irq+0x32/0x80
[   24.834701] [<ffffffff810d1f08>] handle_riscv_irq+0x38/0x60
...

If you find some time, I'd appreciate your feedback. It would help me
clarify where my understand is flawed.

Best,
Chris

[1] https://github.com/CHERI-Alliance/qemu/tree/codasp-head

Chris Gellermann (1):
  nvme/ctrl: Fix stale CQ event index causing interrupt storm

 hw/nvme/ctrl.c | 5 +++++
 1 file changed, 5 insertions(+)

--
2.47.3