On Fri, 6 Jul 2018, R0b0t1 wrote: > On Thu, Jul 5, 2018 at 9:27 AM, Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> wrote: > > On Wed, 4 Jul 2018, R0b0t1 wrote: > > > >> On Sun, Jul 1, 2018 at 9:12 AM, Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> wrote: > >> > On Sat, 30 Jun 2018, R0b0t1 wrote: > >> > > >> >> The problem seems more noticeable when using the Python libusb > >> >> bindings but it still exists when using libusb directly. Can anyone > >> >> suggest what to look into? > >> > > >> > Have you tried using usbmon to capture the data as it is received by > >> > the kernel? > >> > > >> > >> Thank you for the suggestion. Having looked at usbmon output it > >> appears the kernel is receiving all zero packets for some transfers. > >> It also looks like some packets are dropped, but I am not sure how to > >> tell. Are blank transfers dropped data also? > > > > It would help if you posted a few examples. Isochronous packets are > > different from other kinds; to interpret them properly you need to look > > at the frame descriptors. > > > > This message was resent. The list has been eating my messages. It > seems like no attachments besides text/plain are accepted, which is > unfortunate because it means I can not include a full log. Log at end. > Two groups of zero filled transfers was attached. Good grief! I just asked for a couple of examples, not 300 KB of them! > I'll attach a recording. The beginning and end will have keystrokes > used to launch the recording program. > > There are bad transfers right at the start, but I believe this has > more to do with the issue I saw where single transfers did not > complete properly. (Note all bad transfers I am talking about are > marked as having completed properly by libusb.) As far as I can tell, all the transfers did complete properly. I didn't find any where the completion line contained an error code. > >> If I try to reconstitute the audio stream by ignoring all zero packets > >> the stream still experiences pops and clicks though they are much > >> quieter. That is the best indication I have that packets are being > >> dropped. The discontinuities in the waves lead to the pops and clicks. > > > > There are a few reasons why isochronous packets may get dropped. > > Possibly the host driver did not ask for them in time. And possibly > > the peripheral wasn't able to send them in time. > > > > Well - I can note that this problem persists with libusb under > Windows. But the most interesting thing is that the same firmware > produces audio which is received by Linux using Audacity with no > popping or clicking when the device registers as audio class. This is > why in my original message I brought to attention that the firmware > does not implement stream resychronization. The transfer issues may > not be cause by my use of only the data endpoint. > > It seems like the error conditions do not occur due to skipped packets > (i.e. transfers are sequential). The driver seems to be returning > transfers of length zero and transfers of the proper length filled > with zeros. Can anyone verify this? Yes, that's what the usbmon trace shows. > I will see what I can find debugging the device, but guesses are > appreciated. PyUSB also turns out to not be a great binding for > troubleshooting so I will update my C code with the tests I am doing. > > Thanks in advance, > R0b0t1 > > --- > Skipping some initial unrelated stuff... > ffff9c3975947a00 2268925206 S Zi:3:094:1 -115:1:0 1 -18:0:200 200 < > ffff9c3975947a00 2268925750 C Zi:3:094:1 0:1:1130:0 1 0:0:0 0 This may indicate a minor problem right at the start. The device apparently sent a packet containing no data (zero length). > ffff9c3975947a00 2268925896 S Zi:3:094:1 -115:1:0 1 -18:0:200 200 < > ffff9c3975947a00 2268926874 C Zi:3:094:1 0:1:1130:0 1 0:0:192 192 = > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 > ffff9c3975947a00 2268926998 S Zi:3:094:1 -115:1:0 1 -18:0:200 200 < > ffff9c3975947a00 2268927874 C Zi:3:094:1 0:1:1132:0 1 0:0:192 192 = > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 Here we have two initial packets of full length but containing only 0s. I suppose the device was supposed to send these. More interesting are the frame numbers in the two header lines. They show that the packets were scheduled in frames 1130 and 1132, indicating that your program did not submit a transfer request in time for frame 1131. In fact, the pattern here and below indicates that your program submits a transfer, waits for it to complete, and then submits the next one. That is not a good way to handle isochronous data. You should submit a bunch of transfers (five to ten, say), and then submit a new transfer whenever an old one completes. That way the request queue is much less likely to empty out, and you're less likely to lose data. Also, a single request can transfer more than one packet of isochronous data (although putting multiple packets into a single transfer does increase latency). > ffff9c3975947a00 2268928021 S Zi:3:094:1 -115:1:0 1 -18:0:200 200 < > ffff9c3975947a00 2268928860 C Zi:3:094:1 0:1:1133:0 1 0:0:192 192 = > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 > ffff9c3975947a00 2268929036 S Zi:3:094:1 -115:1:0 1 -18:0:200 200 < > ffff9c3975947a00 2268929860 C Zi:3:094:1 0:1:1134:0 1 0:0:192 192 = > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 > ffff9c3975947a00 2268930037 S Zi:3:094:1 -115:1:0 1 -18:0:200 200 < > ffff9c3975947a00 2268930860 C Zi:3:094:1 0:1:1135:0 1 0:0:192 192 = > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 00000000 00000000 > ffff9c3975947a00 2268931039 S Zi:3:094:1 -115:1:0 1 -18:0:200 200 < > ffff9c3975947a00 2268931863 C Zi:3:094:1 0:1:1136:0 1 0:0:192 192 = > ceffcbff c6ffb7ff b4ffc0ff afffc3ff c8ffe6ff e0ff0000 d9ff0a00 > e1ffefff fdffdeff ecffd7ff d2ffb9ff dbffb7ff ecffd0ff e4ffd0ff > d3ffe9ff a8ffe7ff 8bffd0ff 8cffdeff 8fffcbff a1ff9dff a3ff91ff > acff95ff a5ffafff 9bffd1ff a2ffd7ff c7ffceff faffe1ff 0d00efff > f6fffdff f2ff0800 e3ff0d00 d8ff1000 d0ff1200 e0ff0000 0200f3ff > f8ff0d00 ebff2600 feff4300 01005b00 fbff4400 19003e00 14005600 > efff4200 0f003000 1e003600 27003f00 3d003f00 41004800 And here we have apparently valid data. Skipping... > ffff9c3975947a00 2268951849 C Zi:3:094:1 0:1:1156:0 1 0:0:192 192 = > 2500edff 1f00f2ff 4b000000 62002d00 46002b00 40001000 54000a00 > 62001000 6c001600 80001100 9d003400 aa003a00 8a003700 98002100 > a0001b00 78001d00 5f000a00 9a000600 90001700 8a002500 9f004100 > 82003f00 4a001700 43000a00 5a000100 6300e9ff 6200d8ff 2f00e6ff > 1f00f0ff 2600f4ff 1c000a00 25001f00 35002a00 4a000d00 6d00ffff > 4a00f8ff 4200ecff 4f00e4ff 3b00f7ff 2e001900 21000c00 2e00f5ff > 2b00f0ff 1200f1ff 0600fbff f0fffcff e9ffefff 02000000 > ffff9c3975947a00 2268951962 S Zi:3:094:1 -115:1:0 1 -18:0:200 200 < > ffff9c3975947a00 2268952861 C Zi:3:094:1 0:1:1156:0 1 0:0:192 192 = > f5ff0000 f0ffeaff 0000e7ff 2100f3ff 1800edff 0500daff ffffc3ff > faffccff f0ffb5ff e9ffbeff 0000d7ff 1100d0ff 0d00bdff e2ff96ff > a9ff92ff 8fff86ff 9aff86ff b7ff92ff b6ff8fff afff8bff bdff90ff > b3ffa8ff a0ffbbff aaffc1ff beffb9ff a2ff9aff 88ff93ff 95ffabff > a0ffb9ff a5ffaeff c1ffa6ff a5ff99ff beff88ff d3ff9fff baffc3ff > c5ffc9ff e5ffb8ff d0ffabff daff9bff eaff88ff ceff8fff c6ff7eff > afff92ff 8fffa0ff a4ff95ff 9fffa4ff 93ffa2ff cbff9bff > ffff9c3975947a00 2268952988 S Zi:3:094:1 -115:1:0 1 -18:0:200 200 < > ffff9c3975947a00 2268953861 C Zi:3:094:1 0:1:1158:0 1 0:0:192 192 = > e0ffa5ff d6ff94ff cdff90ff b7ff97ff c4ffa2ff deff9cff f8ff8aff > 03009fff f2ffc1ff f6ffc5ff ebffcbff e0ffd5ff f4ffefff fbffebff > f5ffd9ff f4ffebff 1400f8ff 1c000600 32001900 3b003300 1b005700 > 20005f00 25004800 1f002400 31002d00 33004000 0f003500 48002600 > 64003900 4c002900 6a003a00 7e005100 71005d00 6e004800 68005d00 > 6e005e00 56005700 4a004b00 6f004800 6f005c00 62008700 78009600 > 7900a000 7000b900 7700b700 9d009500 a5009400 a1008200 I don't understand this. There are two packets both marked for frame 1156 and none for frame 1157. That shouldn't happen, but it might be a result of the fact that you allow the pipeline to empty out after every individual packet. There is at least one place later on where the trace shows that a frame was skipped, and shortly afterward there were multiple packets of 0s. These things may be related, there's no way to know. Alan Stern -- To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
