[alsa-devel] Attempting to understand odd snd-usb-audio code and behavior
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
Keith A. Milner wrote:
I'm struggling to understand why the code is behaving as it does in practice
Because the code has evolved over a long time, and it tries to handle not only both versions of the USB audio specification, but also devices as they are behaving 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
That happens due to requests from user space, probably PulseAudio.
kernel: [ 1987.452947] usb 1-1: Unable to change format on ep #8e: already in use
So this is a Roland device? Playback-synchronized-to-capture is a very special case; at the moment, nobody understands this code completely. But the problem for this device might be that it requires some vendor-specific messages to enable it in the first place. Regards, Clemens
On Wednesday 23 Aug 2017 12:23:00 Clemens Ladisch wrote:
Keith A. Milner wrote:
It seems to open and close the PCMs
That happens due to requests from user space, probably PulseAudio.
kernel: [ 1987.452947] usb 1-1: Unable to change format on ep #8e: already in use So this is a Roland device? Playback-synchronized-to-capture is a very special case; at the moment, nobody understands this code completely.
But the problem for this device might be that it requires some vendor-specific messages to enable it in the first place.
That's very useful, thank you. I forgot about pulseaudio! So the error messages are due to a userspace app trying to open playback and capture at the same time? Or is it just a generic driver/card issue when trying to open the interface? I have the ability to sniff the USB whilst running on Windows. For this specific device I may try that. Regards, Keith
Keith A. Milner wrote:
kernel: [ 1987.452947] usb 1-1: Unable to change format on ep #8e: already in use
So the error messages are due to a userspace app trying to open playback and capture at the same time?
For this device, playback requires a running capture stream to determine the rate of packets. This error happens when the application tries to open the capture stream after the playback stream. (If the format does not actually need to change, the error message is misleading.) Your actual problem is that the device does not send any capture packets. Regards, Clemens
On Wednesday 23 Aug 2017 14:52:43 Clemens Ladisch wrote:
Keith A. Milner wrote:
kernel: [ 1987.452947] usb 1-1: Unable to change format on ep #8e: already in use> So the error messages are due to a userspace app trying to open playback and capture at the same time?
For this device, playback requires a running capture stream to determine the rate of packets. This error happens when the application tries to open the capture stream after the playback stream. (If the format does not actually need to change, the error message is misleading.)
Your actual problem is that the device does not send any capture packets.
Thank you for the clarification. Hopefully I will find some time to explore this further. Cheers, Keith
On Wednesday 23 Aug 2017 14:52:43 Clemens Ladisch wrote:
Keith A. Milner wrote:
kernel: [ 1987.452947] usb 1-1: Unable to change format on ep #8e: already in use> So the error messages are due to a userspace app trying to open playback and capture at the same time?
For this device, playback requires a running capture stream to determine the rate of packets.
Interestingly, the device works for playback (using aplay) until I try to capture, when it stops working until I reset it.
This error happens when the application tries to open the capture stream after the playback stream. (If the format does not actually need to change, the error message is misleading.)
Your actual problem is that the device does not send any capture packets.
Presumably this should (in principle) be taken care of by the driver. The application should not care. So the driver should detect the dependency and open the corresponding capture stream if a playback stream is opened? There's definitely something hooky with this device and the capture stream though, which I need to explore further. So far I cannot get capture working at all. Cheers, Keith
On Wednesday 23 Aug 2017 14:52:43 Clemens Ladisch wrote:
Keith A. Milner wrote:
kernel: [ 1987.452947] usb 1-1: Unable to change format on ep #8e: already in use> So the error messages are due to a userspace app trying to open playback and capture at the same time?
For this device, playback requires a running capture stream to determine the rate of packets. This error happens when the application tries to open the capture stream after the playback stream. (If the format does not actually need to change, the error message is misleading.)
Your actual problem is that the device does not send any capture packets.
OK, I found some more time to look at this. The background is a Roland device. The device descriptor is attached, but it seems to be common to a lot of Roland devices. Specifically on this device, the Playback endpoint is 0x0d and there is a related Implicit feedback endpoint at 0x8e. I have USB traces of the device operation under Windows and the (non) operation under Linux. The primary difference seems to be that, under Windows, the Implict Feedback endpoint (0x8e) is opened prior to playback commencing. Given previous discussions (and further research) on Implicit feedback, this makes sense. Under Linux, this does not happen. I've been studying the code in pcm.c and endpoint.c to work out why this is, and have some questions on the code function. The flow of the code to deal with implict feedback setup in pcm.c is, roughly, as follows: set_sync_endpoint set_sync_ep_implicit_fb_quirk search_roland_implicit_fb set_sync_ep_implicit_fb_quirk seems to deal with quirks relating to implicit feedback and, within this, is a specific check for Roland which ends up branching to "add_sync_ep" which adds a new endpoint via endpoint.c function snd_usb_add_endpoint and assigns this as as the sync endpoint: subs->sync_endpoint = snd_usb_add_endpoint(subs->stream->chip, alts, ep, !subs->direction, SND_USB_ENDPOINT_TYPE_DATA); subs->data_endpoint->sync_master = subs->sync_endpoint; Within endpoint.c, this new endpoint is added to chip->ep_list : list_add_tail(&ep->list, &chip->ep_list); After set_sync_ep_implicit_fb_quirk has completed it returns to set_sync_endpoint which then checks that there are at least 2 endpoints: if (altsd->bNumEndpoints < 2) return 0; However, in the case I'm testing, on this device, this test fails as bNumEndpoints is 1, even though we've just added a second endpoint for the Implicit feedback. Looking at the code, endpoint.c does not alter bNumEndpoints, which seems to be a fundamental piece of data held against the usb_host_interface instance and, presumably, set from the device descriptor by underlying kernel code. My question is, is the test for bNumEndpoints correct here? From what I can gather, the whole point of the set_sync_ep_implicit_fb_quirk and search_roland_implicit_fb code is to add an endpoint that can then be used by set_sync_endpoint, but this seems to be ignored by doing the test for bNumEndpoints. Or, perhaps, is it that the way that this endpoint is added is incorrect. I have, by the way, tried commenting out the bNumEndpoints test, and it fails at the subsequent sync-pipe check with: invalid sync pipe. bmAttributes 00, bLength 0, bSynchAddress 00 To me this suggests the endpoint isn't being set correctly somehow. Any pointers gratefully received. Cheers, Keith
On Monday 22 Jan 2018 14:06:08 Keith A. Milner wrote:
On Wednesday 23 Aug 2017 14:52:43 Clemens Ladisch wrote:
Keith A. Milner wrote:
kernel: [ 1987.452947] usb 1-1: Unable to change format on ep #8e: already in use>
So the error messages are due to a userspace app trying to open playback and capture at the same time?
For this device, playback requires a running capture stream to determine the rate of packets. This error happens when the application tries to open the capture stream after the playback stream. (If the format does not actually need to change, the error message is misleading.)
Your actual problem is that the device does not send any capture packets.
OK, I found some more time to look at this.
The background is a Roland device. The device descriptor is attached, but it seems to be common to a lot of Roland devices.
Specifically on this device, the Playback endpoint is 0x0d and there is a related Implicit feedback endpoint at 0x8e.
I have USB traces of the device operation under Windows and the (non) operation under Linux. The primary difference seems to be that, under Windows, the Implict Feedback endpoint (0x8e) is opened prior to playback commencing. Given previous discussions (and further research) on Implicit feedback, this makes sense.
Under Linux, this does not happen.
I've been studying the code in pcm.c and endpoint.c to work out why this is, and have some questions on the code function.
The flow of the code to deal with implict feedback setup in pcm.c is, roughly, as follows: set_sync_endpoint set_sync_ep_implicit_fb_quirk search_roland_implicit_fb
set_sync_ep_implicit_fb_quirk seems to deal with quirks relating to implicit feedback and, within this, is a specific check for Roland which ends up branching to "add_sync_ep" which adds a new endpoint via endpoint.c function snd_usb_add_endpoint and assigns this as as the sync endpoint:
subs->sync_endpoint = snd_usb_add_endpoint(subs->stream->chip, alts, ep, !subs->direction, SND_USB_ENDPOINT_TYPE_DATA);
subs->data_endpoint->sync_master = subs->sync_endpoint;
Within endpoint.c, this new endpoint is added to chip->ep_list :
list_add_tail(&ep->list, &chip->ep_list);
After set_sync_ep_implicit_fb_quirk has completed it returns to set_sync_endpoint which then checks that there are at least 2 endpoints:
if (altsd->bNumEndpoints < 2) return 0;
However, in the case I'm testing, on this device, this test fails as bNumEndpoints is 1, even though we've just added a second endpoint for the Implicit feedback.
Looking at the code, endpoint.c does not alter bNumEndpoints, which seems to be a fundamental piece of data held against the usb_host_interface instance and, presumably, set from the device descriptor by underlying kernel code.
My question is, is the test for bNumEndpoints correct here? From what I can gather, the whole point of the set_sync_ep_implicit_fb_quirk and search_roland_implicit_fb code is to add an endpoint that can then be used by set_sync_endpoint, but this seems to be ignored by doing the test for bNumEndpoints.
Or, perhaps, is it that the way that this endpoint is added is incorrect.
I have, by the way, tried commenting out the bNumEndpoints test, and it fails at the subsequent sync-pipe check with:
invalid sync pipe. bmAttributes 00, bLength 0, bSynchAddress 00
To me this suggests the endpoint isn't being set correctly somehow.
Any pointers gratefully received.
Answering my own question, I've just realized that the objective of set_sync_endpoint is to set the sync endpoint as follows: subs->data_endpoint->sync_master = subs->sync_endpoint; The quirks in set_sync_ep_implicit_fb_quirk do this directly, so the remainder of the code in set_sync_endpoint is irrelevant for these devices. My next course of action is to try to work out why the sync endpoint doesn't seem to be opened. Cheers, Keith
On Monday 22 Jan 2018 15:40:03 Keith A. Milner wrote:
On Monday 22 Jan 2018 14:06:08 Keith A. Milner wrote:
On Wednesday 23 Aug 2017 14:52:43 Clemens Ladisch wrote:
Keith A. Milner wrote:
My next course of action is to try to work out why the sync endpoint doesn't seem to be opened.
Right, so I see it IS being opened, and this results in URB_ISOCHRONOUS in URBs being sent, and the device responds (packet dissection in attached files for alsa and windows). However, the sync packets received are empty and are, thus, ignored by snd_usb_handle_sync_urb (in endpoint.c). There are a couple of minor differences between the URBs in the Windows case and the Linux case: 1. The Windows URBs are larger: 448 bytes with a data length of 384 bytes compared to 448 bytes with a data length of 128 bytes for Alsa I don't know if this is significant or is the impact of Alsa chosing a different format/framerate. 2. The bInterfaceClass in the Windows case is set to Vendor Specific (0xff) but is Unknown (0xffff) in the Alsa case. I can't see where this is being set. The host interfaces seem to have the correct bInterfaceClass Other than that, the two appear to be the same. The ISO descriptors in the Windows case also appear to be empty: 0000 ee ff ff ff 00 00 00 00 38 00 00 00 00 00 00 00 ........8....... 0010 ee ff ff ff 38 00 00 00 38 00 00 00 00 00 00 00 ....8...8....... 0020 ee ff ff ff 70 00 00 00 38 00 00 00 00 00 00 00 ....p...8....... 0030 ee ff ff ff a8 00 00 00 38 00 00 00 00 00 00 00 ........8....... 0040 ee ff ff ff e0 00 00 00 38 00 00 00 00 00 00 00 ........8....... 0050 ee ff ff ff 18 01 00 00 38 00 00 00 00 00 00 00 ........8....... 0060 ee ff ff ff 50 01 00 00 38 00 00 00 00 00 00 00 ....P...8....... 0070 ee ff ff ff 88 01 00 00 38 00 00 00 00 00 00 00 ........8....... 0080 ee ff ff ff c0 01 00 00 38 00 00 00 00 00 00 00 ........8....... 0090 ee ff ff ff f8 01 00 00 38 00 00 00 00 00 00 00 ........8....... 00a0 ee ff ff ff 30 02 00 00 38 00 00 00 00 00 00 00 ....0...8....... 00b0 ee ff ff ff 68 02 00 00 38 00 00 00 00 00 00 00 ....h...8....... 00c0 ee ff ff ff a0 02 00 00 38 00 00 00 00 00 00 00 ........8....... 00d0 ee ff ff ff d8 02 00 00 38 00 00 00 00 00 00 00 ........8....... 00e0 ee ff ff ff 10 03 00 00 38 00 00 00 00 00 00 00 ........8....... 00f0 ee ff ff ff 48 03 00 00 38 00 00 00 00 00 00 00 ....H...8....... 0100 ee ff ff ff 80 03 00 00 38 00 00 00 00 00 00 00 ........8....... 0110 ee ff ff ff b8 03 00 00 38 00 00 00 00 00 00 00 ........8....... 0120 ee ff ff ff f0 03 00 00 38 00 00 00 00 00 00 00 ........8....... 0130 ee ff ff ff 28 04 00 00 38 00 00 00 00 00 00 00 ....(...8....... 0140 ee ff ff ff 60 04 00 00 38 00 00 00 00 00 00 00 ....`...8....... 0150 ee ff ff ff 98 04 00 00 38 00 00 00 00 00 00 00 ........8....... 0160 ee ff ff ff d0 04 00 00 38 00 00 00 00 00 00 00 ........8....... 0170 ee ff ff ff 08 05 00 00 38 00 00 00 00 00 00 00 ........8....... Cheers, Keith
Hey Keith! I'm working with Roland R-26, and have pretty same problem here. Was you able to solve yours? WbR Ilya
On Sunday, 5 April 2020 02:14:15 BST Ilya Dikariev wrote:
Hey Keith!
I'm working with Roland R-26, and have pretty same problem here. Was you able to solve yours?
Hi Ilya, No, sorry. I also didn't have time to follow up on this. I get the feeling there's a lot of Roland/Boss devices out there with this problem, and that fixing one of them will fix them all. Regards, Keith
participants (3)
-
Clemens Ladisch -
Ilya Dikariev -
Keith A. Milner