Date:   Thu, 18 Nov 2021 17:57:35 +0100
Message-ID: <s5hilwph05c.wl-tiwai@suse.de>
From:   Takashi Iwai <tiwai@suse.de>
To:     "Kirill A. Shutemov" <kirill@shutemov.name>
Cc:     Linus Torvalds <torvalds@linux-foundation.org>,
        Mark Brown <broonie@kernel.org>,
        Liam Girdwood <lgirdwood@gmail.com>,
        Linux Kernel Mailing List <linux-kernel@vger.kernel.org>
Subject: Re: [GIT PULL] sound updates for 5.16-rc1
In-Reply-To: <s5hpmqxki3h.wl-tiwai@suse.de>
References: <s5hwnlpmt9x.wl-tiwai@suse.de>
        <20211117161855.m45mxcqszkfcetai@box.shutemov.name>
        <s5hmtm2lphf.wl-tiwai@suse.de>
        <20211117174826.23eakoivl33tawb2@box.shutemov.name>
        <s5hfsrulkxk.wl-tiwai@suse.de>
        <s5hpmqxki3h.wl-tiwai@suse.de>
User-Agent: Wanderlust/2.15.9 (Almost Unreal) SEMI/1.14.6 (Maruoka)
 FLIM/1.14.9 (=?UTF-8?B?R29qxY0=?=) APEL/10.8 Emacs/25.3
 (x86_64-suse-linux-gnu) MULE/6.0 (HANACHIRUSATO)
MIME-Version: 1.0 (generated by SEMI 1.14.6 - "Maruoka")
Content-Type: text/plain; charset=US-ASCII
Precedence: bulk

On Thu, 18 Nov 2021 09:01:38 +0100,
Takashi Iwai wrote:
> 
> On Wed, 17 Nov 2021 19:02:47 +0100,
> Takashi Iwai wrote:
> > 
> > On Wed, 17 Nov 2021 18:48:26 +0100,
> > Kirill A. Shutemov wrote:
> > > 
> > > On Wed, Nov 17, 2021 at 05:24:28PM +0100, Takashi Iwai wrote:
> > > > On Wed, 17 Nov 2021 17:18:55 +0100,
> > > > Kirill A. Shutemov wrote:
> > > > > 
> > > > > On Wed, Nov 03, 2021 at 11:24:10AM +0100, Takashi Iwai wrote:
> > > > > > Linus,
> > > > > > 
> > > > > > please pull sound updates for v5.16-rc1 from:
> > > > > > 
> > > > > >   git://git.kernel.org/pub/scm/linux/kernel/git/tiwai/sound.git tags/sound-5.16-rc1
> > > > > > 
> > > > > > The topmost commit is df0380b9539b04c1ae8854a984098da06d5f1e67
> > > > > > 
> > > > > > ----------------------------------------------------------------
> > > > > > 
> > > > > > sound updates for 5.16-rc1
> > > > > > 
> > > > > > Lots of code development have been see in ASoC side as usual, while
> > > > > > the continued development on memalloc helper and USB-audio low-
> > > > > > latency support are found in the rest.  Note that a few changes in the
> > > > > > unusual places like arch/sh are included, which are a part of ASoC DAI
> > > > > > format cleanups.
> > > > > > 
> > > > > > ALSA core:
> > > > > > - Continued memallloc helper updates and cleanups, now supporting
> > > > > >   non-coherent and non-contiguous pages
> > > > > > - Fixes for races in mixer OSS layer
> > > > > > 
> > > > > > ASoC:
> > > > > > - A new version of the audio graph card which supports a wider range
> > > > > >   of systems
> > > > > > - Several conversions to YAML DT bindings
> > > > > > - Continuing cleanups to the SOF and Intel code
> > > > > > - Move of the Cirrus DSP framework into drivers/firmware to allow for
> > > > > >   future use by non-audio DSPs
> > > > > > - An overhaul of the cs42l42 driver, correcting many problems
> > > > > > - DAI format terminology conversions over many drivers for cleanups
> > > > > > - Support for AMD Vangogh and Yelow Cap, Cirrus CS35L41, Maxim
> > > > > >   MAX98520 and MAX98360A, Mediatek MT8195, Nuvoton NAU8821, nVidia
> > > > > >   Tegra210, NXP i.MX8ULP, Qualcomm AudioReach, Realtek ALC5682I-VS,
> > > > > >   RT5682S, and RT9120 and Rockchip RV1126 and RK3568
> > > > > > 
> > > > > > USB-audio:
> > > > > > - Continued improvements on low-latency playback
> > > > > > - Quirks for Pioneer devices, Line6 HX-Stomp XL, Audient iD14
> > > > > > 
> > > > > > HD-audio:
> > > > > > - Reduce excessive udelay() calls on Intel platforms; this should
> > > > > >   reduce the CPU load with PulseAudio
> > > > > > - Quirks for HP and Clevo laptops
> > > > > > 
> > > > > > FireWire:
> > > > > > - Support for meter information on MOTU
> > > > > > 
> > > > > 
> > > > > ...
> > > > > 
> > > > > > Takashi Iwai (29):
> > > > > >       ALSA: hda: Reduce udelay() at SKL+ position reporting
> > > > > >       ALSA: hda: Use position buffer for SKL+ again
> > > > > >       ALSA: usb-audio: Restrict rates for the shared clocks
> > > > > >       ALSA: usb-audio: Fix possible race at sync of urb completions
> > > > > >       ALSA: usb-audio: Rename early_playback_start flag with lowlatency_playback
> > > > > >       ALSA: usb-audio: Disable low-latency playback for free-wheel mode
> > > > > >       ALSA: usb-audio: Disable low-latency mode for implicit feedback sync
> > > > > >       ALSA: usb-audio: Check available frames for the next packet size
> > > > > >       ALSA: usb-audio: Add spinlock to stop_urbs()
> > > > > >       ALSA: usb-audio: Improved lowlatency playback support
> > > > > 
> > > > > This commit breaks audio playback for me. The sample plays for fraction of
> > > > > a second than stops.
> > > > > 
> > > > > I use SMSL SA300. Let me know what ifo is needed to track it down.
> > > > > 
> > > > > Also I can test potential fixups if needed.
> > > > 
> > > > Could you give alsa-info.sh output with the device?  Run the script
> > > > with --no-upload option, and attach the output.
> > > 
> > > Attached. I run it on kernel without the commit. I hope it is fine.
> > > 
> > > One note: I use monolitic kernel without CONFIG_MODULES. The script
> > > complained about missing /proc/asound/modules and other modules related
> > > stuff.
> > 
> > It's a known problem I forgot, but this doesn't matter much.
> > 
> > > > Also /proc/asound/card*/stream* file for that usb device, too,
> > > > please.
> > > 
> > > Attached.
> > 
> > Thanks!
> > 
> > > > And, which environment are you testing, more exactly?  Which platform,
> > > > and with PulseAudio, pipewire, JACK, or direct ALSA device use?
> > > 
> > > Nothing fancy. Direct ALSA. I tested with 'speaker-test -c2 -t wav' during
> > > bisect.
> > 
> > Did you notice the problem with other applications, too?
> > 
> > When you wrote "The sample plays for fraction of a second than
> > stops.", it means that the speaker-test program stalls?  Or it's
> > shorter playbacks?
> > 
> > Also, please test booting with snd_usb_audio.lowlatency=0 boot
> > option.  Does it behave like before again?
> > 
> > > > For checking the behavior, we'd need to check hw_params in
> > > > /proc/asound/card*/pcm*/sub*/* for the corresponding device during
> > > > playback/capture operations.
> > > 
> > > You need this to be collected when the problem triggers, right?
> > > I will follow up with this.
> > 
> > I'll need to test my device at first.  Maybe tomorrow.
> 
> I checked mine, and all worked fine.  So this doesn't look like a
> generic breakage but somehow specific to certain devices or system.
> 
> Could you verify the lowlatency flag off?
> 
> Also, the simple aplay invocation (e.g. with a 2-channel 16bit sample)
> also goes to the same problem, I suppose?

And it'd be helpful if you can gather the log (from tracing) with the
patch below (from the start of speaker-test until the stall).


Takashi

diff --git a/sound/usb/endpoint.c b/sound/usb/endpoint.c
index 743b8287cfcd..b48e53b490b8 100644
--- a/sound/usb/endpoint.c
+++ b/sound/usb/endpoint.c
@@ -392,6 +392,7 @@ static void notify_xrun(struct snd_usb_endpoint *ep)
 {
 	struct snd_usb_substream *data_subs;
 
+	DBG("XXX XRUN!\n");
 	data_subs = READ_ONCE(ep->data_subs);
 	if (data_subs && data_subs->pcm_substream)
 		snd_pcm_stop_xrun(data_subs->pcm_substream);
@@ -425,6 +426,7 @@ static void push_back_to_ready_list(struct snd_usb_endpoint *ep,
 {
 	unsigned long flags;
 
+	DBG("pkt %d push back\n", ctx->index);
 	spin_lock_irqsave(&ep->lock, flags);
 	list_add_tail(&ctx->ready_list, &ep->ready_playback_urbs);
 	spin_unlock_irqrestore(&ep->lock, flags);
@@ -470,6 +472,8 @@ void snd_usb_queue_pending_output_urbs(struct snd_usb_endpoint *ep,
 		if (ctx == NULL)
 			return;
 
+		DBG("checking queue pkt %d (active_mask=%lx)\n", ctx->index,
+		    ep->active_mask);
 		/* copy over the length information */
 		if (implicit_fb) {
 			for (i = 0; i < packet->packets; i++)
@@ -490,6 +494,7 @@ void snd_usb_queue_pending_output_urbs(struct snd_usb_endpoint *ep,
 			return;
 		}
 
+		DBG("pkt %d submitted\n", ctx->index);
 		err = usb_submit_urb(ctx->urb, GFP_ATOMIC);
 		if (err < 0) {
 			usb_audio_err(ep->chip,
@@ -513,6 +518,7 @@ static void snd_complete_urb(struct urb *urb)
 	struct snd_usb_endpoint *ep = ctx->ep;
 	int err;
 
+	DBG("pkt complete %d\n", ctx->index);
 	if (unlikely(urb->status == -ENOENT ||		/* unlinked */
 		     urb->status == -ENODEV ||		/* device removed */
 		     urb->status == -ECONNRESET ||	/* unlinked */
@@ -1442,6 +1448,7 @@ int snd_usb_endpoint_start(struct snd_usb_endpoint *ep)
 	int err;
 	unsigned int i;
 
+	DBG("endpoint start\n");
 	if (atomic_read(&ep->chip->shutdown))
 		return -EBADFD;
 
@@ -1500,6 +1507,7 @@ int snd_usb_endpoint_start(struct snd_usb_endpoint *ep)
 			goto __error;
 		}
 
+		DBG("start: pkt %d submitted\n", i);
 		err = usb_submit_urb(urb, GFP_ATOMIC);
 		if (err < 0) {
 			usb_audio_err(ep->chip,
diff --git a/sound/usb/pcm.c b/sound/usb/pcm.c
index 95ec8eec1bb0..b1651db2e1e8 100644
--- a/sound/usb/pcm.c
+++ b/sound/usb/pcm.c
@@ -1232,6 +1232,8 @@ static void urb_ctx_queue_advance(struct snd_usb_substream *subs,
 	subs->hwptr_done += bytes;
 	if (subs->hwptr_done >= subs->buffer_bytes)
 		subs->hwptr_done -= subs->buffer_bytes;
+	DBG("PCM bytes=%d, queued=%d, inflight=%d, hwptr=%d\n",
+	    bytes, ctx->queued, subs->inflight_bytes, subs->hwptr_done);
 }
 
 static inline void fill_playback_urb_dsd_dop(struct snd_usb_substream *subs,
@@ -1389,10 +1391,17 @@ static int prepare_playback_urb(struct snd_usb_substream *subs,
 		if (avail <= hwptr)
 			avail += runtime->buffer_size;
 		avail -= hwptr;
+		DBG("prepare: applptr=%ld, hwptr_base=%ld, buffer=%ld, hwptr=%d, avail=%d\n",
+		    (long)runtime->control->appl_ptr,
+		    (long)runtime->hw_ptr_base,
+		    (long)runtime->buffer_size,
+		    hwptr, avail);
 	}
 
 	for (i = 0; i < ctx->packets; i++) {
 		counts = snd_usb_endpoint_next_packet_size(ep, ctx, i, avail);
+		DBG("prepare: pkt %d [%d]: avail=%d, counts=%d\n",
+		    ctx->index, i, avail, counts);
 		if (counts < 0)
 			break;
 		/* set up descriptor */
@@ -1530,6 +1539,7 @@ static int snd_usb_pcm_playback_ack(struct snd_pcm_substream *substream)
 	/* When no more in-flight URBs available, try to process the pending
 	 * outputs here
 	 */
+	DBG("PCM ack: active_mask=%lx\n", ep->active_mask);
 	if (!ep->active_mask)
 		snd_usb_queue_pending_output_urbs(ep, true);
 	return 0;
diff --git a/sound/usb/usbaudio.h b/sound/usb/usbaudio.h
index 167834133b9b..84fcd6956f76 100644
--- a/sound/usb/usbaudio.h
+++ b/sound/usb/usbaudio.h
@@ -184,4 +184,5 @@ extern bool snd_usb_skip_validation;
 #define QUIRK_FLAG_DSD_RAW		(1U << 15)
 #define QUIRK_FLAG_SET_IFACE_FIRST	(1U << 16)
 
+#define DBG(fmt, ...)	trace_printk(fmt, ##__VA_ARGS__)
 #endif /* __USBAUDIO_H */