On Sun, 3 Oct 2021, Howard Spoelstra wrote:
> On Sat, Oct 2, 2021 at 5:42 PM BALATON Zoltan <balaton@eik.bme.hu> wrote:
>> I'm also not sure where's the problem (maybe we have multiple problems).
>> It also does not work with an emulated usb-audio device but that also
>> doesn't work with EHCI so it may have a problem by itself (UHCI also seems
>> to be broken on its own so it does not even work as much as OHCI and
>> EHCI). You've also said it worked with pass through with a different
>> device so maybe this only happens with some devices or some sequence of
>> things these devices are doing. Only allowing one async packet in OHCI
>> instead of allowing one per endpoint is just a guess that could cause
>> delays in processing other packets but eventually it should go through
>> unless one async packet never completes and blocks all later ones or the
>> delays introduced by this limitaion causes things to go in a way that
>> guests don't expect and thus fail.
>>
> After some sifting through the logs, I my interpretation of our issue is
> this:
> Too many pending is referring to endpoint 0 when something is not
> completed. Qemu permantly checks endpoint 4 for hid activity, skips when no
> interrupt occurs. You can see both intermittently in the 1st log below.
> Too many pending refers to qemu not being able to fully read/get the device
> descriptors from boot. The too many pending is "solved", with a click on a
> hid button. That leads to async complete, after which the only activity is
> to check for interrupts from the hid devices.
That sounds like an async packet waiting on ep 4 blocks communication on
ep 0 because we don't allow one active packet per ep in hcd-ohci as the
comment says so this may be fixed by implementing that. But I'm not sure
because this log did not include packet status. Maybe also enable
usb_packet_state traces to confirm this. I may try to fix this, I have an
idea how do it: I can pass the USBPacket back from the completion callback
via OHCIState to ohci_service_td() but have to find a way to replace the
various cancel calls that use the usb_packet from OHCIState now to stop
relying on that and do it by ep or whatever they have. This needs some
more thinking and understand the code and OHCI better.
I assume no more than one callback can be running at once so I can't get
completion for two packets at the same time, therefore one pointer to pass
back a packet is enough. I'll put an assert there and see what happens but
if somebody knows please advise.
> However, as the descriptors from endpoint 0 are not fully read from boot,
> endpoint 1 (the actual audio stream) is not available.
> Unplugging/plugging the usb device in combination with some hid interrupts
> (me pushing the volume button) can sometimes reload the configuration
> correctly, so endpoint 1 becomes available and sound can be played through
> it.
Could be if guest driver starts polling ep 4 while still trying to talk to
ep 0 which then fails due to packet waiting in async on ep 4. The emulated
usb-audio may be different, that does not have HID endpoint only ep 0 for
control and two audio ones and it seems to be detected but playing sound
does not work. Does -device usb-audio instead of passed through device
makes sound with your guest OSes or that has a separate problem?
Usb-audio works in MacOS 9.2 guest, but only for some seconds. After that the desktop becomes unresponsive. Icons disappear, mouse still moves but cannot activate anything. With via=pmu, log shows usb mouse/kbd still communicating.
I've seen something very similar happen when I attempt to stop and start usb support in Mac OS 9.2 with the headset passed through.
System sounds in Fedora 12 guest can be played.
New logging with package status shows:
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=-6
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_packet_status status=-6 --------------------------> note this is line 1282 in my log
The following then continues to line 17671
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
And is followed by:
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
The first async complete is then at 57456
It then takes some 4000 lines before a
usb_ohci_td_packet_status status=-6
usb_ohci_async_complete
happens (me clicking hid button)
Next I get:
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_packet_status status=-6
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37 ----> Line 107770
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
-----
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37 ---> Line 187472
usb_ohci_async_complete (me clicking hid button)
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_packet_status status=-6
En1 is then active from line 190303 (after unplug/replug)
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
Which is again solve by a hid button click:
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=-6
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=-6
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=-6
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_packet_status status=-6
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_async_complete
From here on there is intermittent en1 and en 4 traffic:
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_packet_status status=-6
and for good measure some:
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
and finally completing with ep 4 polling:
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
The last async complete is when I shut down the host ;-)
Best,
Howard