* Attempting to understand odd snd-usb-audio code and behavior
@ 2017-08-22 20:25 Keith A. Milner
2017-08-23 10:23 ` Clemens Ladisch
0 siblings, 1 reply; 11+ messages in thread
From: Keith A. Milner @ 2017-08-22 20:25 UTC (permalink / raw)
To: alsa-devel
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
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Attempting to understand odd snd-usb-audio code and behavior
2017-08-22 20:25 Attempting to understand odd snd-usb-audio code and behavior Keith A. Milner
@ 2017-08-23 10:23 ` Clemens Ladisch
2017-08-23 11:25 ` Keith A. Milner
0 siblings, 1 reply; 11+ messages in thread
From: Clemens Ladisch @ 2017-08-23 10:23 UTC (permalink / raw)
To: alsa-devel
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
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Attempting to understand odd snd-usb-audio code and behavior
2017-08-23 10:23 ` Clemens Ladisch
@ 2017-08-23 11:25 ` Keith A. Milner
2017-08-23 12:52 ` Clemens Ladisch
0 siblings, 1 reply; 11+ messages in thread
From: Keith A. Milner @ 2017-08-23 11:25 UTC (permalink / raw)
To: alsa-devel
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
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Attempting to understand odd snd-usb-audio code and behavior
2017-08-23 11:25 ` Keith A. Milner
@ 2017-08-23 12:52 ` Clemens Ladisch
2017-08-23 22:43 ` Keith A. Milner
` (2 more replies)
0 siblings, 3 replies; 11+ messages in thread
From: Clemens Ladisch @ 2017-08-23 12:52 UTC (permalink / raw)
To: alsa-devel
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
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Attempting to understand odd snd-usb-audio code and behavior
2017-08-23 12:52 ` Clemens Ladisch
@ 2017-08-23 22:43 ` Keith A. Milner
2017-08-23 22:49 ` Keith A. Milner
2018-01-22 14:06 ` Keith A. Milner
2 siblings, 0 replies; 11+ messages in thread
From: Keith A. Milner @ 2017-08-23 22:43 UTC (permalink / raw)
To: alsa-devel
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
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Attempting to understand odd snd-usb-audio code and behavior
2017-08-23 12:52 ` Clemens Ladisch
2017-08-23 22:43 ` Keith A. Milner
@ 2017-08-23 22:49 ` Keith A. Milner
2018-01-22 14:06 ` Keith A. Milner
2 siblings, 0 replies; 11+ messages in thread
From: Keith A. Milner @ 2017-08-23 22:49 UTC (permalink / raw)
To: alsa-devel
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
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Attempting to understand odd snd-usb-audio code and behavior
2017-08-23 12:52 ` Clemens Ladisch
2017-08-23 22:43 ` Keith A. Milner
2017-08-23 22:49 ` Keith A. Milner
@ 2018-01-22 14:06 ` Keith A. Milner
2018-01-22 15:40 ` Keith A. Milner
2 siblings, 1 reply; 11+ messages in thread
From: Keith A. Milner @ 2018-01-22 14:06 UTC (permalink / raw)
To: alsa-devel
[-- Attachment #1: Type: text/plain, Size: 3477 bytes --]
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
[-- Attachment #2: GT-1_lsusb.txt --]
[-- Type: text/plain, Size: 6203 bytes --]
Bus 001 Device 013: ID 0582:01d6 Roland Corp.
Device Descriptor:
bLength 18
bDescriptorType 1
bcdUSB 2.00
bDeviceClass 255 Vendor Specific Class
bDeviceSubClass 0
bDeviceProtocol 255
bMaxPacketSize0 64
idVendor 0x0582 Roland Corp.
idProduct 0x01d6
bcdDevice 0.00
iManufacturer 1 BOSS
iProduct 2 GT-1
iSerial 0
bNumConfigurations 1
Configuration Descriptor:
bLength 9
bDescriptorType 2
wTotalLength 188
bNumInterfaces 4
bConfigurationValue 1
iConfiguration 0
bmAttributes 0xc0
Self Powered
MaxPower 0mA
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 0
bAlternateSetting 0
bNumEndpoints 0
bInterfaceClass 255 Vendor Specific Class
bInterfaceSubClass 255 Vendor Specific Subclass
bInterfaceProtocol 0
iInterface 0
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 1
bAlternateSetting 0
bNumEndpoints 0
bInterfaceClass 255 Vendor Specific Class
bInterfaceSubClass 2
bInterfaceProtocol 2
iInterface 0
** UNRECOGNIZED: 06 24 f1 01 00 00
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 1
bAlternateSetting 1
bNumEndpoints 1
bInterfaceClass 255 Vendor Specific Class
bInterfaceSubClass 2
bInterfaceProtocol 2
iInterface 0
** UNRECOGNIZED: 07 24 01 01 00 01 00
** UNRECOGNIZED: 0b 24 02 01 02 04 18 01 44 ac 00
** UNRECOGNIZED: 06 24 f1 04 16 00
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x0d EP 13 OUT
bmAttributes 5
Transfer Type Isochronous
Synch Type Asynchronous
Usage Type Data
wMaxPacketSize 0x0038 1x 56 bytes
bInterval 1
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 2
bAlternateSetting 0
bNumEndpoints 0
bInterfaceClass 255 Vendor Specific Class
bInterfaceSubClass 2
bInterfaceProtocol 1
iInterface 0
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 2
bAlternateSetting 1
bNumEndpoints 1
bInterfaceClass 255 Vendor Specific Class
bInterfaceSubClass 2
bInterfaceProtocol 1
iInterface 0
** UNRECOGNIZED: 07 24 01 07 00 01 00
** UNRECOGNIZED: 0b 24 02 01 02 04 18 01 44 ac 00
** UNRECOGNIZED: 06 24 f1 04 16 00
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x8e EP 14 IN
bmAttributes 37
Transfer Type Isochronous
Synch Type Asynchronous
Usage Type Implicit feedback Data
wMaxPacketSize 0x0038 1x 56 bytes
bInterval 1
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 3
bAlternateSetting 0
bNumEndpoints 2
bInterfaceClass 255 Vendor Specific Class
bInterfaceSubClass 3
bInterfaceProtocol 0
iInterface 0
** UNRECOGNIZED: 06 24 f1 02 01 01
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x03 EP 3 OUT
bmAttributes 2
Transfer Type Bulk
Synch Type None
Usage Type Data
wMaxPacketSize 0x0200 1x 512 bytes
bInterval 1
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x84 EP 4 IN
bmAttributes 2
Transfer Type Bulk
Synch Type None
Usage Type Data
wMaxPacketSize 0x0200 1x 512 bytes
bInterval 0
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 3
bAlternateSetting 1
bNumEndpoints 2
bInterfaceClass 255 Vendor Specific Class
bInterfaceSubClass 3
bInterfaceProtocol 0
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x03 EP 3 OUT
bmAttributes 3
Transfer Type Interrupt
Synch Type None
Usage Type Data
wMaxPacketSize 0x0200 1x 512 bytes
bInterval 4
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x85 EP 5 IN
bmAttributes 3
Transfer Type Interrupt
Synch Type None
Usage Type Data
wMaxPacketSize 0x0200 1x 512 bytes
bInterval 4
Device Qualifier (for other device speed):
bLength 10
bDescriptorType 6
bcdUSB 2.00
bDeviceClass 255 Vendor Specific Class
bDeviceSubClass 0
bDeviceProtocol 255
bMaxPacketSize0 64
bNumConfigurations 1
Device Status: 0x0001
Self Powered
[-- Attachment #3: Type: text/plain, Size: 0 bytes --]
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Attempting to understand odd snd-usb-audio code and behavior
2018-01-22 14:06 ` Keith A. Milner
@ 2018-01-22 15:40 ` Keith A. Milner
2018-01-22 18:14 ` Keith A. Milner
0 siblings, 1 reply; 11+ messages in thread
From: Keith A. Milner @ 2018-01-22 15:40 UTC (permalink / raw)
To: alsa-devel
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
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Attempting to understand odd snd-usb-audio code and behavior
2018-01-22 15:40 ` Keith A. Milner
@ 2018-01-22 18:14 ` Keith A. Milner
2020-04-05 0:14 ` Re: [alsa-devel] " Ilya Dikariev
0 siblings, 1 reply; 11+ messages in thread
From: Keith A. Milner @ 2018-01-22 18:14 UTC (permalink / raw)
To: alsa-devel
[-- Attachment #1: Type: text/plain, Size: 3089 bytes --]
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
[-- Attachment #2: URB_ISOCHRONOUS_alsa.txt --]
[-- Type: text/plain, Size: 3754 bytes --]
No. Time Source Destination Protocol Length Info Comment
68817 2018-01-22 17:03:24.530158000 host 13.14 USB 192 URB_ISOCHRONOUS in
Frame 68817: 192 bytes on wire (1536 bits), 192 bytes captured (1536 bits) on interface 0
Interface id: 0 (usbmon1)
Encapsulation type: USB packets with Linux header and padding (115)
Arrival Time: Jan 22, 2018 17:03:24.530158000 GMT
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1516640604.530158000 seconds
[Time delta from previous captured frame: 0.000335000 seconds]
[Time delta from previous displayed frame: 0.003405000 seconds]
[Time since reference or first frame: 10.408990000 seconds]
Frame Number: 68817
Frame Length: 192 bytes (1536 bits)
Capture Length: 192 bytes (1536 bits)
[Frame is marked: True]
[Frame is ignored: False]
[Protocols in frame: usb]
USB URB
URB id: 0xffff8801640a6200
URB type: URB_SUBMIT ('S')
URB transfer type: URB_ISOCHRONOUS (0x00)
Endpoint: 0x8e, Direction: IN
1... .... = Direction: IN (1)
.000 1110 = Endpoint value: 14
Device: 13
URB bus id: 1
Device setup request: not relevant ('-')
Data: not present ('<')
URB sec: 1516640604
URB usec: 530158
URB status: Operation now in progress (-EINPROGRESS) (-115)
URB length [bytes]: 448
Data length [bytes]: 128
[Response in: 68832]
[bInterfaceClass: Unknown (0xffff)]
ISO error count: 0
Number of ISO descriptors: 8
Interval: 1
Start frame: 0
Copy of Transfer Flags: 0x00000202
Number of ISO descriptors: 8
Leftover Capture Data: eeffffff000000003800000000000000eeffffff38000000...
No. Time Source Destination Protocol Length Info Comment
68832 2018-01-22 17:03:24.532117000 13.14 host USB 192 URB_ISOCHRONOUS in
Frame 68832: 192 bytes on wire (1536 bits), 192 bytes captured (1536 bits) on interface 0
Interface id: 0 (usbmon1)
Encapsulation type: USB packets with Linux header and padding (115)
Arrival Time: Jan 22, 2018 17:03:24.532117000 GMT
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1516640604.532117000 seconds
[Time delta from previous captured frame: 0.000004000 seconds]
[Time delta from previous displayed frame: 0.001959000 seconds]
[Time since reference or first frame: 10.410949000 seconds]
Frame Number: 68832
Frame Length: 192 bytes (1536 bits)
Capture Length: 192 bytes (1536 bits)
[Frame is marked: True]
[Frame is ignored: False]
[Protocols in frame: usb]
USB URB
URB id: 0xffff8801640a6200
URB type: URB_COMPLETE ('C')
URB transfer type: URB_ISOCHRONOUS (0x00)
Endpoint: 0x8e, Direction: IN
1... .... = Direction: IN (1)
.000 1110 = Endpoint value: 14
Device: 13
URB bus id: 1
Device setup request: not relevant ('-')
Data: present (0)
URB sec: 1516640604
URB usec: 532117
URB status: Success (0)
URB length [bytes]: 0
Data length [bytes]: 128
[Request in: 68817]
[Time from request: 0.001959000 seconds]
[bInterfaceClass: Unknown (0xffff)]
ISO error count: 0
Number of ISO descriptors: 8
Interval: 1
Start frame: 3483
Copy of Transfer Flags: 0x00000202
Number of ISO descriptors: 8
Leftover Capture Data: 000000000000000000000000000000000000000038000000...
[-- Attachment #3: URB_ISOCHRONOUS_w10.txt --]
[-- Type: text/plain, Size: 3751 bytes --]
No. Time Source Destination Protocol Length Info Comment
54 2018-01-20 15:49:26.823852000 host 7.14 USB 448 URB_ISOCHRONOUS in
Frame 54: 448 bytes on wire (3584 bits), 448 bytes captured (3584 bits) on interface 0
Interface id: 0 (usbmon1)
Encapsulation type: USB packets with Linux header and padding (115)
Arrival Time: Jan 20, 2018 15:49:26.823852000 GMT
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1516463366.823852000 seconds
[Time delta from previous captured frame: 0.000358000 seconds]
[Time delta from previous displayed frame: 0.000358000 seconds]
[Time since reference or first frame: 29.405244000 seconds]
Frame Number: 54
Frame Length: 448 bytes (3584 bits)
Capture Length: 448 bytes (3584 bits)
[Frame is marked: True]
[Frame is ignored: False]
[Protocols in frame: usb]
USB URB
URB id: 0xffff880352250400
URB type: URB_SUBMIT ('S')
URB transfer type: URB_ISOCHRONOUS (0x00)
Endpoint: 0x8e, Direction: IN
1... .... = Direction: IN (1)
.000 1110 = Endpoint value: 14
Device: 7
URB bus id: 1
Device setup request: not relevant ('-')
Data: not present ('<')
URB sec: 1516463366
URB usec: 823852
URB status: Operation now in progress (-EINPROGRESS) (-115)
URB length [bytes]: 1344
Data length [bytes]: 384
[Response in: 58]
[bInterfaceClass: Vendor Specific (0xff)]
ISO error count: 0
Number of ISO descriptors: 24
Interval: 1
Start frame: 0
Copy of Transfer Flags: 0x00000202
Number of ISO descriptors: 24
Leftover Capture Data: eeffffff000000003800000000000000eeffffff38000000...
No. Time Source Destination Protocol Length Info Comment
58 2018-01-20 15:49:26.827976000 7.14 host USB 448 URB_ISOCHRONOUS in
Frame 58: 448 bytes on wire (3584 bits), 448 bytes captured (3584 bits) on interface 0
Interface id: 0 (usbmon1)
Encapsulation type: USB packets with Linux header and padding (115)
Arrival Time: Jan 20, 2018 15:49:26.827976000 GMT
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1516463366.827976000 seconds
[Time delta from previous captured frame: 0.003959000 seconds]
[Time delta from previous displayed frame: 0.003959000 seconds]
[Time since reference or first frame: 29.409368000 seconds]
Frame Number: 58
Frame Length: 448 bytes (3584 bits)
Capture Length: 448 bytes (3584 bits)
[Frame is marked: True]
[Frame is ignored: False]
[Protocols in frame: usb]
USB URB
URB id: 0xffff880352250400
URB type: URB_COMPLETE ('C')
URB transfer type: URB_ISOCHRONOUS (0x00)
Endpoint: 0x8e, Direction: IN
1... .... = Direction: IN (1)
.000 1110 = Endpoint value: 14
Device: 7
URB bus id: 1
Device setup request: not relevant ('-')
Data: present (0)
URB sec: 1516463366
URB usec: 827976
URB status: Success (0)
URB length [bytes]: 0
Data length [bytes]: 384
[Request in: 54]
[Time from request: 0.004124000 seconds]
[bInterfaceClass: Vendor Specific (0xff)]
ISO error count: 0
Number of ISO descriptors: 24
Interval: 1
Start frame: 6773
Copy of Transfer Flags: 0x00000202
Number of ISO descriptors: 24
Leftover Capture Data: 000000000000000000000000000000000000000038000000...
[-- Attachment #4: Type: text/plain, Size: 0 bytes --]
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Re: [alsa-devel] Attempting to understand odd snd-usb-audio code and behavior
2018-01-22 18:14 ` Keith A. Milner
@ 2020-04-05 0:14 ` Ilya Dikariev
2020-08-21 12:03 ` Keith A. Milner
0 siblings, 1 reply; 11+ messages in thread
From: Ilya Dikariev @ 2020-04-05 0:14 UTC (permalink / raw)
To: alsa-devel
Hey Keith!
I'm working with Roland R-26, and have pretty same problem here.
Was you able to solve yours?
WbR
Ilya
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [alsa-devel] Attempting to understand odd snd-usb-audio code and behavior
2020-04-05 0:14 ` Re: [alsa-devel] " Ilya Dikariev
@ 2020-08-21 12:03 ` Keith A. Milner
0 siblings, 0 replies; 11+ messages in thread
From: Keith A. Milner @ 2020-08-21 12:03 UTC (permalink / raw)
To: alsa-devel; +Cc: Ilya Dikariev
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
^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2020-08-21 12:04 UTC | newest]
Thread overview: 11+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-08-22 20:25 Attempting to understand odd snd-usb-audio code and behavior Keith A. Milner
2017-08-23 10:23 ` Clemens Ladisch
2017-08-23 11:25 ` Keith A. Milner
2017-08-23 12:52 ` Clemens Ladisch
2017-08-23 22:43 ` Keith A. Milner
2017-08-23 22:49 ` Keith A. Milner
2018-01-22 14:06 ` Keith A. Milner
2018-01-22 15:40 ` Keith A. Milner
2018-01-22 18:14 ` Keith A. Milner
2020-04-05 0:14 ` Re: [alsa-devel] " Ilya Dikariev
2020-08-21 12:03 ` Keith A. Milner
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.