snd_hda_intel 2.6.24-rc2 bug: interrupts don't always work on Lenovo X60s

snd_hda_intel 2.6.24-rc2 bug: interrupts don't always work on Lenovo X60s

[Roland Dreier]

With 2.6.24-rc2 on my Lenovo X60s, I sometimes get:

    hda_intel: No response from codec, disabling MSI: last cmd=0x002f0d00
    hda_intel: azx_get_response timeout, switching to polling mode: last cmd=0x002f0d00

when loading snd_hda_intel.  Sound still works but interrupts aren't generated.

I tried bisecting but I haven't gotten good info yet because it seems
that this is not completely reproducible -- sometimes when I load the
module, it works fine, and other times I get the message.

I think this is a regression, since I don't recall ever seeing the
message with 2.6.22 or so.

Any idea on how to help debug this?

Thanks,
  Roland

Re: snd_hda_intel 2.6.24-rc2 bug: interrupts don't always work on Lenovo X60s

[Takashi Iwai]

At Thu, 08 Nov 2007 14:48:32 -0800,
Roland Dreier wrote:
> 
> With 2.6.24-rc2 on my Lenovo X60s, I sometimes get:
> 
>     hda_intel: No response from codec, disabling MSI: last cmd=0x002f0d00
>     hda_intel: azx_get_response timeout, switching to polling mode: last cmd=0x002f0d00
> 
> when loading snd_hda_intel.  Sound still works but interrupts aren't generated.
> 
> I tried bisecting but I haven't gotten good info yet because it seems
> that this is not completely reproducible -- sometimes when I load the
> module, it works fine, and other times I get the message.
> 
> I think this is a regression, since I don't recall ever seeing the
> message with 2.6.22 or so.
> 
> Any idea on how to help debug this?

You seem to pass unneeded module options to snd-hda-intel driver like
MSI enablement.  First, try to remove all these options.


Takashi

Re: snd_hda_intel 2.6.24-rc2 bug: interrupts don't always work on Lenovo X60s

[Roland Dreier]

 > You seem to pass unneeded module options to snd-hda-intel driver like
 > MSI enablement.  First, try to remove all these options.

Yes, it's trivial to reproduce without any options:

    [ 2311.759856] ACPI: PCI Interrupt 0000:00:1b.0[B] -> GSI 17 (level, low) -> IRQ 21
    [ 2311.759866] hda_intel: probe_mask set to 0x1 for device 17aa:2010
    [ 2311.759886] PCI: Setting latency timer of device 0000:00:1b.0 to 64
    [ 2312.911309] hda_intel: azx_get_response timeout, switching to polling mode: last cmd=0x003f000c

(By the way, what's wrong with using the enable_msi option?  MSI seems
very solid on Intel platforms, and I prefer avoiding shared interrupts)

 - R.

Re: snd_hda_intel 2.6.24-rc2 bug: interrupts don't always work on Lenovo X60s

[Takashi Iwai]

At Mon, 12 Nov 2007 08:59:49 -0800,
Roland Dreier wrote:
> 
>  > You seem to pass unneeded module options to snd-hda-intel driver like
>  > MSI enablement.  First, try to remove all these options.
> 
> Yes, it's trivial to reproduce without any options:
> 
>     [ 2311.759856] ACPI: PCI Interrupt 0000:00:1b.0[B] -> GSI 17 (level, low) -> IRQ 21
>     [ 2311.759866] hda_intel: probe_mask set to 0x1 for device 17aa:2010
>     [ 2311.759886] PCI: Setting latency timer of device 0000:00:1b.0 to 64
>     [ 2312.911309] hda_intel: azx_get_response timeout, switching to polling mode: last cmd=0x003f000c

Hm, strange, NID 0x03 shouldn't be accessed via AD1981 codec, at
least, thinkpad model.  Did you enable CONFIG_SND_HDA_CODEC_ANALOG?
Otherwise it won't work.

> (By the way, what's wrong with using the enable_msi option?  MSI seems
> very solid on Intel platforms, and I prefer avoiding shared interrupts)

It may work, but first we need to make sure that we're seeing the same
problem.  MSI is one of the unstable factors for many platforms, thus
the driver tries to disable MSI first if any sign of wrong irqs is
found.


Takashi

Re: snd_hda_intel 2.6.24-rc2 bug: interrupts don't always work on Lenovo X60s

[Roland Dreier]

 > >     [ 2311.759856] ACPI: PCI Interrupt 0000:00:1b.0[B] -> GSI 17 (level, low) -> IRQ 21
 > >     [ 2311.759866] hda_intel: probe_mask set to 0x1 for device 17aa:2010
 > >     [ 2311.759886] PCI: Setting latency timer of device 0000:00:1b.0 to 64
 > >     [ 2312.911309] hda_intel: azx_get_response timeout, switching to polling mode: last cmd=0x003f000c
 > 
 > Hm, strange, NID 0x03 shouldn't be accessed via AD1981 codec, at
 > least, thinkpad model.  Did you enable CONFIG_SND_HDA_CODEC_ANALOG?
 > Otherwise it won't work.

Yes, I have

    CONFIG_SND_HDA_CODEC_ANALOG=y

in my .config.

By the way, the "polling mode" seems to work OK: I still get normal
playback of music etc.

 - R.

Re: snd_hda_intel 2.6.24-rc2 bug: interrupts don't always work on Lenovo X60s

[Takashi Iwai]

At Mon, 12 Nov 2007 10:46:40 -0800,
Roland Dreier wrote:
> 
>  > >     [ 2311.759856] ACPI: PCI Interrupt 0000:00:1b.0[B] -> GSI 17 (level, low) -> IRQ 21
>  > >     [ 2311.759866] hda_intel: probe_mask set to 0x1 for device 17aa:2010
>  > >     [ 2311.759886] PCI: Setting latency timer of device 0000:00:1b.0 to 64
>  > >     [ 2312.911309] hda_intel: azx_get_response timeout, switching to polling mode: last cmd=0x003f000c
>  > 
>  > Hm, strange, NID 0x03 shouldn't be accessed via AD1981 codec, at
>  > least, thinkpad model.  Did you enable CONFIG_SND_HDA_CODEC_ANALOG?
>  > Otherwise it won't work.
> 
> Yes, I have
> 
>     CONFIG_SND_HDA_CODEC_ANALOG=y
> 
> in my .config.
> 
> By the way, the "polling mode" seems to work OK: I still get normal
> playback of music etc.

Yes, the polling mode should work in most cases, too.

Anyway, could you try the patch below?  As far as I see, it's the only
part that may access PINCAP verb for that NID.


thanks,

Takashi

---

diff -r cd6cede1eca4 sound/pci/hda/hda_codec.c
--- a/sound/pci/hda/hda_codec.c	Mon Nov 12 14:55:19 2007 +0000
+++ b/sound/pci/hda/hda_codec.c	Tue Nov 13 08:28:48 2007 +0100
@@ -1626,19 +1626,26 @@ static void hda_set_power_state(struct h
 
 	nid = codec->start_nid;
 	for (i = 0; i < codec->num_nodes; i++, nid++) {
-		if (get_wcaps(codec, nid) & AC_WCAP_POWER) {
-			unsigned int pincap;
-			/*
-			 * don't power down the widget if it controls eapd
-			 * and EAPD_BTLENABLE is set.
-			 */
-			pincap = snd_hda_param_read(codec, nid, AC_PAR_PIN_CAP);
-			if (pincap & AC_PINCAP_EAPD) {
-				int eapd = snd_hda_codec_read(codec, nid,
-					0, AC_VERB_GET_EAPD_BTLENABLE, 0);
-				eapd &= 0x02;
-				if (power_state == AC_PWRST_D3 && eapd)
-					continue;
+		unsigned int wcaps = get_wcaps(codec, nid);
+		if (wcaps & AC_WCAP_POWER) {
+			unsigned int wid_type = (wcaps & AC_WCAP_TYPE) >>
+				AC_WCAP_TYPE_SHIFT;
+			if (wid_type == AC_WID_PIN) {
+				unsigned int pincap;
+				/*
+				 * don't power down the widget if it controls
+				 * eapd and EAPD_BTLENABLE is set.
+				 */
+				pincap = snd_hda_param_read(codec, nid,
+							    AC_PAR_PIN_CAP);
+				if (pincap & AC_PINCAP_EAPD) {
+					int eapd = snd_hda_codec_read(codec,
+						nid, 0,
+						AC_VERB_GET_EAPD_BTLENABLE, 0);
+					eapd &= 0x02;
+					if (power_state == AC_PWRST_D3 && eapd)
+						continue;
+				}
 			}
 			snd_hda_codec_write(codec, nid, 0,
 					    AC_VERB_SET_POWER_STATE,

Re: snd_hda_intel 2.6.24-rc2 bug: interrupts don't always work on Lenovo X60s

[Roland Dreier]

 > Roland Dreier wrote:
 > > > >     [ 2311.759856] ACPI: PCI Interrupt 0000:00:1b.0[B] -> GSI 17 (level, low) -> IRQ 21
 > > > >     [ 2311.759866] hda_intel: probe_mask set to 0x1 for device 17aa:2010
 > > > >     [ 2311.759886] PCI: Setting latency timer of device 0000:00:1b.0 to 64
 > > > >     [ 2312.911309] hda_intel: azx_get_response timeout, switching to polling mode: last cmd=0x003f000c

 > Anyway, could you try the patch below?  As far as I see, it's the only
 > part that may access PINCAP verb for that NID.

This seems to help in that I don't see the "azx_get_response timeout"
message on every module load as I do with mainline, but I still see a
problem with a different cmd after a few load-unload cycles:

[  257.503143] ACPI: PCI interrupt for device 0000:00:1b.0 disabled
[  259.215359] ACPI: PCI Interrupt 0000:00:1b.0[B] -> GSI 17 (level, low) -> IRQ 22
[  259.215372] hda_intel: probe_mask set to 0x1 for device 17aa:2010
[  259.215398] PCI: Setting latency timer of device 0000:00:1b.0 to 64
[  263.418591] ACPI: PCI interrupt for device 0000:00:1b.0 disabled
[  265.626093] ACPI: PCI Interrupt 0000:00:1b.0[B] -> GSI 17 (level, low) -> IRQ 22
[  265.626105] hda_intel: probe_mask set to 0x1 for device 17aa:2010
[  265.626133] PCI: Setting latency timer of device 0000:00:1b.0 to 64
[  320.898290] ACPI: PCI interrupt for device 0000:00:1b.0 disabled
[  322.874182] ACPI: PCI Interrupt 0000:00:1b.0[B] -> GSI 17 (level, low) -> IRQ 22
[  322.874196] hda_intel: probe_mask set to 0x1 for device 17aa:2010
[  322.874228] PCI: Setting latency timer of device 0000:00:1b.0 to 64
[  333.087177] ACPI: PCI interrupt for device 0000:00:1b.0 disabled
[  334.024358] ACPI: PCI Interrupt 0000:00:1b.0[B] -> GSI 17 (level, low) -> IRQ 22
[  334.024371] hda_intel: probe_mask set to 0x1 for device 17aa:2010
[  334.024395] PCI: Setting latency timer of device 0000:00:1b.0 to 64
[  335.422296] hda_intel: azx_get_response timeout, switching to polling mode: last cmd=0x002f0d00

Thanks,
  Roland

Re: snd_hda_intel 2.6.24-rc2 bug: interrupts don't always work on Lenovo X60s

[Takashi Iwai]

At Wed, 14 Nov 2007 08:39:03 -0800,
Roland Dreier wrote:
> 
>  > Roland Dreier wrote:
>  > > > >     [ 2311.759856] ACPI: PCI Interrupt 0000:00:1b.0[B] -> GSI 17 (level, low) -> IRQ 21
>  > > > >     [ 2311.759866] hda_intel: probe_mask set to 0x1 for device 17aa:2010
>  > > > >     [ 2311.759886] PCI: Setting latency timer of device 0000:00:1b.0 to 64
>  > > > >     [ 2312.911309] hda_intel: azx_get_response timeout, switching to polling mode: last cmd=0x003f000c
> 
>  > Anyway, could you try the patch below?  As far as I see, it's the only
>  > part that may access PINCAP verb for that NID.
> 
> This seems to help in that I don't see the "azx_get_response timeout"
> message on every module load as I do with mainline, but I still see a
> problem with a different cmd after a few load-unload cycles:

What cmd more exactly?  The below is GET_DIGI_CONVERT.  So it must be
related with SPDIF but it must be same as 2.6.23.  Or do you happen to
set CONFIG_SND_HDA_POWER_SAVE=y?

Anyway I think there is no real problem with polling mode.  The driver
switches to it when the response from the hardware gets confused.


Takashi

> [  257.503143] ACPI: PCI interrupt for device 0000:00:1b.0 disabled
> [  259.215359] ACPI: PCI Interrupt 0000:00:1b.0[B] -> GSI 17 (level, low) -> IRQ 22
> [  259.215372] hda_intel: probe_mask set to 0x1 for device 17aa:2010
> [  259.215398] PCI: Setting latency timer of device 0000:00:1b.0 to 64
> [  263.418591] ACPI: PCI interrupt for device 0000:00:1b.0 disabled
> [  265.626093] ACPI: PCI Interrupt 0000:00:1b.0[B] -> GSI 17 (level, low) -> IRQ 22
> [  265.626105] hda_intel: probe_mask set to 0x1 for device 17aa:2010
> [  265.626133] PCI: Setting latency timer of device 0000:00:1b.0 to 64
> [  320.898290] ACPI: PCI interrupt for device 0000:00:1b.0 disabled
> [  322.874182] ACPI: PCI Interrupt 0000:00:1b.0[B] -> GSI 17 (level, low) -> IRQ 22
> [  322.874196] hda_intel: probe_mask set to 0x1 for device 17aa:2010
> [  322.874228] PCI: Setting latency timer of device 0000:00:1b.0 to 64
> [  333.087177] ACPI: PCI interrupt for device 0000:00:1b.0 disabled
> [  334.024358] ACPI: PCI Interrupt 0000:00:1b.0[B] -> GSI 17 (level, low) -> IRQ 22
> [  334.024371] hda_intel: probe_mask set to 0x1 for device 17aa:2010
> [  334.024395] PCI: Setting latency timer of device 0000:00:1b.0 to 64
> [  335.422296] hda_intel: azx_get_response timeout, switching to polling mode: last cmd=0x002f0d00

Re: snd_hda_intel 2.6.24-rc2 bug: interrupts don't always work on Lenovo X60s

[Roland Dreier]

 > NWhat cmd more exactly?  The below is GET_DIGI_CONVERT.  So it must be
 > related with SPDIF but it must be same as 2.6.23.  Or do you happen to
 > set CONFIG_SND_HDA_POWER_SAVE=y?

The new error message is:

    hda_intel: azx_get_response timeout, switching to polling mode: last cmd=0x002f0d00

so the cmd is 0x002f0d00.

I'm not sure if I ever saw this with 2.6.23 or not -- it is rare
enough that I may have missed it.  I do have

    CONFIG_SND_HDA_POWER_SAVE=y
    CONFIG_SND_HDA_POWER_SAVE_DEFAULT=5

in my .config.  And I don't think that the X61s has anything
SPDIF-related accessible on the outside... not sure what mmight be
going on inside of course.

Thanks,
  Roland

Re: snd_hda_intel 2.6.24-rc2 bug: interrupts don't always work on Lenovo X60s

[Takashi Iwai]

At Wed, 14 Nov 2007 09:22:18 -0800,
Roland Dreier wrote:
> 
>  > NWhat cmd more exactly?  The below is GET_DIGI_CONVERT.  So it must be
>  > related with SPDIF but it must be same as 2.6.23.  Or do you happen to
>  > set CONFIG_SND_HDA_POWER_SAVE=y?
> 
> The new error message is:
> 
>     hda_intel: azx_get_response timeout, switching to polling mode: last cmd=0x002f0d00
> 
> so the cmd is 0x002f0d00.
> 
> I'm not sure if I ever saw this with 2.6.23 or not -- it is rare
> enough that I may have missed it.  I do have
> 
>     CONFIG_SND_HDA_POWER_SAVE=y
>     CONFIG_SND_HDA_POWER_SAVE_DEFAULT=5

First try to set power_save_controller=0 module option for
snd-hda-intel.  If this doesn't make any difference, try to turn
CONFIG_SND_HDA_POWER_SAVE off.  If the problem still persists, then I
have no idea what change triggered it.  Maybe you got this in the
earlier versions but in less verbose way...

> in my .config.  And I don't think that the X61s has anything
> SPDIF-related accessible on the outside... not sure what mmight be
> going on inside of course.

It's on the docking station, IIRC.


thanks,

Takashi

Re: snd_hda_intel 2.6.24-rc2 bug: interrupts don't always work on Lenovo X60s

[Theodore Tso]

On Tue, Nov 13, 2007 at 04:43:05AM +0100, Takashi Iwai wrote:
> > By the way, the "polling mode" seems to work OK: I still get normal
> > playback of music etc.
> 
> Yes, the polling mode should work in most cases, too.

Out of curiosity, how many wakeups/interrupts are involved with the
sound going into polling mode?  Is it going to make a difference as
far as battery life is concerned?

I'm seeing the message:

hda_intel: azx_get_response timeout, switching to polling mode: last cmd=0x005f000c

on my X61s laptop as well, where the last_cmd varies quite a bit.
Over the past two weeks, I've seen last cmd be:

0x003f000c, 0x004f000c, 0x005f000c, 0x006f000c, 0x00db8000,
0x011b8000, 0x011ba000, 0x012ba000, 0x012f000c, 0x013f000c,
0x014f000d, 0x019f000c, 0x020b0001, 0x020b0003, 0x020b2000,
0x020b2001, 0x020b2002, 0x025f0012

Interestingly, when I was using a post 2.6.24-rc1 and -rc2 kernel, I
was getting a lot of these "switching polling to mode messages",
usually within a minute of the machine booting.  Now that I have
switched to a recent rc3 kernel, they seem to have largely gone away.

Looking at my kernel, it looks like the patch you suggested to Roland
was *not* applied, and "git log sound/pci/hda" shows that the only
change to that directory was a patch from Ingo Molnar that I had
cherry picked from LKML.  Given that we were doing a
schedule_timeout_uninterruptible for a full second, that certainly
seems to be a likely candidate for why we were getting the response
timeout message!  Does this analysis make sense to you?

Regards,

						- Ted

commit 2f7e58208e0d59ca6e4ad1561f47391d4efa19fa
Author: Ingo Molnar <mingo@elte.hu>
Date:   Fri Nov 16 11:35:05 2007 -0500

    snd hda suspend latency: shorten codec read
    
    not sleeping for every codec read/write but doing a short udelay and
    a conditional reschedule has cut suspend+resume latency by about 1
    second on my T60.
    
    Signed-off-by: Ingo Molnar <mingo@elte.hu>

diff --git a/sound/pci/hda/hda_intel.c b/sound/pci/hda/hda_intel.c
index 3fa0f97..62b9fb3 100644
--- a/sound/pci/hda/hda_intel.c
+++ b/sound/pci/hda/hda_intel.c
@@ -555,7 +555,8 @@ static unsigned int azx_rirb_get_response(struct hda_codec *codec)
 		}
 		if (!chip->rirb.cmds)
 			return chip->rirb.res; /* the last value */
-		schedule_timeout_uninterruptible(1);
+		udelay(10);
+		cond_resched();
 	} while (time_after_eq(timeout, jiffies));
 
 	if (chip->msi) {

Re: snd_hda_intel 2.6.24-rc2 bug: interrupts don't always work on Lenovo X60s

[Takashi Iwai]

At Thu, 22 Nov 2007 12:42:42 -0500,
Theodore Tso wrote:
> 
> On Tue, Nov 13, 2007 at 04:43:05AM +0100, Takashi Iwai wrote:
> > > By the way, the "polling mode" seems to work OK: I still get normal
> > > playback of music etc.
> > 
> > Yes, the polling mode should work in most cases, too.
> 
> Out of curiosity, how many wakeups/interrupts are involved with the
> sound going into polling mode?  Is it going to make a difference as
> far as battery life is concerned?

Switch to polling mode is judged whether the response comes within one
second.  It's irrelevant of number of interrupts.
This mechanism was introduced at the time many devices have broken
BIOS and indeed irq was screwed up.

But, the polling mode is no dramatic change.  This means that the
driver polls the response value not only waiting for an ACK via 
irq.  Thus no big change over battery life.  The new option,
CONFIG_SND_HDA_POWER_SAVE, is a far bigger behavior change and would
influence a lot more on battery life.


> I'm seeing the message:
> 
> hda_intel: azx_get_response timeout, switching to polling mode: last cmd=0x005f000c
> 
> on my X61s laptop as well, where the last_cmd varies quite a bit.
> Over the past two weeks, I've seen last cmd be:
> 
> 0x003f000c, 0x004f000c, 0x005f000c, 0x006f000c, 0x00db8000,
> 0x011b8000, 0x011ba000, 0x012ba000, 0x012f000c, 0x013f000c,
> 0x014f000d, 0x019f000c, 0x020b0001, 0x020b0003, 0x020b2000,
> 0x020b2001, 0x020b2002, 0x025f0012

A half of them should go away with my patch.  They are wrong PINCAP
verbs.  But others seem not.

> Interestingly, when I was using a post 2.6.24-rc1 and -rc2 kernel, I
> was getting a lot of these "switching polling to mode messages",
> usually within a minute of the machine booting.  Now that I have
> switched to a recent rc3 kernel, they seem to have largely gone away.

Interesting, indeed.

> Looking at my kernel, it looks like the patch you suggested to Roland
> was *not* applied, and "git log sound/pci/hda" shows that the only
> change to that directory was a patch from Ingo Molnar that I had
> cherry picked from LKML.  Given that we were doing a
> schedule_timeout_uninterruptible for a full second, that certainly
> seems to be a likely candidate for why we were getting the response
> timeout message!  Does this analysis make sense to you?

It might be true.  As mentioned, the threshold to polling mode is one
second.  If schedule_timeout_uninterruptible(1) takes one second, of
course, this fails.  I didn't expect that schedule_timeout() may take
that long.

If Ingo's patch really helps in such a situation, we should get it
into 2.6.24.  It's already in ALSA tree (perex/alsa.git mm branch),
but I didn't ask Jaroslav to included in the push chunk.

Jaroslav, care to push again?


thanks,

Takashi

> 
> Regards,
> 
> 						- Ted
> 
> commit 2f7e58208e0d59ca6e4ad1561f47391d4efa19fa
> Author: Ingo Molnar <mingo@elte.hu>
> Date:   Fri Nov 16 11:35:05 2007 -0500
> 
>     snd hda suspend latency: shorten codec read
>     
>     not sleeping for every codec read/write but doing a short udelay and
>     a conditional reschedule has cut suspend+resume latency by about 1
>     second on my T60.
>     
>     Signed-off-by: Ingo Molnar <mingo@elte.hu>
> 
> diff --git a/sound/pci/hda/hda_intel.c b/sound/pci/hda/hda_intel.c
> index 3fa0f97..62b9fb3 100644
> --- a/sound/pci/hda/hda_intel.c
> +++ b/sound/pci/hda/hda_intel.c
> @@ -555,7 +555,8 @@ static unsigned int azx_rirb_get_response(struct hda_codec *codec)
>  		}
>  		if (!chip->rirb.cmds)
>  			return chip->rirb.res; /* the last value */
> -		schedule_timeout_uninterruptible(1);
> +		udelay(10);
> +		cond_resched();
>  	} while (time_after_eq(timeout, jiffies));
>  
>  	if (chip->msi) {
>