2021-01-22 08:12:44

by Jamie Heilman

[permalink] [raw]
Subject: bisected regression in v5.11-rc1 snd-usb-audio

I've bisected a failure in support for the M2Tech USB HiFace Two
192kHz Digital Audio Interface device (read as: a reclocked USB
S/PDIF) to the following ...

commit 93db51d06b32227319dae2ac289029ccf1b33181
Author: Takashi Iwai <[email protected]>
Date: Mon Nov 23 09:53:09 2020 +0100

ALSA: usb-audio: Check valid altsetting at parsing rates for UAC2/3

This has always been a somewhat finicky device, but my life is a
silent void without it, as it is currently a vital part of getting
audio to my mixer (now, if I could get USB Audio on my Rane MP2015
actually working right I'd very happily take that approach instead[1],
but I digress). It has been known to require replugging to initialize
properly at times, but until now, it's always worked fine eventually.

I've attached the dmesg from a working 5.10.9 kernel, the alsa-info
output, and the lsusb -vvv output for this device when it's
functioning. (Note, that alsa-info claims jack isn't running...
that's not actually true though, maybe because I'm using jack 2's
jackdbus subsystem, but jack is infact running, though it's probably
not relevant to the issue at hand[2].)

When I boot 93db51d06b32 or later I get lot of errors in the dmesg
like:

usb 1-1.1.2: New USB device found, idVendor=249c, idProduct=930b, bcdDevice= 2.13
usb 1-1.1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
usb 1-1.1.2: Product: M2Tech USB Audio 2.0
usb 1-1.1.2: Manufacturer: M2Tech
usb 1-1.1.2: SerialNumber: 0000
usb 1-1.1.2: cannot get ctl value: req = 0x83, wValue = 0x201, wIndex = 0xa00, type = 4
usb 1-1.1.2: 10:0: cannot get min/max values for control 2 (id 10)
usb 1-1.1.2: cannot get ctl value: req = 0x83, wValue = 0x200, wIndex = 0xa00, type = 4
usb 1-1.1.2: 10:0: cannot get min/max values for control 2 (id 10)
usbcore: registered new interface driver snd-usb-audio
usb 1-1.1-port2: disabled by hub (EMI?), re-enabling...
usb 1-1.1.2: USB disconnect, device number 6
usb 1-1.1.2: new full-speed USB device number 7 using ehci-pci
usb 1-1.1.2: device descriptor read/64, error -32
usb 1-1.1.2: device descriptor read/64, error -32
usb 1-1.1.2: new full-speed USB device number 8 using ehci-pci
usb 1-1.1.2: device descriptor read/64, error -32
usb 1-1.1.2: device descriptor read/64, error -32
usb 1-1.1-port2: attempt power cycle
usb 1-1.1.2: new full-speed USB device number 9 using ehci-pci
usb 1-1.1.2: device not accepting address 9, error -32
usb 1-1.1.2: new full-speed USB device number 10 using ehci-pci
usb 1-1.1.2: device not accepting address 10, error -32
usb 1-1.1-port2: unable to enumerate USB device

and obviously the device doesn't work at all. Sometimes there's more
"cannot get ctl value:" noise than other times, but the above is a
clean boot after being in a working state (it tends to require
replugging to get back to a being usable again after this, once I've
booted a working kernel, possibly becuase its hanging off a hub in my
monitor, not the most elegant of setups, I know---but none of this
changes even if I plug it directly into my workstation's USB ports, I
tried that).

I'm happy to try any patches, or provide more details, just ask.

--
Jamie Heilman http://audible.transient.net/~jamie/

[1] it's never been quite right, if you ever want to try to figure out
why, I'd be happy to tackle that separately

[2] just in case, jack_control dp output:
--- get driver parameters (type:isset:default:value)
device: ALSA device name (str:set:hw:0:hw:CARD=hiFace2,DEV=0)
capture: Provide capture ports. Optionally set device (str:notset:none:none)
playback: Provide playback ports. Optionally set device (str:set:none:hw:CARD=hiFace2,DEV=0)
rate: Sample rate (uint:set:48000:96000)
period: Frames per period (uint:notset:1024:1024)
nperiods: Number of periods of playback latency (uint:set:2:3)
hwmon: Hardware monitoring, if available (bool:notset:False:False)
hwmeter: Hardware metering, if available (bool:notset:False:False)
duplex: Provide both capture and playback ports (bool:notset:True:True)
softmode: Soft-mode, no xrun handling (bool:notset:False:False)
monitor: Provide monitor ports for the output (bool:notset:False:False)
dither: Dithering mode (char:notset:n:n)
inchannels: Number of capture channels (defaults to hardware max) (uint:notset:0:0)
outchannels: Number of playback channels (defaults to hardware max) (uint:notset:0:0)
shorts: Try 16-bit samples before 32-bit (bool:notset:False:False)
input-latency: Extra input latency (frames) (uint:notset:0:0)
output-latency: Extra output latency (frames) (uint:notset:0:0)
midi-driver: ALSA MIDI driver (str:notset:none:none)


Attachments:
(No filename) (4.84 kB)
v5.10.9-working-dmesg.txt (53.54 kB)
v5.10.9-working-alsa-info.txt (35.61 kB)
v5.10.9-working-lsusb-vvv.txt (15.71 kB)
Download all attachments

2021-01-22 08:48:55

by Takashi Iwai

[permalink] [raw]
Subject: Re: bisected regression in v5.11-rc1 snd-usb-audio

On Fri, 22 Jan 2021 09:09:08 +0100,
Jamie Heilman wrote:
>
> I've bisected a failure in support for the M2Tech USB HiFace Two
> 192kHz Digital Audio Interface device (read as: a reclocked USB
> S/PDIF) to the following ...
>
> commit 93db51d06b32227319dae2ac289029ccf1b33181
> Author: Takashi Iwai <[email protected]>
> Date: Mon Nov 23 09:53:09 2020 +0100
>
> ALSA: usb-audio: Check valid altsetting at parsing rates for UAC2/3
>
> This has always been a somewhat finicky device, but my life is a
> silent void without it, as it is currently a vital part of getting
> audio to my mixer (now, if I could get USB Audio on my Rane MP2015
> actually working right I'd very happily take that approach instead[1],
> but I digress). It has been known to require replugging to initialize
> properly at times, but until now, it's always worked fine eventually.
>
> I've attached the dmesg from a working 5.10.9 kernel, the alsa-info
> output, and the lsusb -vvv output for this device when it's
> functioning. (Note, that alsa-info claims jack isn't running...
> that's not actually true though, maybe because I'm using jack 2's
> jackdbus subsystem, but jack is infact running, though it's probably
> not relevant to the issue at hand[2].)
>
> When I boot 93db51d06b32 or later I get lot of errors in the dmesg
> like:
>
> usb 1-1.1.2: New USB device found, idVendor=249c, idProduct=930b, bcdDevice= 2.13
> usb 1-1.1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
> usb 1-1.1.2: Product: M2Tech USB Audio 2.0
> usb 1-1.1.2: Manufacturer: M2Tech
> usb 1-1.1.2: SerialNumber: 0000
> usb 1-1.1.2: cannot get ctl value: req = 0x83, wValue = 0x201, wIndex = 0xa00, type = 4
> usb 1-1.1.2: 10:0: cannot get min/max values for control 2 (id 10)
> usb 1-1.1.2: cannot get ctl value: req = 0x83, wValue = 0x200, wIndex = 0xa00, type = 4
> usb 1-1.1.2: 10:0: cannot get min/max values for control 2 (id 10)
> usbcore: registered new interface driver snd-usb-audio
> usb 1-1.1-port2: disabled by hub (EMI?), re-enabling...
> usb 1-1.1.2: USB disconnect, device number 6
> usb 1-1.1.2: new full-speed USB device number 7 using ehci-pci
> usb 1-1.1.2: device descriptor read/64, error -32
> usb 1-1.1.2: device descriptor read/64, error -32
> usb 1-1.1.2: new full-speed USB device number 8 using ehci-pci
> usb 1-1.1.2: device descriptor read/64, error -32
> usb 1-1.1.2: device descriptor read/64, error -32
> usb 1-1.1-port2: attempt power cycle
> usb 1-1.1.2: new full-speed USB device number 9 using ehci-pci
> usb 1-1.1.2: device not accepting address 9, error -32
> usb 1-1.1.2: new full-speed USB device number 10 using ehci-pci
> usb 1-1.1.2: device not accepting address 10, error -32
> usb 1-1.1-port2: unable to enumerate USB device
>
> and obviously the device doesn't work at all. Sometimes there's more
> "cannot get ctl value:" noise than other times, but the above is a
> clean boot after being in a working state (it tends to require
> replugging to get back to a being usable again after this, once I've
> booted a working kernel, possibly becuase its hanging off a hub in my
> monitor, not the most elegant of setups, I know---but none of this
> changes even if I plug it directly into my workstation's USB ports, I
> tried that).
>
> I'm happy to try any patches, or provide more details, just ask.

You seem hitting a firmware bug, and it doesn't look like the only
case. Interestingly, the backport of 5.11 USB-audio stuff on 5.3
kernel on openSUSE Leap 15.2 caused a similar bug on Steinberg device,
while it worked with 5.11-rc. So I thought this specific with the
older kernel (in USB core changes or such), but my guess seems wrong,
and the bug looks remaining in 5.11 for some cases.

Below is the fix patch. Please give it a try.


thanks,

Takashi

-- 8< --
From: Takashi Iwai <[email protected]>
Subject: [PATCH] ALSA: usb-audio: workaround for iface reset issue

The recently introduced sample rate validation code seems causing a
problem on some devices; namely, after performing this, the bus gets
screwed and it influences even on other USB devices.
As a quick workaround, perform it only for the necessary devices;
currently MOTU devices are known to need the valid altset checks, so
filter out other devices.

Fixes: 93db51d06b32 ("ALSA: usb-audio: Check valid altsetting at parsing rates for UAC2/3")
Reported-by: Jamie Heilman <[email protected]>
BugLink: https://bugzilla.suse.com/show_bug.cgi?id=1178203
Signed-off-by: Takashi Iwai <[email protected]>
---
sound/usb/format.c | 11 +++++++++++
1 file changed, 11 insertions(+)

diff --git a/sound/usb/format.c b/sound/usb/format.c
index 9ebc5d202c87..e6ff317a6785 100644
--- a/sound/usb/format.c
+++ b/sound/usb/format.c
@@ -466,6 +466,17 @@ static int validate_sample_rate_table_v2v3(struct snd_usb_audio *chip,
unsigned int nr_rates;
int i, err;

+ /* performing the rate verification may lead to unexpected USB bus
+ * behavior afterwards by some unknown reason. Do this only for the
+ * known devices.
+ */
+ switch (USB_ID_VENDOR(chip->usb_id)) {
+ case 0x07fd: /* MOTU */
+ break;
+ default:
+ return 0; /* don't perform the validation as default */
+ }
+
table = kcalloc(fp->nr_rates, sizeof(*table), GFP_KERNEL);
if (!table)
return -ENOMEM;
--
2.26.2

2021-01-22 10:09:53

by Jamie Heilman

[permalink] [raw]
Subject: Re: bisected regression in v5.11-rc1 snd-usb-audio

Takashi Iwai wrote:
> You seem hitting a firmware bug, and it doesn't look like the only
> case. Interestingly, the backport of 5.11 USB-audio stuff on 5.3
> kernel on openSUSE Leap 15.2 caused a similar bug on Steinberg device,
> while it worked with 5.11-rc. So I thought this specific with the
> older kernel (in USB core changes or such), but my guess seems wrong,
> and the bug looks remaining in 5.11 for some cases.
>
> Below is the fix patch. Please give it a try.
>
>
> thanks,
>
> Takashi
>
> -- 8< --
> From: Takashi Iwai <[email protected]>
> Subject: [PATCH] ALSA: usb-audio: workaround for iface reset issue
>
> The recently introduced sample rate validation code seems causing a
> problem on some devices; namely, after performing this, the bus gets
> screwed and it influences even on other USB devices.
> As a quick workaround, perform it only for the necessary devices;
> currently MOTU devices are known to need the valid altset checks, so
> filter out other devices.
>
> Fixes: 93db51d06b32 ("ALSA: usb-audio: Check valid altsetting at parsing rates for UAC2/3")
> Reported-by: Jamie Heilman <[email protected]>
> BugLink: https://bugzilla.suse.com/show_bug.cgi?id=1178203
> Signed-off-by: Takashi Iwai <[email protected]>
> ---
> sound/usb/format.c | 11 +++++++++++
> 1 file changed, 11 insertions(+)
>
> diff --git a/sound/usb/format.c b/sound/usb/format.c
> index 9ebc5d202c87..e6ff317a6785 100644
> --- a/sound/usb/format.c
> +++ b/sound/usb/format.c
> @@ -466,6 +466,17 @@ static int validate_sample_rate_table_v2v3(struct snd_usb_audio *chip,
> unsigned int nr_rates;
> int i, err;
>
> + /* performing the rate verification may lead to unexpected USB bus
> + * behavior afterwards by some unknown reason. Do this only for the
> + * known devices.
> + */
> + switch (USB_ID_VENDOR(chip->usb_id)) {
> + case 0x07fd: /* MOTU */
> + break;
> + default:
> + return 0; /* don't perform the validation as default */
> + }
> +
> table = kcalloc(fp->nr_rates, sizeof(*table), GFP_KERNEL);
> if (!table)
> return -ENOMEM;

Well, with this patch, while I can get it to seemingly initialize
without errors by replugging, I can't actually get it to work. Jack
says:

Starting jack server...
JACK server starting in realtime mode with priority 10
self-connect-mode is "Don't restrict self connect requests"
Acquired audio card Audio1
creating alsa driver ... hw:CARD=hiFace2,DEV=0|-|1024|3|96000|0|0|nomon|swmeter|-|32bit
ERROR: ALSA: Cannot open PCM device alsa_pcm for playback. Falling back to capture-only mode
Released audio card Audio1
ERROR: Cannot initialize driver
ERROR: JackServer::Open failed with -1
ERROR: Failed to open server

here's what aplay does when it tries:

aplay: main:830: audio open error: Invalid argument

strace of that says:
openat(AT_FDCWD, "/dev/snd/pcmC1D0p", O_RDWR|O_NONBLOCK|O_CLOEXEC) = -1 EINVAL (Invalid argument)

I dug up a different USB sound device (bithead) and plugged it in, it
still works just fine with the same commands.

The only difference I see in the alsa-info output is that

control.7 {
iface CARD
name 'Keep Interface'
value false
comment {
access 'read write'
type BOOLEAN
count 1
}
}

has gone missing. I've attached it incase you can spot something I
didn't (obviously the cards are in a different order which makes
things somewhat tedious for a direct comparison). Apart from the
device number on the usb bus, the lsusb -vvv output is the same as
it was in with 5.10.9.

--
Jamie Heilman http://audible.transient.net/~jamie/


Attachments:
(No filename) (3.74 kB)
v5.11.0-rc4-00164-g83d09ad4b950-dirty-alsa-info.txt (39.58 kB)
Download all attachments

2021-01-22 12:02:12

by Takashi Iwai

[permalink] [raw]
Subject: Re: bisected regression in v5.11-rc1 snd-usb-audio

On Fri, 22 Jan 2021 11:03:48 +0100,
Jamie Heilman wrote:
>
> Takashi Iwai wrote:
> > You seem hitting a firmware bug, and it doesn't look like the only
> > case. Interestingly, the backport of 5.11 USB-audio stuff on 5.3
> > kernel on openSUSE Leap 15.2 caused a similar bug on Steinberg device,
> > while it worked with 5.11-rc. So I thought this specific with the
> > older kernel (in USB core changes or such), but my guess seems wrong,
> > and the bug looks remaining in 5.11 for some cases.
> >
> > Below is the fix patch. Please give it a try.
> >
> >
> > thanks,
> >
> > Takashi
> >
> > -- 8< --
> > From: Takashi Iwai <[email protected]>
> > Subject: [PATCH] ALSA: usb-audio: workaround for iface reset issue
> >
> > The recently introduced sample rate validation code seems causing a
> > problem on some devices; namely, after performing this, the bus gets
> > screwed and it influences even on other USB devices.
> > As a quick workaround, perform it only for the necessary devices;
> > currently MOTU devices are known to need the valid altset checks, so
> > filter out other devices.
> >
> > Fixes: 93db51d06b32 ("ALSA: usb-audio: Check valid altsetting at parsing rates for UAC2/3")
> > Reported-by: Jamie Heilman <[email protected]>
> > BugLink: https://bugzilla.suse.com/show_bug.cgi?id=1178203
> > Signed-off-by: Takashi Iwai <[email protected]>
> > ---
> > sound/usb/format.c | 11 +++++++++++
> > 1 file changed, 11 insertions(+)
> >
> > diff --git a/sound/usb/format.c b/sound/usb/format.c
> > index 9ebc5d202c87..e6ff317a6785 100644
> > --- a/sound/usb/format.c
> > +++ b/sound/usb/format.c
> > @@ -466,6 +466,17 @@ static int validate_sample_rate_table_v2v3(struct snd_usb_audio *chip,
> > unsigned int nr_rates;
> > int i, err;
> >
> > + /* performing the rate verification may lead to unexpected USB bus
> > + * behavior afterwards by some unknown reason. Do this only for the
> > + * known devices.
> > + */
> > + switch (USB_ID_VENDOR(chip->usb_id)) {
> > + case 0x07fd: /* MOTU */
> > + break;
> > + default:
> > + return 0; /* don't perform the validation as default */
> > + }
> > +
> > table = kcalloc(fp->nr_rates, sizeof(*table), GFP_KERNEL);
> > if (!table)
> > return -ENOMEM;
>
> Well, with this patch, while I can get it to seemingly initialize
> without errors by replugging, I can't actually get it to work. Jack
> says:
>
> Starting jack server...
> JACK server starting in realtime mode with priority 10
> self-connect-mode is "Don't restrict self connect requests"
> Acquired audio card Audio1
> creating alsa driver ... hw:CARD=hiFace2,DEV=0|-|1024|3|96000|0|0|nomon|swmeter|-|32bit
> ERROR: ALSA: Cannot open PCM device alsa_pcm for playback. Falling back to capture-only mode
> Released audio card Audio1
> ERROR: Cannot initialize driver
> ERROR: JackServer::Open failed with -1
> ERROR: Failed to open server

Which kernel did you test? There have been a few more USB-audio fixes
that landed to Linus tree yesterday, so you'd need to test with it (in
addition to the previous patch).

> here's what aplay does when it tries:
>
> aplay: main:830: audio open error: Invalid argument
>
> strace of that says:
> openat(AT_FDCWD, "/dev/snd/pcmC1D0p", O_RDWR|O_NONBLOCK|O_CLOEXEC) = -1 EINVAL (Invalid argument)

Hm, it's weird that open returns -EINVAL, not the later ioctl...

> I dug up a different USB sound device (bithead) and plugged it in, it
> still works just fine with the same commands.
>
> The only difference I see in the alsa-info output is that
>
> control.7 {
> iface CARD
> name 'Keep Interface'
> value false
> comment {
> access 'read write'
> type BOOLEAN
> count 1
> }
> }
>
> has gone missing.

This is an intended change and should be irrelevant.

If the problem is still seen with the very latest Linus tree and the
previous patch, please enable the dyndbg, e.g. pass dydbg=+p option to
snd-usb-audio module, i.e. reload like
modprobe snd-usb-audio dydbg=+p
or boot with
snd_usb_audio.dyndbg=+p
boot option, retest, and give the kernel messages.


thanks,

Takashi

2021-01-23 11:11:38

by Jamie Heilman

[permalink] [raw]
Subject: Re: bisected regression in v5.11-rc1 snd-usb-audio

Takashi Iwai wrote:
> On Fri, 22 Jan 2021 11:03:48 +0100,
> Jamie Heilman wrote:
> >
> > Takashi Iwai wrote:
> > > You seem hitting a firmware bug, and it doesn't look like the only
> > > case. Interestingly, the backport of 5.11 USB-audio stuff on 5.3
> > > kernel on openSUSE Leap 15.2 caused a similar bug on Steinberg device,
> > > while it worked with 5.11-rc. So I thought this specific with the
> > > older kernel (in USB core changes or such), but my guess seems wrong,
> > > and the bug looks remaining in 5.11 for some cases.
> > >
> > > Below is the fix patch. Please give it a try.
> > >
> > >
> > > thanks,
> > >
> > > Takashi
> > >
> > > -- 8< --
> > > From: Takashi Iwai <[email protected]>
> > > Subject: [PATCH] ALSA: usb-audio: workaround for iface reset issue
> > >
> > > The recently introduced sample rate validation code seems causing a
> > > problem on some devices; namely, after performing this, the bus gets
> > > screwed and it influences even on other USB devices.
> > > As a quick workaround, perform it only for the necessary devices;
> > > currently MOTU devices are known to need the valid altset checks, so
> > > filter out other devices.
> > >
> > > Fixes: 93db51d06b32 ("ALSA: usb-audio: Check valid altsetting at parsing rates for UAC2/3")
> > > Reported-by: Jamie Heilman <[email protected]>
> > > BugLink: https://bugzilla.suse.com/show_bug.cgi?id=1178203
> > > Signed-off-by: Takashi Iwai <[email protected]>
> > > ---
> > > sound/usb/format.c | 11 +++++++++++
> > > 1 file changed, 11 insertions(+)
> > >
> > > diff --git a/sound/usb/format.c b/sound/usb/format.c
> > > index 9ebc5d202c87..e6ff317a6785 100644
> > > --- a/sound/usb/format.c
> > > +++ b/sound/usb/format.c
> > > @@ -466,6 +466,17 @@ static int validate_sample_rate_table_v2v3(struct snd_usb_audio *chip,
> > > unsigned int nr_rates;
> > > int i, err;
> > >
> > > + /* performing the rate verification may lead to unexpected USB bus
> > > + * behavior afterwards by some unknown reason. Do this only for the
> > > + * known devices.
> > > + */
> > > + switch (USB_ID_VENDOR(chip->usb_id)) {
> > > + case 0x07fd: /* MOTU */
> > > + break;
> > > + default:
> > > + return 0; /* don't perform the validation as default */
> > > + }
> > > +
> > > table = kcalloc(fp->nr_rates, sizeof(*table), GFP_KERNEL);
> > > if (!table)
> > > return -ENOMEM;
> >
> > Well, with this patch, while I can get it to seemingly initialize
> > without errors by replugging, I can't actually get it to work. Jack
> > says:
> >
> > Starting jack server...
> > JACK server starting in realtime mode with priority 10
> > self-connect-mode is "Don't restrict self connect requests"
> > Acquired audio card Audio1
> > creating alsa driver ... hw:CARD=hiFace2,DEV=0|-|1024|3|96000|0|0|nomon|swmeter|-|32bit
> > ERROR: ALSA: Cannot open PCM device alsa_pcm for playback. Falling back to capture-only mode
> > Released audio card Audio1
> > ERROR: Cannot initialize driver
> > ERROR: JackServer::Open failed with -1
> > ERROR: Failed to open server
>
> Which kernel did you test? There have been a few more USB-audio fixes
> that landed to Linus tree yesterday, so you'd need to test with it (in
> addition to the previous patch).

Sorry, thought that'd be clear from the alsa-info output, but yes, the
tip of Linus's tree at the time: 5.11.0-rc4-00164-g83d09ad4b950

> > here's what aplay does when it tries:
> >
> > aplay: main:830: audio open error: Invalid argument
> >
> > strace of that says:
> > openat(AT_FDCWD, "/dev/snd/pcmC1D0p", O_RDWR|O_NONBLOCK|O_CLOEXEC) = -1 EINVAL (Invalid argument)
>
> Hm, it's weird that open returns -EINVAL, not the later ioctl...
>
> > I dug up a different USB sound device (bithead) and plugged it in, it
> > still works just fine with the same commands.
> >
> > The only difference I see in the alsa-info output is that
> >
> > control.7 {
> > iface CARD
> > name 'Keep Interface'
> > value false
> > comment {
> > access 'read write'
> > type BOOLEAN
> > count 1
> > }
> > }
> >
> > has gone missing.
>
> This is an intended change and should be irrelevant.

Groovy.

> If the problem is still seen with the very latest Linus tree and the
> previous patch, please enable the dyndbg, e.g. pass dydbg=+p option to
> snd-usb-audio module, i.e. reload like
> modprobe snd-usb-audio dydbg=+p
> or boot with
> snd_usb_audio.dyndbg=+p
> boot option, retest, and give the kernel messages.

OK, updated to 5.11.0-rc4-00202-gfe75a21824e7, repatched & rebuilt with:
CONFIG_SND_DEBUG=y
CONFIG_SND_CTL_VALIDATION=y
CONFIG_DYNAMIC_DEBUG=y
CONFIG_DYNAMIC_DEBUG_CORE=y

and added dyndbg=+p to my snd-usb-audio options, dmesg after an
attempted aplay execution is attached. For grins I built a 5.10.9
kernel with the same config to compare ... the difference between
5.10.9 and 5.11.0-rc4-00202-gfe75a21824e7 debug output is basically:


+usb 1-1.1.2: 1:1: found sync_ep=0x81, iface=1, alt=1, implicit_fb=0
usb 1-1.1.2: 1:1: add audio endpoint 0x1
+usb 1-1.1.2: Creating new data endpoint #1
+usb 1-1.1.2: Creating new sync endpoint #81
+usb 1-1.1.2: 1:1 Set sample rate 192000, clock 40
usb 1-1.1.2: [10] FU [M2Tech Audio 2.0 Output Playback Switch] ch = 2, val = 0/1/1
usb 1-1.1.2: [10] FU [M2Tech Audio 2.0 Output Playback Switch] ch = 1, val = 0/1/1
usb 1-1.1.2: RANGE setting not yet supported
usb 1-1.1.2: [10] FU [M2Tech Audio 2.0 Output Playback Volume] ch = 2, val = -32512/0/256
usb 1-1.1.2: RANGE setting not yet supported
usb 1-1.1.2: [10] FU [M2Tech Audio 2.0 Output Playback Volume] ch = 1, val = -32512/0/256

...and then on 5.10.9 once I start up jackd ...

-usb 1-1.1.2: setting usb interface 1:1
-usb 1-1.1.2: Creating new playback data endpoint #1
-usb 1-1.1.2: Creating new capture sync endpoint #81
-usb 1-1.1.2: Setting params for ep #1 (type 0, 12 urbs), ret=0
-usb 1-1.1.2: Setting params for ep #81 (type 1, 4 urbs), ret=0
-usb 1-1.1.2: Starting data EP @00000000d63f36f3
-usb 1-1.1.2: Starting sync EP @00000000e9f3024b

--
Jamie Heilman http://audible.transient.net/~jamie/


Attachments:
(No filename) (6.26 kB)
v5.11.0-rc4-00202-gfe75a21824e7-dirty-dmesg.txt (59.00 kB)
Download all attachments

2021-01-23 12:44:35

by Takashi Iwai

[permalink] [raw]
Subject: Re: bisected regression in v5.11-rc1 snd-usb-audio

On Sat, 23 Jan 2021 12:08:02 +0100,
Jamie Heilman wrote:
>
> > If the problem is still seen with the very latest Linus tree and the
> > previous patch, please enable the dyndbg, e.g. pass dydbg=+p option to
> > snd-usb-audio module, i.e. reload like
> > modprobe snd-usb-audio dydbg=+p
> > or boot with
> > snd_usb_audio.dyndbg=+p
> > boot option, retest, and give the kernel messages.
>
> OK, updated to 5.11.0-rc4-00202-gfe75a21824e7, repatched & rebuilt with:
> CONFIG_SND_DEBUG=y
> CONFIG_SND_CTL_VALIDATION=y
> CONFIG_DYNAMIC_DEBUG=y
> CONFIG_DYNAMIC_DEBUG_CORE=y
>
> and added dyndbg=+p to my snd-usb-audio options, dmesg after an
> attempted aplay execution is attached.
(snip)
> [ 108.941521] WARNING: CPU: 0 PID: 2776 at sound/core/pcm_lib.c:1148 snd_pcm_hw_rule_add+0xd3/0x160 [snd_pcm]

OK, this must be the culprit of the weird behavior.
I totally overlooked that the max dependencies are three because of
the terminator.

Could you try the patch below in addition?


thanks,

Takashi

--- a/include/sound/pcm.h
+++ b/include/sound/pcm.h
@@ -229,7 +229,7 @@ typedef int (*snd_pcm_hw_rule_func_t)(struct snd_pcm_hw_params *params,
struct snd_pcm_hw_rule {
unsigned int cond;
int var;
- int deps[4];
+ int deps[5];

snd_pcm_hw_rule_func_t func;
void *private;

2021-01-23 22:46:34

by Jamie Heilman

[permalink] [raw]
Subject: Re: bisected regression in v5.11-rc1 snd-usb-audio

Takashi Iwai wrote:
> On Sat, 23 Jan 2021 12:08:02 +0100,
> Jamie Heilman wrote:
> >
> > > If the problem is still seen with the very latest Linus tree and the
> > > previous patch, please enable the dyndbg, e.g. pass dydbg=+p option to
> > > snd-usb-audio module, i.e. reload like
> > > modprobe snd-usb-audio dydbg=+p
> > > or boot with
> > > snd_usb_audio.dyndbg=+p
> > > boot option, retest, and give the kernel messages.
> >
> > OK, updated to 5.11.0-rc4-00202-gfe75a21824e7, repatched & rebuilt with:
> > CONFIG_SND_DEBUG=y
> > CONFIG_SND_CTL_VALIDATION=y
> > CONFIG_DYNAMIC_DEBUG=y
> > CONFIG_DYNAMIC_DEBUG_CORE=y
> >
> > and added dyndbg=+p to my snd-usb-audio options, dmesg after an
> > attempted aplay execution is attached.
> (snip)
> > [ 108.941521] WARNING: CPU: 0 PID: 2776 at sound/core/pcm_lib.c:1148 snd_pcm_hw_rule_add+0xd3/0x160 [snd_pcm]
>
> OK, this must be the culprit of the weird behavior.
> I totally overlooked that the max dependencies are three because of
> the terminator.
>
> Could you try the patch below in addition?

Yep, this works now, thanks! FWIW, here's what the debug output looks
like when its working, and I start jack now:

usb 1-1.1.2: 1:1: found sync_ep=0x81, iface=1, alt=1, implicit_fb=0
usb 1-1.1.2: 1:1: add audio endpoint 0x1
usb 1-1.1.2: Creating new data endpoint #1
usb 1-1.1.2: Creating new sync endpoint #81
usb 1-1.1.2: 1:1 Set sample rate 192000, clock 40
usb 1-1.1.2: [10] FU [M2Tech Audio 2.0 Output Playback Switch] ch = 2, val = 0/1/1
usb 1-1.1.2: [10] FU [M2Tech Audio 2.0 Output Playback Switch] ch = 1, val = 0/1/1
usb 1-1.1.2: RANGE setting not yet supported
usb 1-1.1.2: [10] FU [M2Tech Audio 2.0 Output Playback Volume] ch = 2, val = -32512/0/256
usb 1-1.1.2: RANGE setting not yet supported
usb 1-1.1.2: [10] FU [M2Tech Audio 2.0 Output Playback Volume] ch = 1, val = -32512/0/256
usb 1-1.1.2: Open EP 0x1, iface=1:1, idx=0
usb 1-1.1.2: channels=2, rate=96000, format=S32_LE, period_bytes=8192, periods=3, implicit_fb=0
usb 1-1.1.2: Open EP 0x81, iface=1:1, idx=1
usb 1-1.1.2: channels=2, rate=96000, format=S32_LE, period_bytes=8192, periods=3, implicit_fb=0
usb 1-1.1.2: Setting usb interface 1:0 for EP 0x1
usb 1-1.1.2: 1:1 Set sample rate 96000, clock 40
usb 1-1.1.2: Setting params for data EP 0x1, pipe 0x8600
usb 1-1.1.2: Set up 12 URBS, ret=0
usb 1-1.1.2: Setting usb interface 1:1 for EP 0x1
usb 1-1.1.2: Setting params for sync EP 0x81, pipe 0x8680
usb 1-1.1.2: Set up 4 URBS, ret=0
usb 1-1.1.2: Starting data EP 0x1 (running 0)
usb 1-1.1.2: 12 URBs submitted for EP 0x1
usb 1-1.1.2: Starting sync EP 0x81 (running 0)
usb 1-1.1.2: 4 URBs submitted for EP 0x81
usb 1-1.1.2: 1:1 Start Playback PCM


> --- a/include/sound/pcm.h
> +++ b/include/sound/pcm.h
> @@ -229,7 +229,7 @@ typedef int (*snd_pcm_hw_rule_func_t)(struct snd_pcm_hw_params *params,
> struct snd_pcm_hw_rule {
> unsigned int cond;
> int var;
> - int deps[4];
> + int deps[5];
>
> snd_pcm_hw_rule_func_t func;
> void *private;

--
Jamie Heilman http://audible.transient.net/~jamie/