On Wed, Jul 17, 2013 at 7:48 PM, Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> wrote: > The 32-frames/period trace looks just like the 64 frames/period, only > worse. Each URB has only 4 packets, and the underrun problem is > severe. This won't happen after the minimum pipeline length is fixed. > > The 256-frames/period duplex trace is different. There are 4 output > URBs, alternating between 8 and 7 packets, so no underruns. On the > other hand, the audio-in stream doesn't start up until 900 ms after the > audio-out, and everything stops almost immediately afterward. > > It certainly looks like that delay is causing the problem, so I tracked > it down. Before starting each stream, the ALSA driver sends several > control requests. I'm not very familiar with the USB audio protocol; > it looks like the requests are GET_CUR and SET_CUR for various > clock-related controls. > > First there is Set-Interface for the audio-in interface, followed by: > > ffff88010586a3c0 3063689257 S Ci:1:004:0 s a1 01 0100 2800 0001 1 < > ffff88010586a3c0 3063689324 C Ci:1:004:0 0 1 = 01 > ffff88010586a3c0 3063689355 S Ci:1:004:0 s a1 01 0200 2900 0001 1 < > ffff88010586a3c0 3063689448 C Ci:1:004:0 0 1 = 01 > ffff88010586a3c0 3063689496 S Co:1:004:0 s 21 01 0100 2900 0004 4 = 44ac0000 > ffff88010586a3c0 3064139502 C Co:1:004:0 0 4 > > ffff88010586a3c0 3064139605 S Ci:1:004:0 s a1 01 0100 2900 0004 4 < > ffff88010586a3c0 3064139706 C Ci:1:004:0 0 4 = 44ac0000 > > As far as I can tell, entity 0x28 is a CLOCK_SELECTOR and 0x29 is a > CLOCK_SOURCE. The last two requests appear to set the clock frequency > to 44100 (0x44ac0000 in little-endian hex) and read it back. > > Then there is Set-Interface for the audio-out interface, followed by: > > ffff88010586ac00 3064140256 S Ci:1:004:0 s a1 01 0100 2800 0001 1 < > ffff88010586ac00 3064140495 C Ci:1:004:0 0 1 = 01 > ffff88010586ac00 3064140593 S Ci:1:004:0 s a1 01 0200 2900 0001 1 < > ffff88010586ac00 3064140706 C Ci:1:004:0 0 1 = 01 > ffff88010586ac00 3064140764 S Co:1:004:0 s 21 01 0100 2900 0004 4 = 44ac0000 > ffff88010586ac00 3064590952 C Co:1:004:0 0 4 > > ffff88010586ac00 3064591055 S Ci:1:004:0 s a1 01 0100 2900 0004 4 < > ffff88010586ac00 3064592201 C Ci:1:004:0 0 4 = 44ac0000 > > These are exactly the same as the previous set of requests. I don't > know why they are repeated. (It's worth pointing out that the same > repeat also occurs in the simplex out-only trace.) > > Next, the audio-out URBs (including the synch URBs) begin, followed by > some more control requests interspersed among them: > > ffff88010586ac00 3064593448 S Ci:1:004:0 s a1 01 0100 2800 0001 1 < > ffff88010586ac00 3064593885 C Ci:1:004:0 0 1 = 01 > ffff88010586ac00 3064593964 S Ci:1:004:0 s a1 01 0200 2900 0001 1 < > ffff88010586ac00 3064594185 C Ci:1:004:0 0 1 = 01 > ffff8800bd6db180 3064594238 S Co:1:004:0 s 21 01 0100 2900 0004 4 = 44ac0000 > ffff8800bd6db180 3065044098 C Co:1:004:0 0 4 > > ffff88010586a240 3065044188 S Ci:1:004:0 s a1 01 0100 2900 0004 4 < > ffff88010586a240 3065044350 C Ci:1:004:0 0 4 = 44ac0000 > ffff88010586a240 3065044412 S Ci:1:004:0 s a1 01 0100 2800 0001 1 < > ffff88010586a240 3065044474 C Ci:1:004:0 0 1 = 01 > ffff88010586a240 3065044510 S Ci:1:004:0 s a1 01 0200 2900 0001 1 < > ffff88010586a240 3065044598 C Ci:1:004:0 0 1 = 01 > ffff88010586a240 3065044631 S Co:1:004:0 s 21 01 0100 2900 0004 4 = 44ac0000 > ffff88010586a240 3065494566 C Co:1:004:0 0 4 > > ffff88010586a240 3065494651 S Ci:1:004:0 s a1 01 0100 2900 0004 4 < > ffff88010586a240 3065494814 C Ci:1:004:0 0 4 = 44ac0000 > > after which the audio-in URBs start up. This is the same four requests > as before, repeated as before. But notice the timestamps (second > column, values are in microseconds). Each of the SET_CUR requests for > the clock frequency requires 450 ms to complete! That accounts for the > 900 ms delay. > > The same 450-ms delay can be seen in the earlier requests too, but > there they didn't matter. It appears that the delay in starting up the > second stream annoys JACK, causing it to abort the session. > > After everything stops, another attempt is made. This time there is > only one SET_CUR between the start of the audio-out and the start of > the audio-in. Even so, a 450-ms delay evidently is enough to cause > JACK to abort. Several more attempts were made, each with the same > result. > > The questions now are: > > Why are the same requests sent over and over again? > > Why does the ALSA driver attempt to set the clock frequency > while the clock is actively in use? > > Has this behavior changed since the 3.5 kernel? > Well, I think these requests may correspond to the lights flashing on and off on the front of the device. When starting the device in 3.5 at 256 frames/period (duplex), the lights flash on and off 2 times, in the current patched 3.8 version I have been using, the device lights flash on and off 4 times before starting jack with exactly the same settings - so it seems for some reason, the requests are going through multiple times on the 3.8 kernel but not on 3.5. I will send a 3.5 usbmon trace of a successful start off list (plus the same for 3.8?) if it would be useful. James -- 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
