Problems (timeouts) when testing usb-ohci with qemu

[Guenter Roeck]

Hi,

when testing usb-ohci with qemu's pci-ohci emulation, I keep getting
random usb interface timeouts. Sometimes the usb_hub_wq times out.

[    9.555666] Waiting for root device /dev/sda...
[   62.452625] INFO: task kworker/0:2:42 blocked for more than 30 seconds.
[   62.453036]       Tainted: G                 N 6.9.0-rc1-00305-geae7a41d2233 
#1
[   62.453393] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this 
message.
[   62.453778] task:kworker/0:2     state:D stack:0     pid:42    tgid:42    
ppid:2      flags:0x00000000
[   62.454700] Workqueue: usb_hub_wq hub_event
[   62.455137] Call Trace:
[   62.455416] [<c0b47836>] __schedule+0x35c/0xe00
[   62.455708] [<c0b4830c>] schedule+0x32/0x178
[   62.455906] [<c07da782>] usb_kill_urb+0xa8/0xda
[   62.456220] [<c07db53c>] usb_start_wait_urb+0xca/0xe2
[   62.456441] [<c07db5ee>] usb_control_msg+0x9a/0x102
[   62.456648] [<c07d3970>] hub_port_init+0x5de/0xb40
[   62.456851] [<c07d67fe>] hub_event+0xb90/0x1364
[   62.457049] [<c002ead6>] process_one_work+0x200/0x564

Sometimes there is an i/o scheduling timeout such as

[    6.361811] Run /sbin/init as init process
[   93.167039] INFO: task kworker/u4:0:10 blocked for more than 30 seconds.
[   93.167715]       Tainted: G                 N 6.9.0-rc5-00036-gaece0dd54838 
#4
[   93.168169] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this 
message.
[   93.168607] task:kworker/u4:0    state:D stack:0     pid:10    tgid:10    
ppid:2      flags:0x00000000
[   93.169602] Workqueue: scsi_tmf_0 scmd_eh_abort_handler
[   93.170278] Call Trace:
[   93.170584] [<c0b3a70e>] __schedule+0x358/0xd4e
[   93.170904] [<c0b3b136>] schedule+0x32/0x166
[   93.171161] [<c0b41d6c>] schedule_timeout+0xd8/0x10a
[   93.171420] [<c0b3ba0e>] __wait_for_common+0xce/0x1ce
[   93.171604] [<c0b3bb2a>] wait_for_completion+0x1c/0x24
[   93.171716] [<c0810a70>] command_abort_matching.part.0+0x38/0x52
[   93.171841] [<c0810ac0>] command_abort+0x36/0x70
[   93.171946] [<c06970a4>] scmd_eh_abort_handler+0xa6/0x192
...

This is not a new problem; I have seen it forever. Recently I spent some
time trying to understand the problem and found that the linux driver does
not always handle all ohci interupts. Since the interrupt is shared and
thus level triggered, that means that interrupts are still pending when
ohci_irq() exits. The interrupt core in Linux does not re-enter the
interrupt handler, presumably because it is marked as shared interrupt
and returns that the interrupt has been handled.

I found two possible fixes for the problem. One essentially mirrors the
code from ehci_irq(), the other adds a (bad) kludge into qemu. Both "fix"
or work around the problem.

Question is: What is actually wrong ? Something in the generic interrupt
handling code in Linux, something in the Linux usb-ohci driver, or
something in qemu ? Any idea how a proper fix might look like ?

Thanks,
Guenter

---
Linux hack:

diff --git a/drivers/usb/host/ohci-hcd.c b/drivers/usb/host/ohci-hcd.c
index 4f9982ecfb58..48d523e71ea0 100644
--- a/drivers/usb/host/ohci-hcd.c
+++ b/drivers/usb/host/ohci-hcd.c
@@ -883,6 +883,7 @@ static irqreturn_t ohci_irq (struct usb_hcd *hcd)
         * optimization of checking the LSB of hcca->done_head; it doesn't
         * work on all systems (edge triggering for OHCI can be a factor).
         */
+retry:
        ints = ohci_readl(ohci, &regs->intrstatus);
 
        /* Check for an all 1's result which is a typical consequence
@@ -982,6 +983,14 @@ static irqreturn_t ohci_irq (struct usb_hcd *hcd)
        }
        spin_unlock(&ohci->lock);
 
+       ints = ohci_readl(ohci, &regs->intrstatus);
+       ints &= ohci_readl(ohci, &regs->intrenable);
+       if (ints) {
+               pr_err("######## Interrupts still pending 0x%x mask 0x%x\n", 
ints,
+                      ohci_readl(ohci, &regs->intrenable));
+               goto retry;
+       }
+
        return IRQ_HANDLED;
 }

---
qemu hack:

 hw/usb/hcd-ohci.c | 11 +++++++++++
 hw/usb/hcd-ohci.h |  1 +
 2 files changed, 12 insertions(+)

diff --git a/hw/usb/hcd-ohci.c b/hw/usb/hcd-ohci.c
index fc8fc91a1d..99e52ad13a 100644
--- a/hw/usb/hcd-ohci.c
+++ b/hw/usb/hcd-ohci.c
@@ -267,6 +267,10 @@ static inline void ohci_intr_update(OHCIState *ohci)
         (ohci->intr_status & ohci->intr))
         level = 1;
 
+    if (level && ohci->level)
+        qemu_set_irq(ohci->irq, 0);
+
+    ohci->level = level;
     qemu_set_irq(ohci->irq, level);
 }
 
diff --git a/hw/usb/hcd-ohci.h b/hw/usb/hcd-ohci.h
index e1827227ac..6f82e72bd9 100644
--- a/hw/usb/hcd-ohci.h
+++ b/hw/usb/hcd-ohci.h
@@ -52,6 +52,7 @@ struct OHCIState {
     uint32_t ctl, status;
     uint32_t intr_status;
     uint32_t intr;
+    int level;
 
     /* memory pointer partition */
     uint32_t hcca;
-- 
2.39.2