[GIT PULL] sound fixes for 3.6-rc5

[GIT PULL] sound fixes for 3.6-rc5

[Takashi Iwai]

Linus,

The following changes since commit 53e1719f3da0f095b8db1461bd12dd79f3246b84:

  ALSA: snd-als100: fix suspend/resume (2012-08-21 07:29:40 +0200)

are available in the git repository at:

  git://git.kernel.org/pub/scm/linux/kernel/git/tiwai/sound.git tags/sound-3.6

for you to fetch changes up to 2e4a263ca80a203ac6109f5932722a716c265395:

  ALSA: snd-usb: fix cross-interface streaming devices (2012-08-31 21:04:53 +0200)

----------------------------------------------------------------
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
      ALSA: snd-usb: fix calls to next_packet_size
      ALSA: snd-usb: fix cross-interface streaming devices

David Henningsson (1):
      ALSA: hda - Do not set GPIOs for speakers on IDT if there are no speakers

Pavel Roskin (1):
      ALSA: snd-usb: use list_for_each_safe for endpoint resources

Takashi Iwai (2):
      ALSA: hda - Avoid unnecessary parameter read for EPSS
      ALSA: hda - Don't trust codec EPSS bit for IDT 92HD83xx & co

 sound/pci/hda/hda_codec.c      | 10 +++++--
 sound/pci/hda/hda_codec.h      |  1 +
 sound/pci/hda/patch_sigmatel.c |  4 +++
 sound/usb/card.c               |  4 +--
 sound/usb/endpoint.c           | 24 +++++++---------
 sound/usb/endpoint.h           |  3 +-
 sound/usb/pcm.c                | 64 ++++++++++++++++++++++++++++++++++--------
 7 files changed, 79 insertions(+), 31 deletions(-)

diff --git a/sound/pci/hda/hda_codec.c b/sound/pci/hda/hda_codec.c
index f560051..f25c24c 100644
--- a/sound/pci/hda/hda_codec.c
+++ b/sound/pci/hda/hda_codec.c
@@ -1209,6 +1209,9 @@ static void snd_hda_codec_free(struct hda_codec *codec)
 	kfree(codec);
 }
 
+static bool snd_hda_codec_get_supported_ps(struct hda_codec *codec,
+				hda_nid_t fg, unsigned int power_state);
+
 static void hda_set_power_state(struct hda_codec *codec, hda_nid_t fg,
 				unsigned int power_state);
 
@@ -1317,6 +1320,10 @@ int /*__devinit*/ snd_hda_codec_new(struct hda_bus *bus,
 					   AC_VERB_GET_SUBSYSTEM_ID, 0);
 	}
 
+	codec->epss = snd_hda_codec_get_supported_ps(codec,
+					codec->afg ? codec->afg : codec->mfg,
+					AC_PWRST_EPSS);
+
 	/* power-up all before initialization */
 	hda_set_power_state(codec,
 			    codec->afg ? codec->afg : codec->mfg,
@@ -3543,8 +3550,7 @@ static void hda_set_power_state(struct hda_codec *codec, hda_nid_t fg,
 	/* this delay seems necessary to avoid click noise at power-down */
 	if (power_state == AC_PWRST_D3) {
 		/* transition time less than 10ms for power down */
-		bool epss = snd_hda_codec_get_supported_ps(codec, fg, AC_PWRST_EPSS);
-		msleep(epss ? 10 : 100);
+		msleep(codec->epss ? 10 : 100);
 	}
 
 	/* repeat power states setting at most 10 times*/
diff --git a/sound/pci/hda/hda_codec.h b/sound/pci/hda/hda_codec.h
index 7fbc1bc..e5a7e19 100644
--- a/sound/pci/hda/hda_codec.h
+++ b/sound/pci/hda/hda_codec.h
@@ -862,6 +862,7 @@ struct hda_codec {
 	unsigned int ignore_misc_bit:1; /* ignore MISC_NO_PRESENCE bit */
 	unsigned int no_jack_detect:1;	/* Machine has no jack-detection */
 	unsigned int pcm_format_first:1; /* PCM format must be set first */
+	unsigned int epss:1;		/* supporting EPSS? */
 #ifdef CONFIG_SND_HDA_POWER_SAVE
 	unsigned int power_on :1;	/* current (global) power-state */
 	int power_transition;	/* power-state in transition */
diff --git a/sound/pci/hda/patch_sigmatel.c b/sound/pci/hda/patch_sigmatel.c
index ea5775a..6f806d3 100644
--- a/sound/pci/hda/patch_sigmatel.c
+++ b/sound/pci/hda/patch_sigmatel.c
@@ -4543,6 +4543,9 @@ static void stac92xx_line_out_detect(struct hda_codec *codec,
 	struct auto_pin_cfg *cfg = &spec->autocfg;
 	int i;
 
+	if (cfg->speaker_outs == 0)
+		return;
+
 	for (i = 0; i < cfg->line_outs; i++) {
 		if (presence)
 			break;
@@ -5531,6 +5534,7 @@ static int patch_stac92hd83xxx(struct hda_codec *codec)
 		snd_hda_codec_set_pincfg(codec, 0xf, 0x2181205e);
 	}
 
+	codec->epss = 0; /* longer delay needed for D3 */
 	codec->no_trigger_sense = 1;
 	codec->spec = spec;
 
diff --git a/sound/usb/card.c b/sound/usb/card.c
index d5b5c33..4a469f0 100644
--- a/sound/usb/card.c
+++ b/sound/usb/card.c
@@ -553,7 +553,7 @@ static void snd_usb_audio_disconnect(struct usb_device *dev,
 				     struct snd_usb_audio *chip)
 {
 	struct snd_card *card;
-	struct list_head *p;
+	struct list_head *p, *n;
 
 	if (chip == (void *)-1L)
 		return;
@@ -570,7 +570,7 @@ static void snd_usb_audio_disconnect(struct usb_device *dev,
 			snd_usb_stream_disconnect(p);
 		}
 		/* release the endpoint resources */
-		list_for_each(p, &chip->ep_list) {
+		list_for_each_safe(p, n, &chip->ep_list) {
 			snd_usb_endpoint_free(p);
 		}
 		/* release the midi resources */
diff --git a/sound/usb/endpoint.c b/sound/usb/endpoint.c
index c411812..d6e2bb4 100644
--- a/sound/usb/endpoint.c
+++ b/sound/usb/endpoint.c
@@ -141,7 +141,7 @@ int snd_usb_endpoint_implict_feedback_sink(struct snd_usb_endpoint *ep)
  *
  * For implicit feedback, next_packet_size() is unused.
  */
-static int next_packet_size(struct snd_usb_endpoint *ep)
+int snd_usb_endpoint_next_packet_size(struct snd_usb_endpoint *ep)
 {
 	unsigned long flags;
 	int ret;
@@ -177,15 +177,6 @@ static void retire_inbound_urb(struct snd_usb_endpoint *ep,
 		ep->retire_data_urb(ep->data_subs, urb);
 }
 
-static void prepare_outbound_urb_sizes(struct snd_usb_endpoint *ep,
-				       struct snd_urb_ctx *ctx)
-{
-	int i;
-
-	for (i = 0; i < ctx->packets; ++i)
-		ctx->packet_size[i] = next_packet_size(ep);
-}
-
 /*
  * Prepare a PLAYBACK urb for submission to the bus.
  */
@@ -370,7 +361,6 @@ static void snd_complete_urb(struct urb *urb)
 			goto exit_clear;
 		}
 
-		prepare_outbound_urb_sizes(ep, ctx);
 		prepare_outbound_urb(ep, ctx);
 	} else {
 		retire_inbound_urb(ep, ctx);
@@ -799,7 +789,9 @@ int snd_usb_endpoint_set_params(struct snd_usb_endpoint *ep,
 /**
  * snd_usb_endpoint_start: start an snd_usb_endpoint
  *
- * @ep: the endpoint to start
+ * @ep:		the endpoint to start
+ * @can_sleep:	flag indicating whether the operation is executed in
+ * 		non-atomic context
  *
  * A call to this function will increment the use count of the endpoint.
  * In case it is not already running, the URBs for this endpoint will be
@@ -809,7 +801,7 @@ int snd_usb_endpoint_set_params(struct snd_usb_endpoint *ep,
  *
  * Returns an error if the URB submission failed, 0 in all other cases.
  */
-int snd_usb_endpoint_start(struct snd_usb_endpoint *ep)
+int snd_usb_endpoint_start(struct snd_usb_endpoint *ep, int can_sleep)
 {
 	int err;
 	unsigned int i;
@@ -821,6 +813,11 @@ int snd_usb_endpoint_start(struct snd_usb_endpoint *ep)
 	if (++ep->use_count != 1)
 		return 0;
 
+	/* just to be sure */
+	deactivate_urbs(ep, 0, can_sleep);
+	if (can_sleep)
+		wait_clear_urbs(ep);
+
 	ep->active_mask = 0;
 	ep->unlink_mask = 0;
 	ep->phase = 0;
@@ -850,7 +847,6 @@ int snd_usb_endpoint_start(struct snd_usb_endpoint *ep)
 			goto __error;
 
 		if (usb_pipeout(ep->pipe)) {
-			prepare_outbound_urb_sizes(ep, urb->context);
 			prepare_outbound_urb(ep, urb->context);
 		} else {
 			prepare_inbound_urb(ep, urb->context);
diff --git a/sound/usb/endpoint.h b/sound/usb/endpoint.h
index ee2723f..cbbbdf2 100644
--- a/sound/usb/endpoint.h
+++ b/sound/usb/endpoint.h
@@ -13,7 +13,7 @@ int snd_usb_endpoint_set_params(struct snd_usb_endpoint *ep,
 				struct audioformat *fmt,
 				struct snd_usb_endpoint *sync_ep);
 
-int  snd_usb_endpoint_start(struct snd_usb_endpoint *ep);
+int  snd_usb_endpoint_start(struct snd_usb_endpoint *ep, int can_sleep);
 void snd_usb_endpoint_stop(struct snd_usb_endpoint *ep,
 			   int force, int can_sleep, int wait);
 int  snd_usb_endpoint_activate(struct snd_usb_endpoint *ep);
@@ -21,6 +21,7 @@ int  snd_usb_endpoint_deactivate(struct snd_usb_endpoint *ep);
 void snd_usb_endpoint_free(struct list_head *head);
 
 int snd_usb_endpoint_implict_feedback_sink(struct snd_usb_endpoint *ep);
+int snd_usb_endpoint_next_packet_size(struct snd_usb_endpoint *ep);
 
 void snd_usb_handle_sync_urb(struct snd_usb_endpoint *ep,
 			     struct snd_usb_endpoint *sender,
diff --git a/sound/usb/pcm.c b/sound/usb/pcm.c
index 62ec808..fd5e982 100644
--- a/sound/usb/pcm.c
+++ b/sound/usb/pcm.c
@@ -212,7 +212,7 @@ int snd_usb_init_pitch(struct snd_usb_audio *chip, int iface,
 	}
 }
 
-static int start_endpoints(struct snd_usb_substream *subs)
+static int start_endpoints(struct snd_usb_substream *subs, int can_sleep)
 {
 	int err;
 
@@ -225,7 +225,7 @@ static int start_endpoints(struct snd_usb_substream *subs)
 		snd_printdd(KERN_DEBUG "Starting data EP @%p\n", ep);
 
 		ep->data_subs = subs;
-		err = snd_usb_endpoint_start(ep);
+		err = snd_usb_endpoint_start(ep, can_sleep);
 		if (err < 0) {
 			clear_bit(SUBSTREAM_FLAG_DATA_EP_STARTED, &subs->flags);
 			return err;
@@ -236,10 +236,25 @@ static int start_endpoints(struct snd_usb_substream *subs)
 	    !test_and_set_bit(SUBSTREAM_FLAG_SYNC_EP_STARTED, &subs->flags)) {
 		struct snd_usb_endpoint *ep = subs->sync_endpoint;
 
+		if (subs->data_endpoint->iface != subs->sync_endpoint->iface ||
+		    subs->data_endpoint->alt_idx != subs->sync_endpoint->alt_idx) {
+			err = usb_set_interface(subs->dev,
+						subs->sync_endpoint->iface,
+						subs->sync_endpoint->alt_idx);
+			if (err < 0) {
+				snd_printk(KERN_ERR
+					   "%d:%d:%d: cannot set interface (%d)\n",
+					   subs->dev->devnum,
+					   subs->sync_endpoint->iface,
+					   subs->sync_endpoint->alt_idx, err);
+				return -EIO;
+			}
+		}
+
 		snd_printdd(KERN_DEBUG "Starting sync EP @%p\n", ep);
 
 		ep->sync_slave = subs->data_endpoint;
-		err = snd_usb_endpoint_start(ep);
+		err = snd_usb_endpoint_start(ep, can_sleep);
 		if (err < 0) {
 			clear_bit(SUBSTREAM_FLAG_SYNC_EP_STARTED, &subs->flags);
 			return err;
@@ -544,13 +559,10 @@ static int snd_usb_pcm_prepare(struct snd_pcm_substream *substream)
 	subs->last_frame_number = 0;
 	runtime->delay = 0;
 
-	/* clear the pending deactivation on the target EPs */
-	deactivate_endpoints(subs);
-
 	/* 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)
-		return start_endpoints(subs);
+		return start_endpoints(subs, 1);
 
 	return 0;
 }
@@ -1032,6 +1044,7 @@ static void prepare_playback_urb(struct snd_usb_substream *subs,
 				 struct urb *urb)
 {
 	struct snd_pcm_runtime *runtime = subs->pcm_substream->runtime;
+	struct snd_usb_endpoint *ep = subs->data_endpoint;
 	struct snd_urb_ctx *ctx = urb->context;
 	unsigned int counts, frames, bytes;
 	int i, stride, period_elapsed = 0;
@@ -1043,7 +1056,11 @@ static void prepare_playback_urb(struct snd_usb_substream *subs,
 	urb->number_of_packets = 0;
 	spin_lock_irqsave(&subs->lock, flags);
 	for (i = 0; i < ctx->packets; i++) {
-		counts = ctx->packet_size[i];
+		if (ctx->packet_size[i])
+			counts = ctx->packet_size[i];
+		else
+			counts = snd_usb_endpoint_next_packet_size(ep);
+
 		/* set up descriptor */
 		urb->iso_frame_desc[i].offset = frames * stride;
 		urb->iso_frame_desc[i].length = counts * stride;
@@ -1094,7 +1111,16 @@ static void prepare_playback_urb(struct snd_usb_substream *subs,
 	subs->hwptr_done += bytes;
 	if (subs->hwptr_done >= runtime->buffer_size * stride)
 		subs->hwptr_done -= runtime->buffer_size * stride;
+
+	/* update delay with exact number of samples queued */
+	runtime->delay = subs->last_delay;
 	runtime->delay += frames;
+	subs->last_delay = runtime->delay;
+
+	/* realign last_frame_number */
+	subs->last_frame_number = usb_get_current_frame_number(subs->dev);
+	subs->last_frame_number &= 0xFF; /* keep 8 LSBs */
+
 	spin_unlock_irqrestore(&subs->lock, flags);
 	urb->transfer_buffer_length = bytes;
 	if (period_elapsed)
@@ -1112,12 +1138,26 @@ static void retire_playback_urb(struct snd_usb_substream *subs,
 	struct snd_pcm_runtime *runtime = subs->pcm_substream->runtime;
 	int stride = runtime->frame_bits >> 3;
 	int processed = urb->transfer_buffer_length / stride;
+	int est_delay;
 
 	spin_lock_irqsave(&subs->lock, flags);
-	if (processed > runtime->delay)
-		runtime->delay = 0;
+	est_delay = snd_usb_pcm_delay(subs, runtime->rate);
+	/* update delay with exact number of samples played */
+	if (processed > subs->last_delay)
+		subs->last_delay = 0;
 	else
-		runtime->delay -= processed;
+		subs->last_delay -= processed;
+	runtime->delay = subs->last_delay;
+
+	/*
+	 * Report when delay estimate is off by more than 2ms.
+	 * The error should be lower than 2ms since the estimate relies
+	 * on two reads of a counter updated every ms.
+	 */
+	if (abs(est_delay - subs->last_delay) * 1000 > runtime->rate * 2)
+		snd_printk(KERN_DEBUG "delay: estimated %d, actual %d\n",
+			est_delay, subs->last_delay);
+
 	spin_unlock_irqrestore(&subs->lock, flags);
 }
 
@@ -1175,7 +1215,7 @@ static int snd_usb_substream_capture_trigger(struct snd_pcm_substream *substream
 
 	switch (cmd) {
 	case SNDRV_PCM_TRIGGER_START:
-		err = start_endpoints(subs);
+		err = start_endpoints(subs, 0);
 		if (err < 0)
 			return err;
 

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:

[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:

[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

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;
 	}

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

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