On Wed, 17 Jul 2013, James Stone wrote: > On Wed, Jul 17, 2013 at 3:59 PM, Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> wrote: > > On Tue, 16 Jul 2013, James Stone wrote: > > > >> Thanks. The patch allows jack to now start at (playback only) 64 > >> frames/period. It doesn't work with 32 frames/period though (I think > >> you predicted this). This is still a regression from 3.5.0-28, which > >> will work with 8 frames/period for playback only. Furthermore, jack > >> won't start in duplex at 128 frames/period. It doesn't (yet) tempt me > >> to use the 3.8 series kernels for proper audio work. > > > > Usbmon traces, please (for 3.8 only; I'm willing to believe that 3.5 > > works okay). It's difficult to predict the final effect of the > > parameters you supply to JACK, because the ALSA layer imposes its own > > set of requirements on them. > > I will send off list again. 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? Clemens, any thoughts? 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
