LinuxLists.cc - [BUG] 4.15-rc4 'do_IRQ: 0.33 No irq handler for vector'

2017-12-19 04:31:41

Subject: [BUG] 4.15-rc4 'do_IRQ: 0.33 No irq handler for vector'

Hello everyone,

While investigating `journalctl -k` for anything associated with broken
audio, this was found:

Dec 18 16:09:28 iridesce kernel: do_IRQ: 0.33 No irq handler for vector
Dec 18 16:10:21 iridesce kernel: ata1.00: exception Emask 0x0 SAct 0xfe0 SErr 0x0 action 0x6 frozen
Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/08:28:30:92:79/00:00:1c:00:00/40 tag 5 ncq dma 4096 out
res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/08:30:10:20:68/00:00:00:00:00/40 tag 6 ncq dma 4096 out
res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/08:38:30:5d:ec/00:00:1c:00:00/40 tag 7 ncq dma 4096 out
res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/48:40:c0:75:64/00:00:00:00:00/40 tag 8 ncq dma 36864 out
res 40/00:fe:00:00:00/00:00:00:00:00/40 Emask 0x4 (timeout)
Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/08:48:20:20:ec/00:00:1c:00:00/40 tag 9 ncq dma 4096 out
res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/08:50:80:20:78/00:00:1c:00:00/40 tag 10 ncq dma 4096 out
res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/08:58:90:3e:78/00:00:1c:00:00/40 tag 11 ncq dma 4096 out
res 40/00:01:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
Dec 18 16:10:21 iridesce kernel: ata1: hard resetting link
Dec 18 16:10:21 iridesce kernel: ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Dec 18 16:10:21 iridesce kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
Dec 18 16:10:21 iridesce kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
Dec 18 16:10:21 iridesce kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
Dec 18 16:10:21 iridesce kernel: ata1.00: supports DRM functions and may not be fully accessible
Dec 18 16:10:21 iridesce kernel: ata1.00: NCQ Send/Recv Log not supported
Dec 18 16:10:21 iridesce kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
Dec 18 16:10:21 iridesce kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
Dec 18 16:10:21 iridesce kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
Dec 18 16:10:21 iridesce kernel: ata1.00: supports DRM functions and may not be fully accessible
Dec 18 16:10:21 iridesce kernel: ata1.00: NCQ Send/Recv Log not supported
Dec 18 16:10:21 iridesce kernel: ata1.00: configured for UDMA/133
Dec 18 16:10:21 iridesce kernel: ata1.00: device reported invalid CHS sector 0
Dec 18 16:10:21 iridesce kernel: ata1.00: device reported invalid CHS sector 0
Dec 18 16:10:21 iridesce kernel: ata1.00: device reported invalid CHS sector 0
Dec 18 16:10:21 iridesce kernel: ata1.00: device reported invalid CHS sector 0
Dec 18 16:10:21 iridesce kernel: ata1.00: device reported invalid CHS sector 0
Dec 18 16:10:21 iridesce kernel: ata1: EH complete

I have approximately ~300 boots logged back to kernel 4.13.0-rc7, and
there's not a single occurrence of this kind of thing in any of them.

Now 4.15-rc4 is my first 4.15 kernel, so I don't know if this was
introduced in one of the RCs or if it's 4.15-*.

I also don't know if this is associated with the audio problem I
observed. Nor do I know if this is reproducible. It hasn't recurred
yet, and I'm now in my second boot of 4.15-rc4. The problem is, I'm not
likely to spend much time in 4.15-rc4 with audio malfunctioning, as this
is my primary laptop and music tends to always be playing.

Machine is thinkpad x61s, 840 evo ssd, kernel config attached.

Regards,
Vito Caputo

Attachments:

(No filename) (4.96 kB)
v4.15-rc4.config.gz (25.00 kB)
Download all attachments

2017-12-30 20:47:31

by Alan Cox

[permalink] [raw]

Subject: Re: [BUG] 4.15-rc4 'do_IRQ: 0.33 No irq handler for vector'

On Mon, 18 Dec 2017 20:39:17 -0800
[email protected] wrote:

> Hello everyone,
>
> While investigating `journalctl -k` for anything associated with broken
> audio, this was found:
>
> Dec 18 16:09:28 iridesce kernel: do_IRQ: 0.33 No irq handler for vector

That first one is a bit weird. But it looks like your machine got very
upset.

> Dec 18 16:10:21 iridesce kernel: ata1.00: exception Emask 0x0 SAct 0xfe0 SErr 0x0 action 0x6 frozen
> Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
> Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/08:28:30:92:79/00:00:1c:00:00/40 tag 5 ncq dma 4096 out
> res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
> Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
> Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/08:30:10:20:68/00:00:00:00:00/40 tag 6 ncq dma 4096 out
> res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
> Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
> Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/08:38:30:5d:ec/00:00:1c:00:00/40 tag 7 ncq dma 4096 out
> res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
> Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
> Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/48:40:c0:75:64/00:00:00:00:00/40 tag 8 ncq dma 36864 out
> res 40/00:fe:00:00:00/00:00:00:00:00/40 Emask 0x4 (timeout)
> Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
> Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
> Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/08:48:20:20:ec/00:00:1c:00:00/40 tag 9 ncq dma 4096 out
> res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
> Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
> Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/08:50:80:20:78/00:00:1c:00:00/40 tag 10 ncq dma 4096 out
> res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
> Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
> Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/08:58:90:3e:78/00:00:1c:00:00/40 tag 11 ncq dma 4096 out
> res 40/00:01:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }

Your hard disk stopped responding

> Dec 18 16:10:21 iridesce kernel: ata1: hard resetting link
> Dec 18 16:10:21 iridesce kernel: ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
> Dec 18 16:10:21 iridesce kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
> Dec 18 16:10:21 iridesce kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
> Dec 18 16:10:21 iridesce kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
> Dec 18 16:10:21 iridesce kernel: ata1.00: supports DRM functions and may not be fully accessible
> Dec 18 16:10:21 iridesce kernel: ata1.00: NCQ Send/Recv Log not supported
> Dec 18 16:10:21 iridesce kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
> Dec 18 16:10:21 iridesce kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
> Dec 18 16:10:21 iridesce kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
> Dec 18 16:10:21 iridesce kernel: ata1.00: supports DRM functions and may not be fully accessible
> Dec 18 16:10:21 iridesce kernel: ata1.00: NCQ Send/Recv Log not supported
> Dec 18 16:10:21 iridesce kernel: ata1.00: configured for UDMA/133

And while it kind of came back

> Dec 18 16:10:21 iridesce kernel: ata1.00: device reported invalid CHS sector 0
> Dec 18 16:10:21 iridesce kernel: ata1.00: device reported invalid CHS sector 0
> Dec 18 16:10:21 iridesce kernel: ata1.00: device reported invalid CHS sector 0
> Dec 18 16:10:21 iridesce kernel: ata1.00: device reported invalid CHS sector 0
> Dec 18 16:10:21 iridesce kernel: ata1.00: device reported invalid CHS sector 0
> Dec 18 16:10:21 iridesce kernel: ata1: EH complete

It wasn't talking sense.

Do you see the same whenever the audio fails ?

2017-12-31 08:40:06

by Vito Caputo

[permalink] [raw]

Subject: Re: [BUG] 4.15-rc4 'do_IRQ: 0.33 No irq handler for vector'

On Sat, Dec 30, 2017 at 08:47:23PM +0000, Alan Cox wrote:
> On Mon, 18 Dec 2017 20:39:17 -0800
> [email protected] wrote:
>
> > Hello everyone,
> >
> > While investigating `journalctl -k` for anything associated with broken
> > audio, this was found:
> >
> > Dec 18 16:09:28 iridesce kernel: do_IRQ: 0.33 No irq handler for vector
>
> That first one is a bit weird. But it looks like your machine got very
> upset.
>
> > Dec 18 16:10:21 iridesce kernel: ata1.00: exception Emask 0x0 SAct 0xfe0 SErr 0x0 action 0x6 frozen
> > Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
> > Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/08:28:30:92:79/00:00:1c:00:00/40 tag 5 ncq dma 4096 out
> > res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> > Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
> > Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
> > Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/08:30:10:20:68/00:00:00:00:00/40 tag 6 ncq dma 4096 out
> > res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> > Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
> > Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
> > Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/08:38:30:5d:ec/00:00:1c:00:00/40 tag 7 ncq dma 4096 out
> > res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> > Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
> > Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
> > Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/48:40:c0:75:64/00:00:00:00:00/40 tag 8 ncq dma 36864 out
> > res 40/00:fe:00:00:00/00:00:00:00:00/40 Emask 0x4 (timeout)
> > Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
> > Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
> > Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/08:48:20:20:ec/00:00:1c:00:00/40 tag 9 ncq dma 4096 out
> > res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> > Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
> > Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
> > Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/08:50:80:20:78/00:00:1c:00:00/40 tag 10 ncq dma 4096 out
> > res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> > Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
> > Dec 18 16:10:21 iridesce kernel: ata1.00: failed command: WRITE FPDMA QUEUED
> > Dec 18 16:10:21 iridesce kernel: ata1.00: cmd 61/08:58:90:3e:78/00:00:1c:00:00/40 tag 11 ncq dma 4096 out
> > res 40/00:01:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> > Dec 18 16:10:21 iridesce kernel: ata1.00: status: { DRDY }
>
> Your hard disk stopped responding
>
> > Dec 18 16:10:21 iridesce kernel: ata1: hard resetting link
> > Dec 18 16:10:21 iridesce kernel: ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
> > Dec 18 16:10:21 iridesce kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
> > Dec 18 16:10:21 iridesce kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
> > Dec 18 16:10:21 iridesce kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
> > Dec 18 16:10:21 iridesce kernel: ata1.00: supports DRM functions and may not be fully accessible
> > Dec 18 16:10:21 iridesce kernel: ata1.00: NCQ Send/Recv Log not supported
> > Dec 18 16:10:21 iridesce kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
> > Dec 18 16:10:21 iridesce kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
> > Dec 18 16:10:21 iridesce kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
> > Dec 18 16:10:21 iridesce kernel: ata1.00: supports DRM functions and may not be fully accessible
> > Dec 18 16:10:21 iridesce kernel: ata1.00: NCQ Send/Recv Log not supported
> > Dec 18 16:10:21 iridesce kernel: ata1.00: configured for UDMA/133
>
> And while it kind of came back
>
> > Dec 18 16:10:21 iridesce kernel: ata1.00: device reported invalid CHS sector 0
> > Dec 18 16:10:21 iridesce kernel: ata1.00: device reported invalid CHS sector 0
> > Dec 18 16:10:21 iridesce kernel: ata1.00: device reported invalid CHS sector 0
> > Dec 18 16:10:21 iridesce kernel: ata1.00: device reported invalid CHS sector 0
> > Dec 18 16:10:21 iridesce kernel: ata1.00: device reported invalid CHS sector 0
> > Dec 18 16:10:21 iridesce kernel: ata1: EH complete
>
> It wasn't talking sense.
>
>
> Do you see the same whenever the audio fails ?

Hi Alan,

This seems to be related to and already fixed by:
https://lkml.org/lkml/2017/12/28/665

Thanks,
Vito Caputo