[PATCH] usb-audio: Rate limit usb_set_interface error reporting
When an error occurs during USB disconnection sometimes things can go wrong as endpoint_set_interface may end up being called repeatedly. For example:
% dmesg --notime | grep 'usb 3-7.1.4' | sort | uniq -c | head -2 3069 usb 3-7.1.4: 1:1: usb_set_interface failed (-19) 908 usb 3-7.1.4: 1:1: usb_set_interface failed (-71)
In my case, there sometimes are hundreds of these usb_set_interface failure messages a second when I disconnect the hub that has my USB audio device.
These messages can take a huge amount of the kmsg ringbuffer and don't provide any extra information over the previous ones, so ratelimit them.
Signed-off-by: Chris Down chris@chrisdown.name --- sound/usb/endpoint.c | 5 +++-- sound/usb/usbaudio.h | 2 ++ 2 files changed, 5 insertions(+), 2 deletions(-)
diff --git a/sound/usb/endpoint.c b/sound/usb/endpoint.c index 647fa054d8b1..2cd99cc8c360 100644 --- a/sound/usb/endpoint.c +++ b/sound/usb/endpoint.c @@ -916,8 +916,9 @@ static int endpoint_set_interface(struct snd_usb_audio *chip, ep->iface, altset, ep->ep_num); err = usb_set_interface(chip->dev, ep->iface, altset); if (err < 0) { - usb_audio_err(chip, "%d:%d: usb_set_interface failed (%d)\n", - ep->iface, altset, err); + usb_audio_err_ratelimited( + chip, "%d:%d: usb_set_interface failed (%d)\n", + ep->iface, altset, err); return err; }
diff --git a/sound/usb/usbaudio.h b/sound/usb/usbaudio.h index f5a8dca66457..38a85b2c9a73 100644 --- a/sound/usb/usbaudio.h +++ b/sound/usb/usbaudio.h @@ -67,6 +67,8 @@ struct snd_usb_audio {
#define usb_audio_err(chip, fmt, args...) \ dev_err(&(chip)->dev->dev, fmt, ##args) +#define usb_audio_err_ratelimited(chip, fmt, args...) \ + dev_err_ratelimited(&(chip)->dev->dev, fmt, ##args) #define usb_audio_warn(chip, fmt, args...) \ dev_warn(&(chip)->dev->dev, fmt, ##args) #define usb_audio_info(chip, fmt, args...) \
On Fri, 21 Apr 2023 16:38:41 +0200, Chris Down wrote:
When an error occurs during USB disconnection sometimes things can go wrong as endpoint_set_interface may end up being called repeatedly. For example:
% dmesg --notime | grep 'usb 3-7.1.4' | sort | uniq -c | head -2 3069 usb 3-7.1.4: 1:1: usb_set_interface failed (-19) 908 usb 3-7.1.4: 1:1: usb_set_interface failed (-71)
In my case, there sometimes are hundreds of these usb_set_interface failure messages a second when I disconnect the hub that has my USB audio device.
These messages can take a huge amount of the kmsg ringbuffer and don't provide any extra information over the previous ones, so ratelimit them.
Signed-off-by: Chris Down chris@chrisdown.name
This patch itself is safe and good to have, so I'm going to take it as is.
But I'm still curious in which code path the problem happens. That is, we should address such unnecessary repeats if possible. Do you have some more data?
thanks,
Takashi
Hi Takashi,
Takashi Iwai writes:
This patch itself is safe and good to have, so I'm going to take it as is.
Thanks!
But I'm still curious in which code path the problem happens. That is, we should address such unnecessary repeats if possible. Do you have some more data?
Unfortunately not, I've been running with a kernel testing some other mm changes recently so haven't had a chance to debug what's going on here. But it starts like this:
[Fri Apr 21 13:21:10 2023] usb 3-7: USB disconnect, device number 39 [Fri Apr 21 13:21:10 2023] usb 3-7.1: USB disconnect, device number 40 [Fri Apr 21 13:21:10 2023] usb 3-7.1.1: USB disconnect, device number 42 [Fri Apr 21 13:21:10 2023] usb 3-7.4: cannot submit urb (err = -19) [Fri Apr 21 13:21:10 2023] usb 3-7.4: Unable to submit urb #2: -19 at snd_usb_queue_pending_output_urbs [Fri Apr 21 13:21:10 2023] usb 3-7.4: cannot submit urb 0, error -19: no device [Fri Apr 21 13:21:10 2023] usb 3-7.4: cannot submit urb 0, error -19: no device [Fri Apr 21 13:21:10 2023] usb 3-7.4: cannot submit urb 0, error -19: no device [Fri Apr 21 13:21:10 2023] usb 3-7.4: 1:0: usb_set_interface failed (-19) [Fri Apr 21 13:21:10 2023] usb 3-7.4: 2:0: usb_set_interface failed (-19) [Fri Apr 21 13:21:10 2023] usb 3-7.1.2: USB disconnect, device number 44 [Fri Apr 21 13:21:10 2023] usb 3-7.1.4: 1:1: usb_set_interface failed (-19) [Fri Apr 21 13:21:10 2023] usb 3-7.1.4: 1:1: usb_set_interface failed (-19) [Fri Apr 21 13:21:10 2023] usb 3-7.1.4: 1:1: usb_set_interface failed (-19) [Fri Apr 21 13:21:10 2023] usb 3-7.1.4: 1:1: usb_set_interface failed (-19) [Fri Apr 21 13:21:10 2023] usb 3-7.1.4: 1:1: usb_set_interface failed (-19) [Fri Apr 21 13:21:10 2023] usb 3-7.1.4: 1:1: usb_set_interface failed (-19) [Fri Apr 21 13:21:10 2023] usb 3-7.1.4: 1:1: usb_set_interface failed (-19) [Fri Apr 21 13:21:10 2023] usb 3-7.1.4: 1:1: usb_set_interface failed (-19) [... thousands of messages ensue ...]
So it looks like maybe some ordering is not quite right in destruction, perhaps only on multi-level USB topologies?
Thanks,
Chris
On Fri, 21 Apr 2023 16:48:27 +0200, Chris Down wrote:
Hi Takashi,
Takashi Iwai writes:
This patch itself is safe and good to have, so I'm going to take it as is.
Thanks!
But I'm still curious in which code path the problem happens. That is, we should address such unnecessary repeats if possible. Do you have some more data?
Unfortunately not, I've been running with a kernel testing some other mm changes recently so haven't had a chance to debug what's going on here. But it starts like this:
[Fri Apr 21 13:21:10 2023] usb 3-7: USB disconnect, device number 39 [Fri Apr 21 13:21:10 2023] usb 3-7.1: USB disconnect, device number 40 [Fri Apr 21 13:21:10 2023] usb 3-7.1.1: USB disconnect, device number 42 [Fri Apr 21 13:21:10 2023] usb 3-7.4: cannot submit urb (err = -19) [Fri Apr 21 13:21:10 2023] usb 3-7.4: Unable to submit urb #2: -19 at snd_usb_queue_pending_output_urbs [Fri Apr 21 13:21:10 2023] usb 3-7.4: cannot submit urb 0, error -19: no device [Fri Apr 21 13:21:10 2023] usb 3-7.4: cannot submit urb 0, error -19: no device [Fri Apr 21 13:21:10 2023] usb 3-7.4: cannot submit urb 0, error -19: no device [Fri Apr 21 13:21:10 2023] usb 3-7.4: 1:0: usb_set_interface failed (-19) [Fri Apr 21 13:21:10 2023] usb 3-7.4: 2:0: usb_set_interface failed (-19) [Fri Apr 21 13:21:10 2023] usb 3-7.1.2: USB disconnect, device number 44 [Fri Apr 21 13:21:10 2023] usb 3-7.1.4: 1:1: usb_set_interface failed (-19) [Fri Apr 21 13:21:10 2023] usb 3-7.1.4: 1:1: usb_set_interface failed (-19) [Fri Apr 21 13:21:10 2023] usb 3-7.1.4: 1:1: usb_set_interface failed (-19) [Fri Apr 21 13:21:10 2023] usb 3-7.1.4: 1:1: usb_set_interface failed (-19) [Fri Apr 21 13:21:10 2023] usb 3-7.1.4: 1:1: usb_set_interface failed (-19) [Fri Apr 21 13:21:10 2023] usb 3-7.1.4: 1:1: usb_set_interface failed (-19) [Fri Apr 21 13:21:10 2023] usb 3-7.1.4: 1:1: usb_set_interface failed (-19) [Fri Apr 21 13:21:10 2023] usb 3-7.1.4: 1:1: usb_set_interface failed (-19) [... thousands of messages ensue ...]So it looks like maybe some ordering is not quite right in destruction, perhaps only on multi-level USB topologies?
Hrm, is "usb 3-7.1.4" really the USB audio device? The previous errors like "Unable to submit urb #2..." are certainly for USB audio, and those are with "usb 3-7.4".
You patch may still make sense, though. So I'll keep it applied.
thanks,
Takashi
Takashi Iwai writes:
Hrm, is "usb 3-7.1.4" really the USB audio device? The previous errors like "Unable to submit urb #2..." are certainly for USB audio, and those are with "usb 3-7.4".
There are two USB audio devices -- 3-7.1.4 is input, 3-7.4 is output.
% dmesg --notime | grep -e 'usb 3-7.4' -e 'usb 3-7.1.4' | grep Product: | sort | uniq usb 3-7.1.4: Product: USB2.0 Microphone usb 3-7.4: Product: USB Audio Device
Thanks,
Chris
On Fri, 21 Apr 2023 17:16:59 +0200, Chris Down wrote:
Takashi Iwai writes:
Hrm, is "usb 3-7.1.4" really the USB audio device? The previous errors like "Unable to submit urb #2..." are certainly for USB audio, and those are with "usb 3-7.4".
There are two USB audio devices -- 3-7.1.4 is input, 3-7.4 is output.
% dmesg --notime | grep -e 'usb 3-7.4' -e 'usb 3-7.1.4' | grep Product: | sort | uniq usb 3-7.1.4: Product: USB2.0 Microphone usb 3-7.4: Product: USB Audio Device
Ah I see. Then those are two different sound cards?
The repeated call of usb_set_interface() might be avoided by the additional check like below. But it's still puzzling how it happens, because the only caller of endpoint_set_interface() you modified is snd_usb_endpoint_prepare(), and it's called only from snd_usb_pcm_prepare(). And, snd_usb_pcm_preapre() has the snd_usb_lock_shutdown() call, which does the check of the card->shutdown flag that should be set by the USB disconnection callback...
thanks,
Takashi
-- 8< -- --- a/sound/usb/endpoint.c +++ b/sound/usb/endpoint.c @@ -911,6 +911,9 @@ static int endpoint_set_interface(struct snd_usb_audio *chip,
if (ep->iface_ref->altset == altset) return 0; + /* already disconnected? */ + if (unlikely(atomic_read(&chip->shutdown))) + return -ENODEV;
usb_audio_dbg(chip, "Setting usb interface %d:%d for EP 0x%x\n", ep->iface, altset, ep->ep_num);
participants (2)
-
Chris Down -
Takashi Iwai