Re:

Re:

[Markus Trippelsdorf]

On 2012.09.04 at 16:40 +0200, Takashi Iwai wrote:
> ----------------------------------------------------------------
> Sound fixes for 3.6-rc5
> 
> There are nothing scaring, contains only small fixes for HD-audio and
> USB-audio:
> - EPSS regression fix and GPIO fix for HD-audio IDT codecs
> - A series of USB-audio regression fixes that are found since 3.5 kernel
> 
> ----------------------------------------------------------------
> Daniel Mack (4):
>       ALSA: snd-usb: Fix URB cancellation at stream start
>       ALSA: snd-usb: restore delay information
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 
The commit fbcfbf5f above causes the following lines to be printed
whenever I start a new song:

delay: estimated 0, actual 352
delay: estimated 353, actual 705

(44.1 * 8 = 352.8)

This happens with an USB-DAC that identifies itself as "C-Media USB
Headphone Set".

-- 
Markus

Re: (no subject)

[Daniel Mack]

On 06.09.2012 08:02, Markus Trippelsdorf wrote:
> On 2012.09.04 at 16:40 +0200, Takashi Iwai wrote:
>> ----------------------------------------------------------------
>> Sound fixes for 3.6-rc5
>>
>> There are nothing scaring, contains only small fixes for HD-audio and
>> USB-audio:
>> - EPSS regression fix and GPIO fix for HD-audio IDT codecs
>> - A series of USB-audio regression fixes that are found since 3.5 kernel
>>
>> ----------------------------------------------------------------
>> Daniel Mack (4):
>>       ALSA: snd-usb: Fix URB cancellation at stream start
>>       ALSA: snd-usb: restore delay information
>         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 
> The commit fbcfbf5f above causes the following lines to be printed
> whenever I start a new song:

Copied Pierre-Louis Bossart - he wrote the code in 294c4fb8 which this
patch (fbcfbf5f) brings back now.

> delay: estimated 0, actual 352
> delay: estimated 353, actual 705
> 
> (44.1 * 8 = 352.8)
> 
> This happens with an USB-DAC that identifies itself as "C-Media USB
> Headphone Set".

And you didn't you see these lines with 3.4?


Daniel

Re:

[Markus Trippelsdorf]

On 2012.09.06 at 08:33 +0200, Daniel Mack wrote:
> On 06.09.2012 08:02, Markus Trippelsdorf wrote:
> > On 2012.09.04 at 16:40 +0200, Takashi Iwai wrote:
> >> ----------------------------------------------------------------
> >> Sound fixes for 3.6-rc5
> >>
> >> There are nothing scaring, contains only small fixes for HD-audio and
> >> USB-audio:
> >> - EPSS regression fix and GPIO fix for HD-audio IDT codecs
> >> - A series of USB-audio regression fixes that are found since 3.5 kernel
> >>
> >> ----------------------------------------------------------------
> >> Daniel Mack (4):
> >>       ALSA: snd-usb: Fix URB cancellation at stream start
> >>       ALSA: snd-usb: restore delay information
> >         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 
> > The commit fbcfbf5f above causes the following lines to be printed
> > whenever I start a new song:
> 
> Copied Pierre-Louis Bossart - he wrote the code in 294c4fb8 which this
> patch (fbcfbf5f) brings back now.
> 
> > delay: estimated 0, actual 352
> > delay: estimated 353, actual 705
> > 
> > (44.1 * 8 = 352.8)
> > 
> > This happens with an USB-DAC that identifies itself as "C-Media USB
> > Headphone Set".
> 
> And you didn't you see these lines with 3.4?

No.

-- 
Markus

Re: (no subject)

[Takashi Iwai]

At Thu, 06 Sep 2012 08:33:30 +0200,
Daniel Mack wrote:
> 
> On 06.09.2012 08:02, Markus Trippelsdorf wrote:
> > On 2012.09.04 at 16:40 +0200, Takashi Iwai wrote:
> >> ----------------------------------------------------------------
> >> Sound fixes for 3.6-rc5
> >>
> >> There are nothing scaring, contains only small fixes for HD-audio and
> >> USB-audio:
> >> - EPSS regression fix and GPIO fix for HD-audio IDT codecs
> >> - A series of USB-audio regression fixes that are found since 3.5 kernel
> >>
> >> ----------------------------------------------------------------
> >> Daniel Mack (4):
> >>       ALSA: snd-usb: Fix URB cancellation at stream start
> >>       ALSA: snd-usb: restore delay information
> >         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 
> > The commit fbcfbf5f above causes the following lines to be printed
> > whenever I start a new song:
> 
> Copied Pierre-Louis Bossart - he wrote the code in 294c4fb8 which this
> patch (fbcfbf5f) brings back now.
> 
> > delay: estimated 0, actual 352
> > delay: estimated 353, actual 705
> > 
> > (44.1 * 8 = 352.8)
> > 
> > This happens with an USB-DAC that identifies itself as "C-Media USB
> > Headphone Set".
> 
> And you didn't you see these lines with 3.4?

Maybe the difference of start condition?

Markus, does the patch below fix anything?


Takashi

---
diff --git a/sound/usb/pcm.c b/sound/usb/pcm.c
index fd5e982..0ff9f1a 100644
--- a/sound/usb/pcm.c
+++ b/sound/usb/pcm.c
@@ -556,7 +556,7 @@ static int snd_usb_pcm_prepare(struct snd_pcm_substream *substream)
 	subs->hwptr_done = 0;
 	subs->transfer_done = 0;
 	subs->last_delay = 0;
-	subs->last_frame_number = 0;
+	subs->last_frame_number = snd_usb_pcm_delay(subs, runtime->rate);
 	runtime->delay = 0;
 
 	/* for playback, submit the URBs now; otherwise, the first hwptr_done

Re:

[Markus Trippelsdorf]

On 2012.09.06 at 08:48 +0200, Takashi Iwai wrote:
> At Thu, 06 Sep 2012 08:33:30 +0200,
> Daniel Mack wrote:
> > 
> > On 06.09.2012 08:02, Markus Trippelsdorf wrote:
> > > On 2012.09.04 at 16:40 +0200, Takashi Iwai wrote:
> > >> ----------------------------------------------------------------
> > >> Sound fixes for 3.6-rc5
> > >>
> > >> There are nothing scaring, contains only small fixes for HD-audio and
> > >> USB-audio:
> > >> - EPSS regression fix and GPIO fix for HD-audio IDT codecs
> > >> - A series of USB-audio regression fixes that are found since 3.5 kernel
> > >>
> > >> ----------------------------------------------------------------
> > >> Daniel Mack (4):
> > >>       ALSA: snd-usb: Fix URB cancellation at stream start
> > >>       ALSA: snd-usb: restore delay information
> > >         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 
> > > The commit fbcfbf5f above causes the following lines to be printed
> > > whenever I start a new song:
> > 
> > Copied Pierre-Louis Bossart - he wrote the code in 294c4fb8 which this
> > patch (fbcfbf5f) brings back now.
> > 
> > > delay: estimated 0, actual 352
> > > delay: estimated 353, actual 705
> > > 
> > > (44.1 * 8 = 352.8)
> > > 
> > > This happens with an USB-DAC that identifies itself as "C-Media USB
> > > Headphone Set".
> > 
> > And you didn't you see these lines with 3.4?
> 
> Maybe the difference of start condition?
> 
> Markus, does the patch below fix anything?

Unfortunately no.
However reverting the following fixes the problem:

commit 245baf983cc39524cce39c24d01b276e6e653c9e
Author: Daniel Mack <zonque@gmail.com>
Date:   Thu Aug 30 18:52:30 2012 +0200

    ALSA: snd-usb: fix calls to next_packet_size

-- 
Markus

Re: snd-usb: "delay: estimated 0, actual 352"

[Daniel Mack]

On 06.09.2012 08:53, Markus Trippelsdorf wrote:
> On 2012.09.06 at 08:48 +0200, Takashi Iwai wrote:
>> At Thu, 06 Sep 2012 08:33:30 +0200,
>> Daniel Mack wrote:
>>>
>>> On 06.09.2012 08:02, Markus Trippelsdorf wrote:
>>>> On 2012.09.04 at 16:40 +0200, Takashi Iwai wrote:
>>>>> ----------------------------------------------------------------
>>>>> Sound fixes for 3.6-rc5
>>>>>
>>>>> There are nothing scaring, contains only small fixes for HD-audio and
>>>>> USB-audio:
>>>>> - EPSS regression fix and GPIO fix for HD-audio IDT codecs
>>>>> - A series of USB-audio regression fixes that are found since 3.5 kernel
>>>>>
>>>>> ----------------------------------------------------------------
>>>>> Daniel Mack (4):
>>>>>       ALSA: snd-usb: Fix URB cancellation at stream start
>>>>>       ALSA: snd-usb: restore delay information
>>>>         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 
>>>> The commit fbcfbf5f above causes the following lines to be printed
>>>> whenever I start a new song:
>>>
>>> Copied Pierre-Louis Bossart - he wrote the code in 294c4fb8 which this
>>> patch (fbcfbf5f) brings back now.
>>>
>>>> delay: estimated 0, actual 352
>>>> delay: estimated 353, actual 705
>>>>
>>>> (44.1 * 8 = 352.8)
>>>>
>>>> This happens with an USB-DAC that identifies itself as "C-Media USB
>>>> Headphone Set".
>>>
>>> And you didn't you see these lines with 3.4?
>>
>> Maybe the difference of start condition?
>>
>> Markus, does the patch below fix anything?
> 
> Unfortunately no.
> However reverting the following fixes the problem:
> 
> commit 245baf983cc39524cce39c24d01b276e6e653c9e
> Author: Daniel Mack <zonque@gmail.com>
> Date:   Thu Aug 30 18:52:30 2012 +0200
> 
>     ALSA: snd-usb: fix calls to next_packet_size
> 

No, this one certainly fixes a problem and does the right thing by
restoring the original code.

If you wouldn't state that you didn't see the same effect with 3.4(!),
before the refactoring done in 3.5, I would believe the device is simply
slightly off in its feedback rate and the tighter delay code complains
about it while compensating, just as it did before.

Are there any more than these two lines? And is audio working at all? Is
it distorted in any way?

Pierre-Louis, could you check whether I did the right thing when I
ported over your delay bits to the new endpoint logic? Maybe I'm missing
something here, but I currently don't see it.


Thanks,
Daniel

Re: snd-usb: "delay: estimated 0, actual 352"

[Markus Trippelsdorf]

On 2012.09.06 at 09:08 +0200, Daniel Mack wrote:
> On 06.09.2012 08:53, Markus Trippelsdorf wrote:
> > On 2012.09.06 at 08:48 +0200, Takashi Iwai wrote:
> >> At Thu, 06 Sep 2012 08:33:30 +0200,
> >> Daniel Mack wrote:
> >>>
> >>> On 06.09.2012 08:02, Markus Trippelsdorf wrote:
> >>>> On 2012.09.04 at 16:40 +0200, Takashi Iwai wrote:
> >>>>> ----------------------------------------------------------------
> >>>>> Sound fixes for 3.6-rc5
> >>>>>
> >>>>> There are nothing scaring, contains only small fixes for HD-audio and
> >>>>> USB-audio:
> >>>>> - EPSS regression fix and GPIO fix for HD-audio IDT codecs
> >>>>> - A series of USB-audio regression fixes that are found since 3.5 kernel
> >>>>>
> >>>>> ----------------------------------------------------------------
> >>>>> Daniel Mack (4):
> >>>>>       ALSA: snd-usb: Fix URB cancellation at stream start
> >>>>>       ALSA: snd-usb: restore delay information
> >>>>         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 
> >>>> The commit fbcfbf5f above causes the following lines to be printed
> >>>> whenever I start a new song:
> >>>
> >>> Copied Pierre-Louis Bossart - he wrote the code in 294c4fb8 which this
> >>> patch (fbcfbf5f) brings back now.
> >>>
> >>>> delay: estimated 0, actual 352
> >>>> delay: estimated 353, actual 705
> >>>>
> >>>> (44.1 * 8 = 352.8)
> >>>>
> >>>> This happens with an USB-DAC that identifies itself as "C-Media USB
> >>>> Headphone Set".
> >>>
> >>> And you didn't you see these lines with 3.4?
> >>
> >> Maybe the difference of start condition?
> >>
> >> Markus, does the patch below fix anything?
> > 
> > Unfortunately no.
> > However reverting the following fixes the problem:
> > 
> > commit 245baf983cc39524cce39c24d01b276e6e653c9e
> > Author: Daniel Mack <zonque@gmail.com>
> > Date:   Thu Aug 30 18:52:30 2012 +0200
> > 
> >     ALSA: snd-usb: fix calls to next_packet_size
> > 
> 
> No, this one certainly fixes a problem and does the right thing by
> restoring the original code.
> 
> If you wouldn't state that you didn't see the same effect with 3.4(!),
> before the refactoring done in 3.5, I would believe the device is simply
> slightly off in its feedback rate and the tighter delay code complains
> about it while compensating, just as it did before.
> 
> Are there any more than these two lines? And is audio working at all? Is
> it distorted in any way?

There are only these two lines (printed whenever sound starts). Audio is
working just fine with no distortions.

I did see similar lines before when the system load was very high
(happend during "make check" when building glibc).

Here is what Pierre-Louis wrote in November 2011:

»This was supposed to be an informational message, I thought it was only
enabled for debug. Regular users don't really need to know.«

-- 
Markus

Re: snd-usb: "delay: estimated 0, actual 352"

[Takashi Iwai]

At Thu, 6 Sep 2012 09:17:57 +0200,
Markus Trippelsdorf wrote:
> 
> On 2012.09.06 at 09:08 +0200, Daniel Mack wrote:
> > On 06.09.2012 08:53, Markus Trippelsdorf wrote:
> > > On 2012.09.06 at 08:48 +0200, Takashi Iwai wrote:
> > >> At Thu, 06 Sep 2012 08:33:30 +0200,
> > >> Daniel Mack wrote:
> > >>>
> > >>> On 06.09.2012 08:02, Markus Trippelsdorf wrote:
> > >>>> On 2012.09.04 at 16:40 +0200, Takashi Iwai wrote:
> > >>>>> ----------------------------------------------------------------
> > >>>>> Sound fixes for 3.6-rc5
> > >>>>>
> > >>>>> There are nothing scaring, contains only small fixes for HD-audio and
> > >>>>> USB-audio:
> > >>>>> - EPSS regression fix and GPIO fix for HD-audio IDT codecs
> > >>>>> - A series of USB-audio regression fixes that are found since 3.5 kernel
> > >>>>>
> > >>>>> ----------------------------------------------------------------
> > >>>>> Daniel Mack (4):
> > >>>>>       ALSA: snd-usb: Fix URB cancellation at stream start
> > >>>>>       ALSA: snd-usb: restore delay information
> > >>>>         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 
> > >>>> The commit fbcfbf5f above causes the following lines to be printed
> > >>>> whenever I start a new song:
> > >>>
> > >>> Copied Pierre-Louis Bossart - he wrote the code in 294c4fb8 which this
> > >>> patch (fbcfbf5f) brings back now.
> > >>>
> > >>>> delay: estimated 0, actual 352
> > >>>> delay: estimated 353, actual 705
> > >>>>
> > >>>> (44.1 * 8 = 352.8)
> > >>>>
> > >>>> This happens with an USB-DAC that identifies itself as "C-Media USB
> > >>>> Headphone Set".
> > >>>
> > >>> And you didn't you see these lines with 3.4?
> > >>
> > >> Maybe the difference of start condition?
> > >>
> > >> Markus, does the patch below fix anything?
> > > 
> > > Unfortunately no.
> > > However reverting the following fixes the problem:
> > > 
> > > commit 245baf983cc39524cce39c24d01b276e6e653c9e
> > > Author: Daniel Mack <zonque@gmail.com>
> > > Date:   Thu Aug 30 18:52:30 2012 +0200
> > > 
> > >     ALSA: snd-usb: fix calls to next_packet_size
> > > 
> > 
> > No, this one certainly fixes a problem and does the right thing by
> > restoring the original code.
> > 
> > If you wouldn't state that you didn't see the same effect with 3.4(!),
> > before the refactoring done in 3.5, I would believe the device is simply
> > slightly off in its feedback rate and the tighter delay code complains
> > about it while compensating, just as it did before.
> > 
> > Are there any more than these two lines? And is audio working at all? Is
> > it distorted in any way?
> 
> There are only these two lines (printed whenever sound starts). Audio is
> working just fine with no distortions.
> 
> I did see similar lines before when the system load was very high
> (happend during "make check" when building glibc).
> 
> Here is what Pierre-Louis wrote in November 2011:
> 
> »This was supposed to be an informational message, I thought it was only
> enabled for debug. Regular users don't really need to know.«

I guess the problem is that the new endpoint scheme doesn't count the
last_delay update unless the stream is triggered.  In the old code,
retire_playback_urb is always called even before the trigger(START) is
set.  And, there retire_playback_urb() does nothing but updating the
delay information.

In the new code, retire_playback_urb is set only at
snd_usb_substream_playback_trigger().  Thus at the very first shot,
the delay account got confused.


Takashi
_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: snd-usb: "delay: estimated 0, actual 352"

[Takashi Iwai]

At Thu, 06 Sep 2012 09:35:26 +0200,
Takashi Iwai wrote:
> 
> At Thu, 6 Sep 2012 09:17:57 +0200,
> Markus Trippelsdorf wrote:
> > 
> > On 2012.09.06 at 09:08 +0200, Daniel Mack wrote:
> > > On 06.09.2012 08:53, Markus Trippelsdorf wrote:
> > > > On 2012.09.06 at 08:48 +0200, Takashi Iwai wrote:
> > > >> At Thu, 06 Sep 2012 08:33:30 +0200,
> > > >> Daniel Mack wrote:
> > > >>>
> > > >>> On 06.09.2012 08:02, Markus Trippelsdorf wrote:
> > > >>>> On 2012.09.04 at 16:40 +0200, Takashi Iwai wrote:
> > > >>>>> ----------------------------------------------------------------
> > > >>>>> Sound fixes for 3.6-rc5
> > > >>>>>
> > > >>>>> There are nothing scaring, contains only small fixes for HD-audio and
> > > >>>>> USB-audio:
> > > >>>>> - EPSS regression fix and GPIO fix for HD-audio IDT codecs
> > > >>>>> - A series of USB-audio regression fixes that are found since 3.5 kernel
> > > >>>>>
> > > >>>>> ----------------------------------------------------------------
> > > >>>>> Daniel Mack (4):
> > > >>>>>       ALSA: snd-usb: Fix URB cancellation at stream start
> > > >>>>>       ALSA: snd-usb: restore delay information
> > > >>>>         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 
> > > >>>> The commit fbcfbf5f above causes the following lines to be printed
> > > >>>> whenever I start a new song:
> > > >>>
> > > >>> Copied Pierre-Louis Bossart - he wrote the code in 294c4fb8 which this
> > > >>> patch (fbcfbf5f) brings back now.
> > > >>>
> > > >>>> delay: estimated 0, actual 352
> > > >>>> delay: estimated 353, actual 705
> > > >>>>
> > > >>>> (44.1 * 8 = 352.8)
> > > >>>>
> > > >>>> This happens with an USB-DAC that identifies itself as "C-Media USB
> > > >>>> Headphone Set".
> > > >>>
> > > >>> And you didn't you see these lines with 3.4?
> > > >>
> > > >> Maybe the difference of start condition?
> > > >>
> > > >> Markus, does the patch below fix anything?
> > > > 
> > > > Unfortunately no.
> > > > However reverting the following fixes the problem:
> > > > 
> > > > commit 245baf983cc39524cce39c24d01b276e6e653c9e
> > > > Author: Daniel Mack <zonque@gmail.com>
> > > > Date:   Thu Aug 30 18:52:30 2012 +0200
> > > > 
> > > >     ALSA: snd-usb: fix calls to next_packet_size
> > > > 
> > > 
> > > No, this one certainly fixes a problem and does the right thing by
> > > restoring the original code.
> > > 
> > > If you wouldn't state that you didn't see the same effect with 3.4(!),
> > > before the refactoring done in 3.5, I would believe the device is simply
> > > slightly off in its feedback rate and the tighter delay code complains
> > > about it while compensating, just as it did before.
> > > 
> > > Are there any more than these two lines? And is audio working at all? Is
> > > it distorted in any way?
> > 
> > There are only these two lines (printed whenever sound starts). Audio is
> > working just fine with no distortions.
> > 
> > I did see similar lines before when the system load was very high
> > (happend during "make check" when building glibc).
> > 
> > Here is what Pierre-Louis wrote in November 2011:
> > 
> > »This was supposed to be an informational message, I thought it was only
> > enabled for debug. Regular users don't really need to know.«
> 
> I guess the problem is that the new endpoint scheme doesn't count the
> last_delay update unless the stream is triggered.  In the old code,
> retire_playback_urb is always called even before the trigger(START) is
> set.  And, there retire_playback_urb() does nothing but updating the
> delay information.
> 
> In the new code, retire_playback_urb is set only at
> snd_usb_substream_playback_trigger().  Thus at the very first shot,
> the delay account got confused.

In short, a patch like below may fix the issue (note: completely
untested!)


Takashi

---

diff --git a/sound/usb/pcm.c b/sound/usb/pcm.c
index fd5e982..928a4f7 100644
--- a/sound/usb/pcm.c
+++ b/sound/usb/pcm.c
@@ -528,6 +528,9 @@ static int snd_usb_hw_free(struct snd_pcm_substream *substream)
 	return snd_pcm_lib_free_vmalloc_buffer(substream);
 }
 
+static void retire_playback_urb(struct snd_usb_substream *subs,
+				struct urb *urb);
+
 /*
  * prepare callback
  *
@@ -561,8 +564,10 @@ static int snd_usb_pcm_prepare(struct snd_pcm_substream *substream)
 
 	/* for playback, submit the URBs now; otherwise, the first hwptr_done
 	 * updates for all URBs would happen at the same time when starting */
-	if (subs->direction == SNDRV_PCM_STREAM_PLAYBACK)
+	if (subs->direction == SNDRV_PCM_STREAM_PLAYBACK) {
+		subs->data_endpoint->retire_data_urb = retire_playback_urb;
 		return start_endpoints(subs, 1);
+	}
 
 	return 0;
 }
@@ -1190,7 +1195,6 @@ static int snd_usb_substream_playback_trigger(struct snd_pcm_substream *substrea
 	case SNDRV_PCM_TRIGGER_START:
 	case SNDRV_PCM_TRIGGER_PAUSE_RELEASE:
 		subs->data_endpoint->prepare_data_urb = prepare_playback_urb;
-		subs->data_endpoint->retire_data_urb = retire_playback_urb;
 		subs->running = 1;
 		return 0;
 	case SNDRV_PCM_TRIGGER_STOP:
@@ -1199,7 +1203,6 @@ static int snd_usb_substream_playback_trigger(struct snd_pcm_substream *substrea
 		return 0;
 	case SNDRV_PCM_TRIGGER_PAUSE_PUSH:
 		subs->data_endpoint->prepare_data_urb = NULL;
-		subs->data_endpoint->retire_data_urb = NULL;
 		subs->running = 0;
 		return 0;
 	}
_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: snd-usb: "delay: estimated 0, actual 352"

[Markus Trippelsdorf]

On 2012.09.06 at 10:21 +0200, Takashi Iwai wrote:
> At Thu, 06 Sep 2012 09:35:26 +0200,
> Takashi Iwai wrote:
> 
> In short, a patch like below may fix the issue (note: completely
> untested!)

No it doesn't, unfortunately...

-- 
Markus

Re: snd-usb: "delay: estimated 0, actual 352"

[Takashi Iwai]

At Thu, 6 Sep 2012 11:43:48 +0200,
Markus Trippelsdorf wrote:
> 
> On 2012.09.06 at 10:21 +0200, Takashi Iwai wrote:
> > At Thu, 06 Sep 2012 09:35:26 +0200,
> > Takashi Iwai wrote:
> > 
> > In short, a patch like below may fix the issue (note: completely
> > untested!)
> 
> No it doesn't, unfortunately...

OK, I start tracking down the problem a bit more deeply now.

The issue happens when the first two URBs are passed to
retire_playback_urb().  These are URBs filled before start_endpoints()
are set, so they contain actually zero size.  Even though these are
a sort of dummy packets, the driver still tries to check with the
queued delay account, and gives bogus errors.

So, essentially the messages are harmless and nothing to worry too
much, but surely it doesn't look sexy.

The patch below should fix the problem.  Please give it a try.


thanks,

Takashi

===

From: Takashi Iwai <tiwai@suse.de>
Subject: [PATCH] ALSA: usb-audio: Fix bogus error messages for delay accounting

The recent fix for the missing fine delayed time adjustment gives
strange error messages at each start of the playback stream, such as
  delay: estimated 0, actual 352
  delay: estimated 353, actual 705

These come from the sanity check in retire_playback_urb().  Before the
stream is activated via start_endpoints(), a few silent packets have
been already sent.  And at this point the delay account is still in
the state as if the new packets are just queued, so the driver gets
confused and spews the bogus error messages.

For fixing the issue, we just need to check whether the received
packet is valid, whether it's zero sized or not.

Reported-by: Markus Trippelsdorf <markus@trippelsdorf.de>
Cc: <stable@vger.kernel.org> [v3.5+]
Signed-off-by: Takashi Iwai <tiwai@suse.de>
---
 sound/usb/pcm.c | 6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/sound/usb/pcm.c b/sound/usb/pcm.c
index fd5e982..f782ce1 100644
--- a/sound/usb/pcm.c
+++ b/sound/usb/pcm.c
@@ -1140,6 +1140,12 @@ static void retire_playback_urb(struct snd_usb_substream *subs,
 	int processed = urb->transfer_buffer_length / stride;
 	int est_delay;
 
+	/* ignore the delay accounting when procssed=0 is given, i.e.
+	 * silent payloads are procssed before handling the actual data
+	 */
+	if (!processed)
+		return;
+
 	spin_lock_irqsave(&subs->lock, flags);
 	est_delay = snd_usb_pcm_delay(subs, runtime->rate);
 	/* update delay with exact number of samples played */
-- 
1.7.11.5

Re: snd-usb: "delay: estimated 0, actual 352"

[Markus Trippelsdorf]

On 2012.09.06 at 15:08 +0200, Takashi Iwai wrote:
> At Thu, 6 Sep 2012 11:43:48 +0200,
> Markus Trippelsdorf wrote:
> > 
> > On 2012.09.06 at 10:21 +0200, Takashi Iwai wrote:
> > > At Thu, 06 Sep 2012 09:35:26 +0200,
> > > Takashi Iwai wrote:
> > > 
> > > In short, a patch like below may fix the issue (note: completely
> > > untested!)
> > 
> > No it doesn't, unfortunately...
> 
> OK, I start tracking down the problem a bit more deeply now.
> 
> The issue happens when the first two URBs are passed to
> retire_playback_urb().  These are URBs filled before start_endpoints()
> are set, so they contain actually zero size.  Even though these are
> a sort of dummy packets, the driver still tries to check with the
> queued delay account, and gives bogus errors.
> 
> So, essentially the messages are harmless and nothing to worry too
> much, but surely it doesn't look sexy.
> 
> The patch below should fix the problem.  Please give it a try.

Yes, your patch finally fixes the problem. 
Thank you Takashi-san.

-- 
Markus

Re: snd-usb: "delay: estimated 0, actual 352"

[Takashi Iwai]

At Thu, 6 Sep 2012 15:17:58 +0200,
Markus Trippelsdorf wrote:
> 
> On 2012.09.06 at 15:08 +0200, Takashi Iwai wrote:
> > At Thu, 6 Sep 2012 11:43:48 +0200,
> > Markus Trippelsdorf wrote:
> > > 
> > > On 2012.09.06 at 10:21 +0200, Takashi Iwai wrote:
> > > > At Thu, 06 Sep 2012 09:35:26 +0200,
> > > > Takashi Iwai wrote:
> > > > 
> > > > In short, a patch like below may fix the issue (note: completely
> > > > untested!)
> > > 
> > > No it doesn't, unfortunately...
> > 
> > OK, I start tracking down the problem a bit more deeply now.
> > 
> > The issue happens when the first two URBs are passed to
> > retire_playback_urb().  These are URBs filled before start_endpoints()
> > are set, so they contain actually zero size.  Even though these are
> > a sort of dummy packets, the driver still tries to check with the
> > queued delay account, and gives bogus errors.
> > 
> > So, essentially the messages are harmless and nothing to worry too
> > much, but surely it doesn't look sexy.
> > 
> > The patch below should fix the problem.  Please give it a try.
> 
> Yes, your patch finally fixes the problem. 
> Thank you Takashi-san.

Thanks for your quick test!

If Daniel has no objection with that patch, I'm going to merge it.


Takashi

Re: snd-usb: "delay: estimated 0, actual 352"

[Daniel Mack]

On 06.09.2012 16:31, Takashi Iwai wrote:
> At Thu, 6 Sep 2012 15:17:58 +0200,
> Markus Trippelsdorf wrote:
>>
>> On 2012.09.06 at 15:08 +0200, Takashi Iwai wrote:
>>> At Thu, 6 Sep 2012 11:43:48 +0200,
>>> Markus Trippelsdorf wrote:
>>>>
>>>> On 2012.09.06 at 10:21 +0200, Takashi Iwai wrote:
>>>>> At Thu, 06 Sep 2012 09:35:26 +0200,
>>>>> Takashi Iwai wrote:
>>>>>
>>>>> In short, a patch like below may fix the issue (note: completely
>>>>> untested!)
>>>>
>>>> No it doesn't, unfortunately...
>>>
>>> OK, I start tracking down the problem a bit more deeply now.
>>>
>>> The issue happens when the first two URBs are passed to
>>> retire_playback_urb().  These are URBs filled before start_endpoints()
>>> are set, so they contain actually zero size.  Even though these are
>>> a sort of dummy packets, the driver still tries to check with the
>>> queued delay account, and gives bogus errors.
>>>
>>> So, essentially the messages are harmless and nothing to worry too
>>> much, but surely it doesn't look sexy.
>>>
>>> The patch below should fix the problem.  Please give it a try.
>>
>> Yes, your patch finally fixes the problem. 
>> Thank you Takashi-san.
> 
> Thanks for your quick test!
> 
> If Daniel has no objection with that patch, I'm going to merge it.

No objections from my side. I also gave it a quick test, and even though
I never saw the problem Markus was seeing, I agree to your findings.

Many thanks, everyone :)


Daniel

Re: snd-usb: "delay: estimated 0, actual 352"

[Andreas Mohr]

Hi,

I can very well believe that bogus triggering of this spewing message
is now fixed by your patch (thanks!), but:

I get the very same message here on OpenWrt's 3.10.24
(verified to be properly containing your patch!),
when playing usb-audio on TL-WDR3600 MIPS via MPD mp3 streaming, *and then*:

Execute

    modprobe zram num_devices=4

    # Set disksize of 16MB for /dev/zram0
    echo $((16*1024*1024)) > /sys/block/zram0/disksize

    mkswap /dev/zram0

    # For zram, use higher prio than for traditional swap devices.
    swapon -p 100 /dev/zram0

Executing these commands will cause the status/error message to
loop again (when doing so manually, it's directly after having executed
the swapon command).

IOW: messages did not appear, then mkswap, then infinite loop, then run
    mpd stop
then they're gone again.

Sample:

[183532.990000] delay: estimated 240, actual 0
[183533.000000] delay: estimated 240, actual 0
[183533.010000] delay: estimated 432, actual 288
[183533.020000] delay: estimated 528, actual 288
[183533.020000] delay: estimated 528, actual 288
[183533.030000] delay: estimated 288, actual 48
[183533.040000] delay: estimated 288, actual 48
[183533.050000] delay: estimated 432, actual 288
[183533.050000] delay: estimated 576, actual 288
[183533.060000] delay: estimated 528, actual 288


My running theory is that that mkswap causes a rather insurmountable
temporary lockup of relevant system processing resources,
which causes audio handling to get out of lock-step, infinitely
(*that* one really shouldn't happen, right!?),
not to be resolved until finally playback gets stopped again.

That message is discussed at
"MPD filling kern.log with "delay: estimated 0, actual xxx""
  http://www.raspberrypi.org/phpBB3/viewtopic.php?f=28&t=15204
as well, but I don't know whether that one is pre- or post-patch ;)
(as opposed to my case, which definitely is post-patch)


Note also that I'm experiencing rather weirdly crackling sound when using
    aplay /usr/share/sounds/alsa/Front_Center.wav
, but only *every other time* that I'm executing this command.
But in this aplay case this delay message does *not* get produced,
so I suspect that that crackling is a different issue.

Wellll... perhaps not quite:
snd-usb-audio param nrpacks=1 (as favourably mentioned by the URL above)
does solve both the mkswap looping error
and the aplay crackling (and solves arec crackling / echoes / corruption, too!).
However I guess that nrpacks=1 is not something that you would want to
have in an optimally performing system...


usb-audio running on a bus-powered USB2 hub connected to USB2 router port,
with certain other devices producing activity (FTDI RS232, X10 lirc remote).

Hmmmm (any interesting thoughts?),

Andreas Mohr

-- 
GNU/Linux. It's not the software that's free, it's you.

Re: snd-usb: "delay: estimated 0, actual 352"

[Daniel Mack]

On 06.09.2012 09:35, Takashi Iwai wrote:
> At Thu, 6 Sep 2012 09:17:57 +0200,
> Markus Trippelsdorf wrote:
>>
>> On 2012.09.06 at 09:08 +0200, Daniel Mack wrote:
>>> On 06.09.2012 08:53, Markus Trippelsdorf wrote:
>>>> On 2012.09.06 at 08:48 +0200, Takashi Iwai wrote:
>>>>> At Thu, 06 Sep 2012 08:33:30 +0200,
>>>>> Daniel Mack wrote:
>>>>>>
>>>>>> On 06.09.2012 08:02, Markus Trippelsdorf wrote:
>>>>>>> On 2012.09.04 at 16:40 +0200, Takashi Iwai wrote:
>>>>>>>> ----------------------------------------------------------------
>>>>>>>> Sound fixes for 3.6-rc5
>>>>>>>>
>>>>>>>> There are nothing scaring, contains only small fixes for HD-audio and
>>>>>>>> USB-audio:
>>>>>>>> - EPSS regression fix and GPIO fix for HD-audio IDT codecs
>>>>>>>> - A series of USB-audio regression fixes that are found since 3.5 kernel
>>>>>>>>
>>>>>>>> ----------------------------------------------------------------
>>>>>>>> Daniel Mack (4):
>>>>>>>>       ALSA: snd-usb: Fix URB cancellation at stream start
>>>>>>>>       ALSA: snd-usb: restore delay information
>>>>>>>         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 
>>>>>>> The commit fbcfbf5f above causes the following lines to be printed
>>>>>>> whenever I start a new song:
>>>>>>
>>>>>> Copied Pierre-Louis Bossart - he wrote the code in 294c4fb8 which this
>>>>>> patch (fbcfbf5f) brings back now.
>>>>>>
>>>>>>> delay: estimated 0, actual 352
>>>>>>> delay: estimated 353, actual 705
>>>>>>>
>>>>>>> (44.1 * 8 = 352.8)
>>>>>>>
>>>>>>> This happens with an USB-DAC that identifies itself as "C-Media USB
>>>>>>> Headphone Set".
>>>>>>
>>>>>> And you didn't you see these lines with 3.4?
>>>>>
>>>>> Maybe the difference of start condition?
>>>>>
>>>>> Markus, does the patch below fix anything?
>>>>
>>>> Unfortunately no.
>>>> However reverting the following fixes the problem:
>>>>
>>>> commit 245baf983cc39524cce39c24d01b276e6e653c9e
>>>> Author: Daniel Mack <zonque@gmail.com>
>>>> Date:   Thu Aug 30 18:52:30 2012 +0200
>>>>
>>>>     ALSA: snd-usb: fix calls to next_packet_size
>>>>
>>>
>>> No, this one certainly fixes a problem and does the right thing by
>>> restoring the original code.
>>>
>>> If you wouldn't state that you didn't see the same effect with 3.4(!),
>>> before the refactoring done in 3.5, I would believe the device is simply
>>> slightly off in its feedback rate and the tighter delay code complains
>>> about it while compensating, just as it did before.
>>>
>>> Are there any more than these two lines? And is audio working at all? Is
>>> it distorted in any way?
>>
>> There are only these two lines (printed whenever sound starts). Audio is
>> working just fine with no distortions.
>>
>> I did see similar lines before when the system load was very high
>> (happend during "make check" when building glibc).
>>
>> Here is what Pierre-Louis wrote in November 2011:
>>
>> »This was supposed to be an informational message, I thought it was only
>> enabled for debug. Regular users don't really need to know.«
> 
> I guess the problem is that the new endpoint scheme doesn't count the
> last_delay update unless the stream is triggered.  In the old code,
> retire_playback_urb is always called even before the trigger(START) is
> set.  And, there retire_playback_urb() does nothing but updating the
> delay information.
> 
> In the new code, retire_playback_urb is set only at
> snd_usb_substream_playback_trigger().  Thus at the very first shot,
> the delay account got confused.

In that case, I'd say we can also safely remove the debug output then.
Let's wait for Pierre-Louis' judgement here.


Daniel

_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: snd-usb: "delay: estimated 0, actual 352"

[Markus Trippelsdorf]

On 2012.09.06 at 12:25 +0200, Daniel Mack wrote:
> On 06.09.2012 09:35, Takashi Iwai wrote:
> > At Thu, 6 Sep 2012 09:17:57 +0200,
> > Markus Trippelsdorf wrote:
> >>
> >> On 2012.09.06 at 09:08 +0200, Daniel Mack wrote:
> >>> On 06.09.2012 08:53, Markus Trippelsdorf wrote:
> >>>> On 2012.09.06 at 08:48 +0200, Takashi Iwai wrote:
> >>>>> At Thu, 06 Sep 2012 08:33:30 +0200,
> >>>>> Daniel Mack wrote:
> >>>>>>
> >>>>>> On 06.09.2012 08:02, Markus Trippelsdorf wrote:
> >>>>>>> On 2012.09.04 at 16:40 +0200, Takashi Iwai wrote:
> >>>>>>>> ----------------------------------------------------------------
> >>>>>>>> Sound fixes for 3.6-rc5
> >>>>>>>>
> >>>>>>>> There are nothing scaring, contains only small fixes for HD-audio and
> >>>>>>>> USB-audio:
> >>>>>>>> - EPSS regression fix and GPIO fix for HD-audio IDT codecs
> >>>>>>>> - A series of USB-audio regression fixes that are found since 3.5 kernel
> >>>>>>>>
> >>>>>>>> ----------------------------------------------------------------
> >>>>>>>> Daniel Mack (4):
> >>>>>>>>       ALSA: snd-usb: Fix URB cancellation at stream start
> >>>>>>>>       ALSA: snd-usb: restore delay information
> >>>>>>>         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 
> >>>>>>> The commit fbcfbf5f above causes the following lines to be printed
> >>>>>>> whenever I start a new song:
> >>>>>>
> >>>>>> Copied Pierre-Louis Bossart - he wrote the code in 294c4fb8 which this
> >>>>>> patch (fbcfbf5f) brings back now.
> >>>>>>
> >>>>>>> delay: estimated 0, actual 352
> >>>>>>> delay: estimated 353, actual 705
> >>>>>>>
> >>>>>>> (44.1 * 8 = 352.8)
> >>>>>>>
> >>>>>>> This happens with an USB-DAC that identifies itself as "C-Media USB
> >>>>>>> Headphone Set".
> >>>>>>
> >>>>>> And you didn't you see these lines with 3.4?
> >>>>>
> >>>>> Maybe the difference of start condition?
> >>>>>
> >>>>> Markus, does the patch below fix anything?
> >>>>
> >>>> Unfortunately no.
> >>>> However reverting the following fixes the problem:
> >>>>
> >>>> commit 245baf983cc39524cce39c24d01b276e6e653c9e
> >>>> Author: Daniel Mack <zonque@gmail.com>
> >>>> Date:   Thu Aug 30 18:52:30 2012 +0200
> >>>>
> >>>>     ALSA: snd-usb: fix calls to next_packet_size
> >>>>
> >>>
> >>> No, this one certainly fixes a problem and does the right thing by
> >>> restoring the original code.
> >>>
> >>> If you wouldn't state that you didn't see the same effect with 3.4(!),
> >>> before the refactoring done in 3.5, I would believe the device is simply
> >>> slightly off in its feedback rate and the tighter delay code complains
> >>> about it while compensating, just as it did before.
> >>>
> >>> Are there any more than these two lines? And is audio working at all? Is
> >>> it distorted in any way?
> >>
> >> There are only these two lines (printed whenever sound starts). Audio is
> >> working just fine with no distortions.
> >>
> >> I did see similar lines before when the system load was very high
> >> (happend during "make check" when building glibc).
> >>
> >> Here is what Pierre-Louis wrote in November 2011:
> >>
> >> »This was supposed to be an informational message, I thought it was only
> >> enabled for debug. Regular users don't really need to know.«
> > 
> > I guess the problem is that the new endpoint scheme doesn't count the
> > last_delay update unless the stream is triggered.  In the old code,
> > retire_playback_urb is always called even before the trigger(START) is
> > set.  And, there retire_playback_urb() does nothing but updating the
> > delay information.
> > 
> > In the new code, retire_playback_urb is set only at
> > snd_usb_substream_playback_trigger().  Thus at the very first shot,
> > the delay account got confused.
> 
> In that case, I'd say we can also safely remove the debug output then.
> Let's wait for Pierre-Louis' judgement here.

v3.5 and v3.6-rc4 with commit fbcfbf5f67 (restore delay information)
applied on top are both fine.

-- 
Markus