[alsa-devel] Attempting to understand odd snd-usb-audio code and behavior

[Keith A. Milner]

Over the last few weeks I've been trying to dig through the snd-usb-audio code 
to try to get an understanding of it. I've used ftrace and also a local 
version which I have heavily polluted with kprintf(KERN_INFO statements so I 
can track what it's doing in practice.

I've been playing with this with some USB audio interfaces I have some which 
work, and some which don't, and trying to understand the differences and, 
ultimately, what I can do to make the non-functioning ones work.

I've got to the point where I have a fairly good understanding of some parts, 
but I'm struggling to understand why the code is behaving as it does in 
practice.

My observation when plugging the USB device in is that, as expected, it tries 
to build the audio device, and add components to it including attaching 
capture and playback streams. It seems to go through this phase without too 
many surprises, and we get to the standard dmesg output:

usbcore: registered new interface driver snd-usb-audio

After this, it gets confusing.

It seems to open and close the PCMs (e.g, snd_usb_capture_open) several times 
in a row. Each time it sets up the hardware info, checks and sets the format 
and then closes the PCM. I don't see anything obviously different between most 
of these cycles. Here's an example my logging output (hopefully this will make 
sense):

Aug 22 20:04:16 kerneldev kernel: [  923.140789] Called: pcm.c - 
snd_usb_capture_open for pcm substream 0
Aug 22 20:04:16 kerneldev kernel: [  923.140789] Called: pcm.c - 
snd_usb_pcm_open for pcm substream 0
Aug 22 20:04:16 kerneldev kernel: [  923.140789] Setting up hw info
Aug 22 20:04:16 kerneldev kernel: [  923.140789] Checking format:
Aug 22 20:04:16 kerneldev kernel: [  923.140790]  Interface number = 2
Aug 22 20:04:16 kerneldev kernel: [  923.140790]  alt setting = 1
Aug 22 20:04:16 kerneldev kernel: [  923.140790]  alt setting index = 1
Aug 22 20:04:16 kerneldev kernel: [  923.140790]  format type = 1
Aug 22 20:04:16 kerneldev kernel: [  923.140790]  frame size = 0
Aug 22 20:04:16 kerneldev kernel: [  923.140791] Setting pt=125 ptmin=125
Aug 22 20:04:16 kerneldev kernel: [  923.140792] Checking for unusual bit 
rates
Aug 22 20:04:16 kerneldev kernel: [  923.140794] Called: init.c - 
snd_card_file_remove
Aug 22 20:04:16 kerneldev kernel: [  923.140921] Called: pcm.c - 
snd_usb_hw_params for pcm substream 0
Aug 22 20:04:16 kerneldev kernel: [  923.140945] Setting format:
Aug 22 20:04:16 kerneldev kernel: [  923.140945]  Bytes per period = 8816
Aug 22 20:04:16 kerneldev kernel: [  923.140945]  Frames per period = 1102
Aug 22 20:04:16 kerneldev kernel: [  923.140946]  Periods per buffer = 4
Aug 22 20:04:16 kerneldev kernel: [  923.140946]  Channels = 2
Aug 22 20:04:16 kerneldev kernel: [  923.140946]  Rate = 44100
Aug 22 20:04:16 kerneldev kernel: [  923.141279] Called: endpoint.c - 
snd_usb_add_endpoint of type 0 with direction 1
Aug 22 20:04:16 kerneldev kernel: [  923.141292] Called: pcm.c - 
snd_usb_pcm_prepare for pcm substream 0
Aug 22 20:04:16 kerneldev kernel: [  923.141293] Called: pcm.c - 
configure_endpoint
Aug 22 20:04:16 kerneldev kernel: [  923.141294] Called: endpoint.c - 
snd_usb_endpoint_set_params for endpoint 142, type 0
Aug 22 20:04:16 kerneldev kernel: [  923.141294] Setting endpoint params for 
endpoint num 142
Aug 22 20:04:16 kerneldev kernel: [  923.141294]  channels=2
Aug 22 20:04:16 kerneldev kernel: [  923.141294]  period bytes=8816
Aug 22 20:04:16 kerneldev kernel: [  923.141295]  frames per period=1102
Aug 22 20:04:16 kerneldev kernel: [  923.141295]  periods per buffer=4
Aug 22 20:04:16 kerneldev kernel: [  923.141296] Called: endpoint.c - 
data_ep_set_params for endpoint 142, type 0
Aug 22 20:04:16 kerneldev kernel: [  923.141301] Called: pcm.c - 
snd_usb_pcm_prepare for pcm substream 0
Aug 22 20:04:16 kerneldev kernel: [  923.142768] Called: init.c - 
snd_card_file_add
Aug 22 20:04:16 kerneldev kernel: [  923.142772] Called: init.c - 
snd_card_file_remove
Aug 22 20:04:16 kerneldev kernel: [  923.142774] Called: init.c - 
snd_card_file_add
Aug 22 20:04:16 kerneldev kernel: [  923.142830] Called: init.c - 
snd_card_file_remove
Aug 22 20:04:16 kerneldev kernel: [  923.142836] Called: pcm.c - 
snd_usb_hw_free for pcm substream 0
Aug 22 20:04:16 kerneldev kernel: [  923.142837] Called: endpoint.c - 
snd_usb_endpoint_deactivate for endpoint 142, type 0
Aug 22 20:04:16 kerneldev kernel: [  923.142846] Called: pcm.c - 
snd_usb_capture_close for pcm substream 0
Aug 22 20:04:16 kerneldev kernel: [  923.146760] Called: init.c - 
snd_card_file_remove
Aug 22 20:04:16 kerneldev kernel: [  923.146834] Called: init.c - 
snd_card_file_add
Aug 22 20:04:16 kerneldev kernel: [  923.146838] Called: init.c - 
snd_card_file_remove
Aug 22 20:04:16 kerneldev kernel: [  923.146841] Called: init.c - 
snd_card_file_add
Aug 22 20:04:16 kerneldev kernel: [  923.146845] Called: init.c - 
snd_card_file_add
Aug 22 20:04:16 kerneldev kernel: [  923.146848] Called: pcm.c - 
snd_usb_capture_open for pcm substream 0
Aug 22 20:04:16 kerneldev kernel: [  923.146849] Called: pcm.c - 
snd_usb_pcm_open for pcm substream 0
Aug 22 20:04:16 kerneldev kernel: [  923.146849] Setting up hw info

It seems to do this several times, before the behavior changing slightly, as 
it now starts to try to set the endpoint parameters and seems to leave the 
stream open. However, it then tries to open the stream and set the endpoint 
parameters again resulting in errors:

Aug 22 20:22:00 kerneldev kernel: [ 1987.452945] Called: endpoint.c - 
snd_usb_endpoint_set_params for endpoint 142, type 0
Aug 22 20:22:00 kerneldev kernel: [ 1987.452945] Setting endpoint params for 
endpoint num 142
Aug 22 20:22:00 kerneldev kernel: [ 1987.452945]  channels=2
Aug 22 20:22:00 kerneldev kernel: [ 1987.452945]  period bytes=1768
Aug 22 20:22:00 kerneldev kernel: [ 1987.452946]  frames per period=221
Aug 22 20:22:00 kerneldev kernel: [ 1987.452946]  periods per buffer=593
Aug 22 20:22:00 kerneldev kernel: [ 1987.452947] usb 1-1: Unable to change 
format on ep #8e: already in use

Maybe this is driven by hotplug or something, but it seems to be performing a 
lot of pointless activities.

Eventually it seems to try to open the PCM playback or capture stream (with 
some devices it opens playback, with others capture) and then checks the 
pointer:

Aug 22 20:22:00 kerneldev kernel: [ 1987.470194] Called: pcm.c - 
snd_usb_substream_playback_trigger for pcm substream 0
Aug 22 20:22:00 kerneldev kernel: [ 1987.470198] Called: pcm.c - 
snd_usb_pcm_pointer for pcm substream 0
Aug 22 20:22:00 kerneldev kernel: [ 1987.470198]   Pointer is 0
Aug 22 20:22:00 kerneldev kernel: [ 1987.470656] Called: pcm.c - 
snd_usb_pcm_pointer for pcm substream 0
Aug 22 20:22:00 kerneldev kernel: [ 1987.470657]   Pointer is 0
Aug 22 20:22:00 kerneldev kernel: [ 1987.470660] Called: pcm.c - 
snd_usb_pcm_pointer for pcm substream 0
Aug 22 20:22:00 kerneldev kernel: [ 1987.470660]   Pointer is 0
Aug 22 20:22:05 kerneldev kernel: [ 1992.473567] Called: pcm.c - 
snd_usb_pcm_pointer for pcm substream 0
Aug 22 20:22:05 kerneldev kernel: [ 1992.473569]   Pointer is 0


The above is from a non-working device. For a working device the pointer 
increments. Eventually this activity ends:

Aug 22 20:22:05 kerneldev kernel: [ 1992.473575] Called: pcm.c - 
snd_usb_substream_playback_trigger for pcm substream 0
Aug 22 20:22:05 kerneldev kernel: [ 1992.473576] Called: endpoint.c - 
snd_usb_endpoint_stop for endpoint 142, type 0
Aug 22 20:22:05 kerneldev kernel: [ 1992.473578] Called: endpoint.c - 
snd_usb_endpoint_stop for endpoint 13, type 0
Aug 22 20:22:05 kerneldev kernel: [ 1992.473602] Called: pcm.c - 
snd_usb_hw_free for pcm substream 0
Aug 22 20:22:05 kerneldev kernel: [ 1992.503287] Called: endpoint.c - 
snd_usb_endpoint_deactivate for endpoint 142, type 0
Aug 22 20:22:05 kerneldev kernel: [ 1992.503288] Called: endpoint.c - 
snd_usb_endpoint_deactivate for endpoint 13, type 0
Aug 22 20:22:05 kerneldev kernel: [ 1992.503323] Called: pcm.c - 
snd_usb_playback_close for pcm substream 0
Aug 22 20:22:05 kerneldev kernel: [ 1992.503656] Called: init.c - 
snd_card_file_remove

This seems as if it might be some sort of test of the PCMs, to make sure they 
are working. Certainly in non-working devices the pcm_pointer stays at zero 
and in working devices it increments.

It also seems to try harder with some devices than others, even though the 
device descriptors seem very similar.

Can anyone explain any of this to me, particularly why it's exhibiting this 
behaviour.

I've uploaded one of the logs from a non-working device to Pastebin if anyone 
wants to look at a full example: https://pastebin.com/uBZEuQ57

Also, is this the best way to approach this, or are there other 
tools/techniques that can help? I've experimented with ftrace and that was 
useful, but didn't give the level of detail I wanted.

Cheers,

Keith