On Sun, Oct 3, 2021 at 12:00 PM BALATON Zoltan <bala...@eik.bme.hu> wrote:
> On Sun, 3 Oct 2021, Howard Spoelstra wrote: > > On Sat, Oct 2, 2021 at 5:42 PM BALATON Zoltan <bala...@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 usb_ohci_td_too_many_pending 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_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_packet_status status=-6 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 ------------------------> last 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 usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37 usb_ohci_async_complete 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 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