On Fri, Jul 6, 2018 at 12:36 PM, Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> wrote:
> On Fri, 6 Jul 2018, R0b0t1 wrote:
>>
>> 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!
>
Sorry, I wanted to make sure there was enough information. I also
apologize as I just realized you must have received multiple messages
from me - I forgot the kernel lists add the respondents to the message
headers.
>> 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.
>
Is anyone able to comment on this in more detail? I thought it was
supposed to be reported if a transfer did not arrive 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).
>
I updated my C code and now everything works. I think the issue was GC
pauses in Python.
What does not work: multiple transfers within an isochronous packet.
More than ~3 transfers results in missing packets (using libusb from
C).
There is no easy way to implement multiple concurrent transfers with
PyUSB. I may implement it in my C code, but the time between transfers
is relatively large and I see no issues currently.
>> 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.
>
Can you explain what you mean?
> 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.
>
I think they are, I will check the device code. That will take a while.
Thanks,
R0b0t1
--
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
