* Re: 2.6.29 regression: ATA bus errors on resume [not found] ` <cjJCb-47c-23@gated-at.bofh.it> @ 2009-03-27 19:10 ` Niel Lambrechts 2009-03-27 22:30 ` Arjan van de Ven 2009-03-30 8:55 ` Tejun Heo 0 siblings, 2 replies; 9+ messages in thread From: Niel Lambrechts @ 2009-03-27 19:10 UTC (permalink / raw) To: linux.kernel Cc: James Bottomley, Pavel Machek, Rafael J. Wysocki, Linux IDE mailing list, Arjan van de Ven, Jeff Garzik [-- Attachment #1: Type: text/plain, Size: 5112 bytes --] On 03/26/2009 12:20 AM, James Bottomley wrote: > On Wed, 2009-03-25 at 02:06 -0400, Jeff Garzik wrote: >> Niel Lambrechts wrote: >>> On 03/25/2009 03:30 AM, Theodore Tso wrote: >>>> On Tue, Mar 24, 2009 at 10:25:57PM +0200, Niel Lambrechts wrote: >>>>> Hi, >>>>> >>>>> After upgrading to 2.6.29 I get the below errors after resuming from >>>>> hibernating with s2disk. I ran fsck and tried doing the same thing again >>>>> in 2.6.28.9-pae, but do not get any errors there. >>>> The ext4 errors are interleaved with hardware errors, and the ext4 >>>> errors are about I/O errors. >>>> >>>> EXT4-fs error (device sda6): __ext4_get_inode_loc: unable to read inode block - inode=2346519 >>>> EXT4-fs error (device sda6) in ext4_reserve_inode_write: IO failure >>>> >>>> This looks more like a hibernation problem than an ext4 problem. >>>> Looks like the hard drive is being left in some inconsistent state >>>> after resuming from hibernation. >>>> >>>> - Ted >>> Thanks for the info Theodore, this is definitely looks like some type of >>> regression in 2.6.29, as the problem is not evident when I s2disk using >>> 2.6.28.9, even after multiple suspend/resume cycles. >>> >>> I found some 'ATA bus errors' and 'SError' messages in >>> /var/log/messages, so I've attached the messages from both 2.6.29 and >>> 2.6.28 for comparison. >> Well, here is the interpretation of messages: >> >>> ata1.00: irq_stat 0x00400008, PHY RDY changed >>> ata1: SError: { PHYRdyChg CommWake } >> Your SATA hardware flags a connect-or-disconnect event ("PHY RDY"), >> which requires us to abort a bunch of queued commands: >> >>> ata1.00: cmd 60/18:00:77:88:6f/00:00:0e:00:00/40 tag 0 ncq 12288 in >>> res 50/00:30:07:b3:10/00:00:0c:00:00/40 Emask 0x10 (ATA bus error) >> [...] >>> ata1.00: cmd 60/30:68:07:b3:10/00:00:0c:00:00/40 tag 13 ncq 24576 in >>> res 50/00:30:07:b3:10/00:00:0c:00:00/40 Emask 0x10 (ATA bus error) >> ...through the 14th command (tag 13). >> >>> Mar 24 21:29:14 linux-7vph kernel: ata1: hard resetting link >>> Mar 24 21:29:14 linux-7vph kernel: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300) >>> Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 succeeded >>> Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 filtered out >>> Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 succeeded >>> Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 filtered out >>> Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 succeeded >>> Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 filtered out >>> Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 succeeded >>> Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 filtered out >>> Mar 24 21:29:14 linux-7vph kernel: ata1.00: configured for UDMA/133 >>> Mar 24 21:29:14 linux-7vph kernel: ata1.00: configured for UDMA/133 >> >> SATA link is reset, and ACPI is re-run. >> >>> Mar 24 21:29:14 linux-7vph kernel: sd 0:0:0:0: [sda] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE,SUGGEST_OK >>> Mar 24 21:29:14 linux-7vph kernel: sd 0:0:0:0: [sda] Sense Key : Aborted Command [current] [descriptor] >>> Mar 24 21:29:14 linux-7vph kernel: Descriptor sense data with sense descriptors (in hex): >>> Mar 24 21:29:14 linux-7vph kernel: 72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00 >>> Mar 24 21:29:14 linux-7vph kernel: 0c 10 b3 07 >>> Mar 24 21:29:14 linux-7vph kernel: sd 0:0:0:0: [sda] Add. Sense: No additional sense information >>> Mar 24 21:29:14 linux-7vph kernel: end_request: I/O error, dev sda, sector 242190455 >> The SCSI subsystem aborts each of the queued commands. > > No .. this is the SCSI subsystem receives an ABORTED COMMAND return in > sense data for each of the outstanding I/Os > > The only place these are generated is in ata_sense_to_error() which only > occurs if there's some type of ata error. > > If I had to theorise, I'd say the system suspended with commands > outstanding to the device. On resume, the device gets reset and returns > some type of ATA error which gets translated to ABORTED COMMAND which > causes a failure. > > In the mid layer, we translate ABORTED_COMMAND into a retry until the > command runs out of them ... could it be there's a race readying the > device and we run through the retries before it can accept the command? I'm seeing some dubious looking ATA messages even on 2.6.28.9-pae, although with all the 2.6.28 variants I used s2disk/resume has always worked. I was wondering if these "errors" perhaps play more of a role in 2.6.29, perhaps due to the async. changes that was mentioned? In particular, I notice some the following before "EH complete": ata1: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0x9 t4 ata1: irq_stat 0x00400040, connection status changed but before this last message there is a ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300) Why would the connection status change if a moment ago it was "link up"? Niel [-- Attachment #2: resume-2.6.28.txt --] [-- Type: text/plain, Size: 12702 bytes --] Mar 27 20:18:01 linux-7vph -- MARK -- Mar 27 20:18:01 linux-7vph syslog-ng[32661]: Log statistics; dropped='pipe(/dev/xconsole)=0', dropped='pipe(/dev/tty10)=0', processed='center(queued)=350', processed='center(received)=284', processed='destination(newsnotice)=0', processed='destination(acpid)=8', processed='destination(firewall)=0', processed='destination(null)=61', processed='destination(mail)=0', processed='destination(mailinfo)=0', processed='destination(console)=20', processed='destination(newserr)=0', processed='destination(newscrit)=0', processed='destination(messages)=129', processed='destination(mailwarn)=0', processed='destination(localmessages)=0', processed='destination(netmgm)=86', processed='destination(mailerr)=0', processed='destination(xconsole)=20', processed='destination(warn)=26', processed='source(src)=284' Mar 27 20:18:00 linux-7vph kernel: Syncing filesystems ... done. Mar 27 20:18:01 linux-7vph kernel: Freezing user space processes ... (elapsed 0.00 seconds) done. Mar 27 20:18:01 linux-7vph kernel: Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done. Mar 27 20:18:01 linux-7vph kernel: PM: Shrinking memory... done (57185 pages freed) Mar 27 20:18:01 linux-7vph kernel: PM: Freed 228740 kbytes in 2.03 seconds (112.67 MB/s) Mar 27 20:18:01 linux-7vph kernel: Suspending console(s) (use no_console_suspend to debug) Mar 27 20:18:01 linux-7vph kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache Mar 27 20:18:01 linux-7vph kernel: ACPI handle has no context! Mar 27 20:18:01 linux-7vph kernel: ehci_hcd 0000:00:1d.7: PCI INT D disabled Mar 27 20:18:01 linux-7vph kernel: uhci_hcd 0000:00:1d.2: PCI INT C disabled Mar 27 20:18:01 linux-7vph kernel: uhci_hcd 0000:00:1d.1: PCI INT B disabled Mar 27 20:18:01 linux-7vph kernel: uhci_hcd 0000:00:1d.0: PCI INT A disabled Mar 27 20:18:01 linux-7vph kernel: HDA Intel 0000:00:1b.0: PCI INT B disabled Mar 27 20:18:01 linux-7vph kernel: ehci_hcd 0000:00:1a.7: PCI INT D disabled Mar 27 20:18:01 linux-7vph kernel: uhci_hcd 0000:00:1a.2: PCI INT C disabled Mar 27 20:18:01 linux-7vph kernel: uhci_hcd 0000:00:1a.1: PCI INT B disabled Mar 27 20:18:01 linux-7vph kernel: uhci_hcd 0000:00:1a.0: PCI INT A disabled Mar 27 20:18:01 linux-7vph kernel: e1000e 0000:00:19.0: PME# enabled Mar 27 20:18:01 linux-7vph kernel: e1000e 0000:00:19.0: wake-up capability enabled by ACPI Mar 27 20:18:01 linux-7vph kernel: e1000e 0000:00:19.0: PME# enabled Mar 27 20:18:01 linux-7vph kernel: e1000e 0000:00:19.0: wake-up capability enabled by ACPI Mar 27 20:18:06 linux-7vph kernel: e1000e 0000:00:19.0: PCI INT A disabled Mar 27 20:18:06 linux-7vph kernel: ACPI: Preparing to enter system sleep state S4 Mar 27 20:18:06 linux-7vph kernel: Disabling non-boot CPUs ... Mar 27 20:18:06 linux-7vph kernel: CPU 1 is now offline Mar 27 20:18:06 linux-7vph kernel: SMP alternatives: switching to UP code Mar 27 20:18:06 linux-7vph kernel: CPU0 attaching NULL sched-domain. Mar 27 20:18:06 linux-7vph kernel: CPU1 attaching NULL sched-domain. Mar 27 20:18:06 linux-7vph kernel: CPU0 attaching NULL sched-domain. Mar 27 20:18:06 linux-7vph kernel: CPU1 is down Mar 27 20:18:06 linux-7vph kernel: Extended CMOS year: 2000 Mar 27 20:18:06 linux-7vph kernel: PM: Creating hibernation image: Mar 27 20:18:06 linux-7vph kernel: PM: Need to copy 125532 pages Mar 27 20:18:06 linux-7vph kernel: x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106 Mar 27 20:18:06 linux-7vph kernel: Intel machine check architecture supported. Mar 27 20:18:06 linux-7vph kernel: Intel machine check reporting enabled on CPU#0. Mar 27 20:18:06 linux-7vph kernel: Extended CMOS year: 2000 Mar 27 20:18:06 linux-7vph kernel: Enabling non-boot CPUs ... Mar 27 20:18:06 linux-7vph kernel: SMP alternatives: switching to SMP code Mar 27 20:18:06 linux-7vph kernel: Booting processor 1 APIC 0x1 ip 0x6000 Mar 27 20:18:06 linux-7vph kernel: Initializing CPU#1 Mar 27 20:18:06 linux-7vph kernel: Calibrating delay using timer specific routine.. 5054.03 BogoMIPS (lpj=10108064) Mar 27 20:18:06 linux-7vph kernel: CPU: L1 I cache: 32K, L1 D cache: 32K Mar 27 20:18:06 linux-7vph kernel: CPU: L2 cache: 6144K Mar 27 20:18:06 linux-7vph kernel: CPU: Physical Processor ID: 0 Mar 27 20:18:06 linux-7vph kernel: CPU: Processor Core ID: 1 Mar 27 20:18:06 linux-7vph kernel: Intel machine check architecture supported. Mar 27 20:18:06 linux-7vph kernel: Intel machine check reporting enabled on CPU#1. Mar 27 20:18:06 linux-7vph kernel: x86 PAT enabled: cpu 1, old 0x7040600070406, new 0x7010600070106 Mar 27 20:18:06 linux-7vph kernel: CPU1: Intel(R) Core(TM)2 Duo CPU T9400 @ 2.53GHz stepping 06 Mar 27 20:18:06 linux-7vph kernel: CPU0 attaching NULL sched-domain. Mar 27 20:18:06 linux-7vph kernel: CPU0 attaching sched-domain: Mar 27 20:18:06 linux-7vph kernel: domain 0: span 0-1 level MC Mar 27 20:18:06 linux-7vph kernel: groups: 0 1 Mar 27 20:18:06 linux-7vph kernel: domain 1: span 0-1 level CPU Mar 27 20:18:06 linux-7vph kernel: groups: 0-1 Mar 27 20:18:06 linux-7vph kernel: CPU1 attaching sched-domain: Mar 27 20:18:06 linux-7vph kernel: domain 0: span 0-1 level MC Mar 27 20:18:06 linux-7vph kernel: groups: 1 0 Mar 27 20:18:06 linux-7vph kernel: domain 1: span 0-1 level CPU Mar 27 20:18:06 linux-7vph kernel: groups: 0-1 Mar 27 20:18:06 linux-7vph kernel: Switched to high resolution mode on CPU 1 Mar 27 20:18:06 linux-7vph kernel: CPU1 is up Mar 27 20:18:06 linux-7vph kernel: ACPI: Waking up from system sleep state S4 Mar 27 20:18:06 linux-7vph kernel: APIC error on CPU1: 00(40) Mar 27 20:18:06 linux-7vph kernel: ACPI: EC: non-query interrupt received, switching to interrupt mode Mar 27 20:18:06 linux-7vph kernel: pci 0000:00:02.0: restoring config space at offset 0x1 (was 0x900007, writing 0x900407) Mar 27 20:18:06 linux-7vph kernel: pci 0000:00:02.0: power state changed by ACPI to D0 Mar 27 20:18:06 linux-7vph kernel: pci 0000:00:02.0: setting latency timer to 64 Mar 27 20:18:06 linux-7vph kernel: e1000e 0000:00:19.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20 Mar 27 20:18:06 linux-7vph kernel: e1000e 0000:00:19.0: setting latency timer to 64 Mar 27 20:18:06 linux-7vph kernel: e1000e 0000:00:19.0: wake-up capability disabled by ACPI Mar 27 20:18:06 linux-7vph kernel: e1000e 0000:00:19.0: PME# disabled Mar 27 20:18:06 linux-7vph kernel: e1000e 0000:00:19.0: wake-up capability disabled by ACPI Mar 27 20:18:06 linux-7vph kernel: e1000e 0000:00:19.0: PME# disabled Mar 27 20:18:06 linux-7vph kernel: e1000e 0000:00:19.0: irq 2298 for MSI/MSI-X Mar 27 20:18:06 linux-7vph kernel: uhci_hcd 0000:00:1a.0: power state changed by ACPI to D0 Mar 27 20:18:06 linux-7vph kernel: uhci_hcd 0000:00:1a.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20 Mar 27 20:18:06 linux-7vph kernel: uhci_hcd 0000:00:1a.0: setting latency timer to 64 Mar 27 20:18:06 linux-7vph kernel: uhci_hcd 0000:00:1a.1: PCI INT B -> GSI 21 (level, low) -> IRQ 21 Mar 27 20:18:06 linux-7vph kernel: uhci_hcd 0000:00:1a.1: setting latency timer to 64 Mar 27 20:18:06 linux-7vph kernel: uhci_hcd 0000:00:1a.2: power state changed by ACPI to D0 Mar 27 20:18:06 linux-7vph kernel: uhci_hcd 0000:00:1a.2: PCI INT C -> GSI 22 (level, low) -> IRQ 22 Mar 27 20:18:06 linux-7vph kernel: uhci_hcd 0000:00:1a.2: setting latency timer to 64 Mar 27 20:18:06 linux-7vph kernel: ehci_hcd 0000:00:1a.7: power state changed by ACPI to D0 Mar 27 20:18:06 linux-7vph kernel: ehci_hcd 0000:00:1a.7: PCI INT D -> GSI 23 (level, low) -> IRQ 23 Mar 27 20:18:06 linux-7vph kernel: ehci_hcd 0000:00:1a.7: setting latency timer to 64 Mar 27 20:18:06 linux-7vph kernel: HDA Intel 0000:00:1b.0: restoring config space at offset 0x1 (was 0x100106, writing 0x100102) Mar 27 20:18:06 linux-7vph kernel: HDA Intel 0000:00:1b.0: PCI INT B -> GSI 17 (level, low) -> IRQ 17 Mar 27 20:18:06 linux-7vph kernel: HDA Intel 0000:00:1b.0: setting latency timer to 64 Mar 27 20:18:06 linux-7vph kernel: pcieport-driver 0000:00:1c.0: setting latency timer to 64 Mar 27 20:18:06 linux-7vph kernel: pcieport-driver 0000:00:1c.1: setting latency timer to 64 Mar 27 20:18:06 linux-7vph kernel: pcieport-driver 0000:00:1c.3: setting latency timer to 64 Mar 27 20:18:06 linux-7vph kernel: pcieport-driver 0000:00:1c.4: setting latency timer to 64 Mar 27 20:18:06 linux-7vph kernel: uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0 Mar 27 20:18:06 linux-7vph kernel: uhci_hcd 0000:00:1d.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16 Mar 27 20:18:06 linux-7vph kernel: uhci_hcd 0000:00:1d.0: setting latency timer to 64 Mar 27 20:18:06 linux-7vph kernel: uhci_hcd 0000:00:1d.1: PCI INT B -> GSI 17 (level, low) -> IRQ 17 Mar 27 20:18:06 linux-7vph kernel: uhci_hcd 0000:00:1d.1: setting latency timer to 64 Mar 27 20:18:06 linux-7vph kernel: uhci_hcd 0000:00:1d.2: PCI INT C -> GSI 18 (level, low) -> IRQ 18 Mar 27 20:18:06 linux-7vph kernel: uhci_hcd 0000:00:1d.2: setting latency timer to 64 Mar 27 20:18:06 linux-7vph kernel: ehci_hcd 0000:00:1d.7: power state changed by ACPI to D0 Mar 27 20:18:06 linux-7vph kernel: ehci_hcd 0000:00:1d.7: PCI INT D -> GSI 19 (level, low) -> IRQ 19 Mar 27 20:18:06 linux-7vph kernel: ehci_hcd 0000:00:1d.7: setting latency timer to 64 Mar 27 20:18:06 linux-7vph kernel: pci 0000:00:1e.0: setting latency timer to 64 Mar 27 20:18:06 linux-7vph kernel: ahci 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b00403, writing 0x2b00407) Mar 27 20:18:06 linux-7vph kernel: ahci 0000:00:1f.2: setting latency timer to 64 Mar 27 20:18:06 linux-7vph kernel: pci 0000:15:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16 Mar 27 20:18:06 linux-7vph kernel: ohci1394: fw-host0: OHCI-1394 1.1 (PCI): IRQ=[17] MMIO=[f4801000-f48017ff] Max Packet=[2048] IR/IT contexts=[4/4] Mar 27 20:18:06 linux-7vph kernel: sd 0:0:0:0: [sda] Starting disk Mar 27 20:18:06 linux-7vph kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300) Mar 27 20:18:06 linux-7vph kernel: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300) Mar 27 20:18:06 linux-7vph kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 succeeded Mar 27 20:18:06 linux-7vph kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 filtered out Mar 27 20:18:06 linux-7vph kernel: ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 succeeded Mar 27 20:18:06 linux-7vph kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 filtered out Mar 27 20:18:06 linux-7vph kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 succeeded Mar 27 20:18:06 linux-7vph kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 filtered out Mar 27 20:18:06 linux-7vph kernel: ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 succeeded Mar 27 20:18:06 linux-7vph kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 filtered out Mar 27 20:18:06 linux-7vph kernel: ata1.00: configured for UDMA/133 Mar 27 20:18:06 linux-7vph kernel: ata1: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0x9 t4 Mar 27 20:18:06 linux-7vph kernel: ata1: irq_stat 0x00400040, connection status changed Mar 27 20:18:06 linux-7vph kernel: ata2.00: ACPI cmd e3/00:1f:00:00:00:a0 succeeded Mar 27 20:18:06 linux-7vph kernel: ata2.00: ACPI cmd e3/00:02:00:00:00:a0 succeeded Mar 27 20:18:06 linux-7vph kernel: ata1.00: configured for UDMA/133 Mar 27 20:18:06 linux-7vph kernel: ata1: EH complete Mar 27 20:18:06 linux-7vph kernel: sd 0:0:0:0: [sda] 390721968 512-byte hardware sectors: (200 GB/186 GiB) Mar 27 20:18:06 linux-7vph kernel: sd 0:0:0:0: [sda] Write Protect is off Mar 27 20:18:06 linux-7vph kernel: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00 Mar 27 20:18:06 linux-7vph kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA Mar 27 20:18:06 linux-7vph kernel: sd 0:0:0:0: [sda] 390721968 512-byte hardware sectors: (200 GB/186 GiB) Mar 27 20:18:06 linux-7vph kernel: sd 0:0:0:0: [sda] Write Protect is off Mar 27 20:18:06 linux-7vph kernel: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00 Mar 27 20:18:06 linux-7vph kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA Mar 27 20:18:06 linux-7vph kernel: ata2.00: ACPI cmd e3/00:1f:00:00:00:a0 succeeded Mar 27 20:18:06 linux-7vph kernel: ata2.00: ACPI cmd e3/00:02:00:00:00:a0 succeeded Mar 27 20:18:06 linux-7vph kernel: ata2.00: configured for UDMA/133 Mar 27 20:18:06 linux-7vph kernel: ata2: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0x9 t4 Mar 27 20:18:06 linux-7vph kernel: ata2: irq_stat 0x40000001 Mar 27 20:18:06 linux-7vph kernel: ata2.00: configured for UDMA/133 Mar 27 20:18:06 linux-7vph kernel: ata2: EH complete Mar 27 20:18:06 linux-7vph kernel: pci 0000:00:02.0: power state changed by ACPI to D0 Mar 27 20:18:06 linux-7vph kernel: pci 0000:00:02.0: setting latency timer to 64 Mar 27 20:18:06 linux-7vph kernel: Restarting tasks ... done. ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 2.6.29 regression: ATA bus errors on resume 2009-03-27 19:10 ` 2.6.29 regression: ATA bus errors on resume Niel Lambrechts @ 2009-03-27 22:30 ` Arjan van de Ven 2009-03-28 10:22 ` Niel Lambrechts 2009-03-30 8:55 ` Tejun Heo 1 sibling, 1 reply; 9+ messages in thread From: Arjan van de Ven @ 2009-03-27 22:30 UTC (permalink / raw) To: Niel Lambrechts Cc: linux.kernel, James Bottomley, Pavel Machek, Rafael J. Wysocki, Linux IDE mailing list, Jeff Garzik On Fri, 27 Mar 2009 21:10:52 +0200 Niel Lambrechts <niel.lambrechts@gmail.com> wrote: > I'm seeing some dubious looking ATA messages even on 2.6.28.9-pae, > although with all the 2.6.28 variants I used s2disk/resume has always > worked. I was wondering if these "errors" perhaps play more of a role > in 2.6.29, perhaps due to the async. changes that was mentioned? unless you actively enabled this via a kernel command line option there are no async changes in 2.6.29 in terms of behavior. -- Arjan van de Ven Intel Open Source Technology Centre For development, discussion and tips for power savings, visit http://www.lesswatts.org ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 2.6.29 regression: ATA bus errors on resume 2009-03-27 22:30 ` Arjan van de Ven @ 2009-03-28 10:22 ` Niel Lambrechts 2009-03-28 14:06 ` Rafael J. Wysocki 0 siblings, 1 reply; 9+ messages in thread From: Niel Lambrechts @ 2009-03-28 10:22 UTC (permalink / raw) To: Arjan van de Ven Cc: linux.kernel, James Bottomley, Pavel Machek, Rafael J. Wysocki, Linux IDE mailing list, Jeff Garzik On 03/28/2009 12:30 AM, Arjan van de Ven wrote: > On Fri, 27 Mar 2009 21:10:52 +0200 > Niel Lambrechts <niel.lambrechts@gmail.com> wrote: > > >> I'm seeing some dubious looking ATA messages even on 2.6.28.9-pae, >> although with all the 2.6.28 variants I used s2disk/resume has always >> worked. I was wondering if these "errors" perhaps play more of a role >> in 2.6.29, perhaps due to the async. changes that was mentioned? >> > > unless you actively enabled this via a kernel command line option there > are no async changes in 2.6.29 in terms of behavior. > > > The only non-default option I had was 'modeset=1'. From Jeff's earlier comment I understood the probing behaviour changed. The fundamental difference is that in 2.6.29 everything initially seems okay, but then there is a ata1.00: exception Emask 0x10 SAct 0x3f SErr 0x50000 action0xe frozen ata1.00: irq_stat 0x00400008, PHY RDY changed There's nothing frozen it 2.6.28. Should I log a kernel bug, what's the best way forward and is there anything more I can do to help? cheers Niel ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 2.6.29 regression: ATA bus errors on resume 2009-03-28 10:22 ` Niel Lambrechts @ 2009-03-28 14:06 ` Rafael J. Wysocki 2009-03-30 8:43 ` Tejun Heo 0 siblings, 1 reply; 9+ messages in thread From: Rafael J. Wysocki @ 2009-03-28 14:06 UTC (permalink / raw) To: Niel Lambrechts Cc: Arjan van de Ven, linux.kernel, James Bottomley, Pavel Machek, Linux IDE mailing list, Jeff Garzik, Tejun Heo On Saturday 28 March 2009, Niel Lambrechts wrote: > On 03/28/2009 12:30 AM, Arjan van de Ven wrote: > > On Fri, 27 Mar 2009 21:10:52 +0200 > > Niel Lambrechts <niel.lambrechts@gmail.com> wrote: > > > > > >> I'm seeing some dubious looking ATA messages even on 2.6.28.9-pae, > >> although with all the 2.6.28 variants I used s2disk/resume has always > >> worked. I was wondering if these "errors" perhaps play more of a role > >> in 2.6.29, perhaps due to the async. changes that was mentioned? > >> > > > > unless you actively enabled this via a kernel command line option there > > are no async changes in 2.6.29 in terms of behavior. > > > > > > > The only non-default option I had was 'modeset=1'. From Jeff's earlier > comment I understood the probing behaviour changed. > > The fundamental difference is that in 2.6.29 everything initially seems > okay, but then there is a > ata1.00: exception Emask 0x10 SAct 0x3f SErr 0x50000 action0xe frozen > ata1.00: irq_stat 0x00400008, PHY RDY changed > > There's nothing frozen it 2.6.28. > > Should I log a kernel bug, what's the best way forward and is there > anything more I can do to help? Let Tejun have a look a this, perhaps? Rafael ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 2.6.29 regression: ATA bus errors on resume 2009-03-28 14:06 ` Rafael J. Wysocki @ 2009-03-30 8:43 ` Tejun Heo 0 siblings, 0 replies; 9+ messages in thread From: Tejun Heo @ 2009-03-30 8:43 UTC (permalink / raw) To: Rafael J. Wysocki Cc: Niel Lambrechts, Arjan van de Ven, linux.kernel, James Bottomley, Pavel Machek, Linux IDE mailing list, Jeff Garzik Hello, Rafael J. Wysocki wrote: > On Saturday 28 March 2009, Niel Lambrechts wrote: >> On 03/28/2009 12:30 AM, Arjan van de Ven wrote: >>> On Fri, 27 Mar 2009 21:10:52 +0200 >>> Niel Lambrechts <niel.lambrechts@gmail.com> wrote: >>> >>> >>>> I'm seeing some dubious looking ATA messages even on 2.6.28.9-pae, >>>> although with all the 2.6.28 variants I used s2disk/resume has always >>>> worked. I was wondering if these "errors" perhaps play more of a role >>>> in 2.6.29, perhaps due to the async. changes that was mentioned? >>>> >>> unless you actively enabled this via a kernel command line option there >>> are no async changes in 2.6.29 in terms of behavior. >>> >>> >>> >> The only non-default option I had was 'modeset=1'. From Jeff's earlier >> comment I understood the probing behaviour changed. >> >> The fundamental difference is that in 2.6.29 everything initially seems >> okay, but then there is a >> ata1.00: exception Emask 0x10 SAct 0x3f SErr 0x50000 action0xe frozen >> ata1.00: irq_stat 0x00400008, PHY RDY changed >> >> There's nothing frozen it 2.6.28. >> >> Should I log a kernel bug, what's the best way forward and is there >> anything more I can do to help? > > Let Tejun have a look a this, perhaps? What Niel is seeing is probably caused by libata EH somehow moving forward too fast and receiving the second PHY changed event after the initial reset is complete. That or the thaw routine is broken and doesn't clear hotplug event properly. Actually, this double reset seems to happen quite often, so it might be about time to drill it down and find out what's really going on. But, generally, it isn't a serious problem, all that happens is EH doing another round. The original one looks quite serious tho. I'll reply separately. Thanks. -- tejun ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 2.6.29 regression: ATA bus errors on resume 2009-03-27 19:10 ` 2.6.29 regression: ATA bus errors on resume Niel Lambrechts 2009-03-27 22:30 ` Arjan van de Ven @ 2009-03-30 8:55 ` Tejun Heo 1 sibling, 0 replies; 9+ messages in thread From: Tejun Heo @ 2009-03-30 8:55 UTC (permalink / raw) To: Niel Lambrechts Cc: linux.kernel, James Bottomley, Pavel Machek, Rafael J. Wysocki, Linux IDE mailing list, Arjan van de Ven, Jeff Garzik Hello, For some reason, I can't find the original thread, so replying here. Niel Lambrechts wrote: >>>>> The ext4 errors are interleaved with hardware errors, and the ext4 >>>>> errors are about I/O errors. >>>>> >>>>> EXT4-fs error (device sda6): __ext4_get_inode_loc: unable to read inode block - inode=2346519 >>>>> EXT4-fs error (device sda6) in ext4_reserve_inode_write: IO failure >>>>> >>>>> This looks more like a hibernation problem than an ext4 problem. >>>>> Looks like the hard drive is being left in some inconsistent state >>>>> after resuming from hibernation. Yeap, ext4 is just the victim here. >>>> ata1.00: irq_stat 0x00400008, PHY RDY changed >>>> ata1: SError: { PHYRdyChg CommWake } >>> Your SATA hardware flags a connect-or-disconnect event ("PHY RDY"), >>> which requires us to abort a bunch of queued commands: >>> >>>> ata1.00: cmd 60/18:00:77:88:6f/00:00:0e:00:00/40 tag 0 ncq 12288 in >>>> res 50/00:30:07:b3:10/00:00:0c:00:00/40 Emask 0x10 (ATA bus error) >>> [...] ... >>> The SCSI subsystem aborts each of the queued commands. >> No .. this is the SCSI subsystem receives an ABORTED COMMAND return in >> sense data for each of the outstanding I/Os >> >> The only place these are generated is in ata_sense_to_error() which only >> occurs if there's some type of ata error. >> >> If I had to theorise, I'd say the system suspended with commands >> outstanding to the device. On resume, the device gets reset and returns >> some type of ATA error which gets translated to ABORTED COMMAND which >> causes a failure. >> >> In the mid layer, we translate ABORTED_COMMAND into a retry until the >> command runs out of them ... could it be there's a race readying the >> device and we run through the retries before it can accept the command? When libata-eh thinks that the problem isn't worth retrying, it sets scmd->retries to scmd->allowed so that it gets aborted immediately. The code is in ata_eh_qc_complete(). Whether a command is to be retried or not is determined with ATA_QCFLAG_RETRY which is set in ata_eh_link_autopsy() for each failed command. Immediate-failure criteria is pretty strict - only driver software errors (AC_ERR_INVALID) and PC or other special commands which failed which got aborted by the device get the immediate pink slip. In this case, the commands are from FS and failed with AC_ERR_ATA_BUS, so it definitely doesn't fit into the criteria. Strange. How reproducible is the problem? Are you interested in trying out some debug patches? Thanks. -- tejun ^ permalink raw reply [flat|nested] 9+ messages in thread
[parent not found: <cjlqb-7sp-1@gated-at.bofh.it>]
[parent not found: <cjq6y-6sq-11@gated-at.bofh.it>]
[parent not found: <49C9BEC8.9020403@devnull.org>]
* Re: 2.6.29 regression: ATA bus errors on resume [not found] ` <49C9BEC8.9020403@devnull.org> @ 2009-03-25 6:06 ` Jeff Garzik 2009-03-25 21:40 ` Niel Lambrechts 2009-03-25 22:16 ` James Bottomley 0 siblings, 2 replies; 9+ messages in thread From: Jeff Garzik @ 2009-03-25 6:06 UTC (permalink / raw) To: Niel Lambrechts Cc: linux.kernel, Linux IDE mailing list, Arjan van de Ven, Rafael J. Wysocki, linux-scsi Niel Lambrechts wrote: > On 03/25/2009 03:30 AM, Theodore Tso wrote: >> On Tue, Mar 24, 2009 at 10:25:57PM +0200, Niel Lambrechts wrote: >>> Hi, >>> >>> After upgrading to 2.6.29 I get the below errors after resuming from >>> hibernating with s2disk. I ran fsck and tried doing the same thing again >>> in 2.6.28.9-pae, but do not get any errors there. >> The ext4 errors are interleaved with hardware errors, and the ext4 >> errors are about I/O errors. >> >> EXT4-fs error (device sda6): __ext4_get_inode_loc: unable to read inode block - inode=2346519 >> EXT4-fs error (device sda6) in ext4_reserve_inode_write: IO failure >> >> This looks more like a hibernation problem than an ext4 problem. >> Looks like the hard drive is being left in some inconsistent state >> after resuming from hibernation. >> >> - Ted > > Thanks for the info Theodore, this is definitely looks like some type of > regression in 2.6.29, as the problem is not evident when I s2disk using > 2.6.28.9, even after multiple suspend/resume cycles. > > I found some 'ATA bus errors' and 'SError' messages in > /var/log/messages, so I've attached the messages from both 2.6.29 and > 2.6.28 for comparison. Well, here is the interpretation of messages: > ata1.00: irq_stat 0x00400008, PHY RDY changed > ata1: SError: { PHYRdyChg CommWake } Your SATA hardware flags a connect-or-disconnect event ("PHY RDY"), which requires us to abort a bunch of queued commands: > ata1.00: cmd 60/18:00:77:88:6f/00:00:0e:00:00/40 tag 0 ncq 12288 in > res 50/00:30:07:b3:10/00:00:0c:00:00/40 Emask 0x10 (ATA bus error) [...] > ata1.00: cmd 60/30:68:07:b3:10/00:00:0c:00:00/40 tag 13 ncq 24576 in > res 50/00:30:07:b3:10/00:00:0c:00:00/40 Emask 0x10 (ATA bus error) ...through the 14th command (tag 13). > Mar 24 21:29:14 linux-7vph kernel: ata1: hard resetting link > Mar 24 21:29:14 linux-7vph kernel: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300) > Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 succeeded > Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 filtered out > Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 succeeded > Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 filtered out > Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 succeeded > Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 filtered out > Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 succeeded > Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 filtered out > Mar 24 21:29:14 linux-7vph kernel: ata1.00: configured for UDMA/133 > Mar 24 21:29:14 linux-7vph kernel: ata1.00: configured for UDMA/133 SATA link is reset, and ACPI is re-run. > Mar 24 21:29:14 linux-7vph kernel: sd 0:0:0:0: [sda] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE,SUGGEST_OK > Mar 24 21:29:14 linux-7vph kernel: sd 0:0:0:0: [sda] Sense Key : Aborted Command [current] [descriptor] > Mar 24 21:29:14 linux-7vph kernel: Descriptor sense data with sense descriptors (in hex): > Mar 24 21:29:14 linux-7vph kernel: 72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00 > Mar 24 21:29:14 linux-7vph kernel: 0c 10 b3 07 > Mar 24 21:29:14 linux-7vph kernel: sd 0:0:0:0: [sda] Add. Sense: No additional sense information > Mar 24 21:29:14 linux-7vph kernel: end_request: I/O error, dev sda, sector 242190455 The SCSI subsystem aborts each of the queued commands. > Mar 24 21:29:14 linux-7vph kernel: ata1: EH complete SATA error handling completes > Mar 24 21:29:14 linux-7vph kernel: EXT4-fs error (device sda6): __ext4_get_inode_loc: unable to read inode block - inode=2330178, block=9338883 ext4 pukes, because of SATA/SCSI errors > Mar 24 21:29:14 linux-7vph kernel: sd 0:0:0:0: [sda] 390721968 512-byte hardware sectors: (200 GB/186 GiB) > Mar 24 21:29:14 linux-7vph kernel: sd 0:0:0:0: [sda] Write Protect is off > Mar 24 21:29:14 linux-7vph kernel: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00 > Mar 24 21:29:14 linux-7vph kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA > Mar 24 21:29:14 linux-7vph kernel: sd 0:0:0:0: [sda] 390721968 512-byte hardware sectors: (200 GB/186 GiB) > Mar 24 21:29:14 linux-7vph kernel: sd 0:0:0:0: [sda] Write Protect is off > Mar 24 21:29:14 linux-7vph kernel: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00 > Mar 24 21:29:14 linux-7vph kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA SCSI finished re-initialization. So from this, a few observations and open questions: Why didn't these SCSI commands get retried? Were they left over from prior to resume? Did SCSI error out the commands too soon? The probing is not complete until AFTER the sector errors, I note. Did the system resume before ACPI resume and SCSI resume completed? It sure looks that way, from the log. Does the asynchronous probing play a role here? Jeff ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 2.6.29 regression: ATA bus errors on resume 2009-03-25 6:06 ` Jeff Garzik @ 2009-03-25 21:40 ` Niel Lambrechts 2009-03-25 22:16 ` James Bottomley 1 sibling, 0 replies; 9+ messages in thread From: Niel Lambrechts @ 2009-03-25 21:40 UTC (permalink / raw) To: Jeff Garzik Cc: linux.kernel, Linux IDE mailing list, Arjan van de Ven, Rafael J. Wysocki, linux-scsi [-- Attachment #1: Type: text/plain, Size: 1177 bytes --] On 03/25/2009 08:06 AM, Jeff Garzik wrote: > > So from this, a few observations and open questions: > > Why didn't these SCSI commands get retried? > > Were they left over from prior to resume? > > Did SCSI error out the commands too soon? The probing is not complete > until AFTER the sector errors, I note. > > Did the system resume before ACPI resume and SCSI resume completed? > It sure looks that way, from the log. > > Does the asynchronous probing play a role here? It looks like there are a few different scenarios in what could happen: I had another go at hibernating on 2.6.29 running with and without X, and this time round it resumed with a *clean* file-system. Without X, it looked to be better off as there were not even any ATA errors logged, but I'm not sure if this is just because of the system being almost entirely idle. Going on your comments of earlier, when hibernating in X it looks like this time the SCSI initialization completes normally before any errors, being 'ATA bus error' messages for a while until a hard reset occurs. I've attached the messages from both, hopefully this gives someone more of a clue of what is happening. cheers Niel [-- Attachment #2: hibernate-x.txt --] [-- Type: text/plain, Size: 17374 bytes --] Mar 25 20:04:27 linux-7vph kernel: [drm:gm45_get_vblank_counter] *ERROR* trying to get vblank count for disabled pipe 0 Mar 25 20:05:32 linux-7vph kernel: Syncing filesystems ... done. Mar 25 20:05:32 linux-7vph kernel: Freezing user space processes ... (elapsed 0.00 seconds) done. Mar 25 20:05:32 linux-7vph kernel: Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done. Mar 25 20:05:32 linux-7vph kernel: PM: Shrinking memory... done (49943 pages freed) Mar 25 20:05:32 linux-7vph kernel: PM: Freed 199772 kbytes in 1.05 seconds (190.25 MB/s) Mar 25 20:05:32 linux-7vph kernel: Suspending console(s) (use no_console_suspend to debug) Mar 25 20:05:32 linux-7vph kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache Mar 25 20:05:32 linux-7vph kernel: ACPI handle has no context! Mar 25 20:05:32 linux-7vph kernel: iwlagn 0000:03:00.0: PCI INT A disabled Mar 25 20:05:32 linux-7vph kernel: ehci_hcd 0000:00:1d.7: PCI INT D disabled Mar 25 20:05:32 linux-7vph kernel: ehci_hcd 0000:00:1d.7: PME# disabled Mar 25 20:05:32 linux-7vph kernel: uhci_hcd 0000:00:1d.2: PCI INT C disabled Mar 25 20:05:35 linux-7vph kernel: uhci_hcd 0000:00:1d.1: PCI INT B disabled Mar 25 20:05:35 linux-7vph kernel: uhci_hcd 0000:00:1d.0: PCI INT A disabled Mar 25 20:05:35 linux-7vph kernel: HDA Intel 0000:00:1b.0: PCI INT B disabled Mar 25 20:05:36 linux-7vph kernel: ehci_hcd 0000:00:1a.7: PCI INT D disabled Mar 25 20:05:36 linux-7vph kernel: ehci_hcd 0000:00:1a.7: PME# disabled Mar 25 20:05:36 linux-7vph kernel: uhci_hcd 0000:00:1a.2: PCI INT C disabled Mar 25 20:05:36 linux-7vph kernel: uhci_hcd 0000:00:1a.1: PCI INT B disabled Mar 25 20:05:36 linux-7vph kernel: uhci_hcd 0000:00:1a.0: PCI INT A disabled Mar 25 20:05:36 linux-7vph kernel: e1000e 0000:00:19.0: PME# enabled Mar 25 20:05:36 linux-7vph kernel: e1000e 0000:00:19.0: wake-up capability enabled by ACPI Mar 25 20:05:36 linux-7vph kernel: e1000e 0000:00:19.0: PME# enabled Mar 25 20:05:36 linux-7vph kernel: e1000e 0000:00:19.0: wake-up capability enabled by ACPI Mar 25 20:05:36 linux-7vph kernel: e1000e 0000:00:19.0: PCI INT A disabled Mar 25 20:05:36 linux-7vph kernel: ACPI: Preparing to enter system sleep state S4 Mar 25 20:05:36 linux-7vph kernel: PM: Saving platform NVS memory Mar 25 20:05:36 linux-7vph kernel: Disabling non-boot CPUs ... Mar 25 20:05:36 linux-7vph kernel: CPU 1 is now offline Mar 25 20:05:36 linux-7vph kernel: SMP alternatives: switching to UP code Mar 25 20:05:36 linux-7vph kernel: CPU0 attaching NULL sched-domain. Mar 25 20:05:36 linux-7vph kernel: CPU1 attaching NULL sched-domain. Mar 25 20:05:36 linux-7vph kernel: CPU0 attaching NULL sched-domain. Mar 25 20:05:36 linux-7vph kernel: CPU1 is down Mar 25 20:05:36 linux-7vph kernel: Extended CMOS year: 2000 Mar 25 20:05:36 linux-7vph kernel: PM: Creating hibernation image: Mar 25 20:05:36 linux-7vph kernel: PM: Need to copy 125019 pages Mar 25 20:05:36 linux-7vph kernel: x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106 Mar 25 20:05:36 linux-7vph kernel: Intel machine check architecture supported. Mar 25 20:05:36 linux-7vph kernel: Intel machine check reporting enabled on CPU#0. Mar 25 20:05:36 linux-7vph kernel: PM: Restoring platform NVS memory Mar 25 20:05:36 linux-7vph kernel: Extended CMOS year: 2000 Mar 25 20:05:36 linux-7vph kernel: pci 0000:00:02.0: restoring config space at offset 0x1 (was 0x900007, writing 0x900403) Mar 25 20:05:36 linux-7vph kernel: HDA Intel 0000:00:1b.0: restoring config space at offset 0x1 (was 0x100106, writing 0x100102) Mar 25 20:05:36 linux-7vph kernel: ahci 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b00403, writing 0x2b00407) Mar 25 20:05:36 linux-7vph kernel: Enabling non-boot CPUs ... Mar 25 20:05:36 linux-7vph kernel: SMP alternatives: switching to SMP code Mar 25 20:05:36 linux-7vph kernel: Booting processor 1 APIC 0x1 ip 0x6000 Mar 25 20:05:36 linux-7vph kernel: Initializing CPU#1 Mar 25 20:05:36 linux-7vph kernel: Calibrating delay using timer specific routine.. 5054.04 BogoMIPS (lpj=10108098) Mar 25 20:05:36 linux-7vph kernel: CPU: L1 I cache: 32K, L1 D cache: 32K Mar 25 20:05:36 linux-7vph kernel: CPU: L2 cache: 6144K Mar 25 20:05:36 linux-7vph kernel: [ds] using Core 2/Atom configuration Mar 25 20:05:36 linux-7vph kernel: CPU: Physical Processor ID: 0 Mar 25 20:05:36 linux-7vph kernel: CPU: Processor Core ID: 1 Mar 25 20:05:36 linux-7vph kernel: Intel machine check architecture supported. Mar 25 20:05:36 linux-7vph kernel: Intel machine check reporting enabled on CPU#1. Mar 25 20:05:36 linux-7vph kernel: x86 PAT enabled: cpu 1, old 0x7040600070406, new 0x7010600070106 Mar 25 20:05:36 linux-7vph kernel: CPU1: Intel(R) Core(TM)2 Duo CPU T9400 @ 2.53GHz stepping 06 Mar 25 20:05:36 linux-7vph kernel: CPU0 attaching NULL sched-domain. Mar 25 20:05:36 linux-7vph kernel: Switched to high resolution mode on CPU 1 Mar 25 20:05:36 linux-7vph kernel: CPU0 attaching sched-domain: Mar 25 20:05:36 linux-7vph kernel: domain 0: span 0-1 level MC Mar 25 20:05:36 linux-7vph kernel: groups: 0 1 Mar 25 20:05:36 linux-7vph kernel: domain 1: span 0-1 level CPU Mar 25 20:05:36 linux-7vph kernel: groups: 0-1 Mar 25 20:05:36 linux-7vph kernel: CPU1 attaching sched-domain: Mar 25 20:05:36 linux-7vph kernel: domain 0: span 0-1 level MC Mar 25 20:05:36 linux-7vph kernel: groups: 1 0 Mar 25 20:05:36 linux-7vph kernel: domain 1: span 0-1 level CPU Mar 25 20:05:36 linux-7vph kernel: groups: 0-1 Mar 25 20:05:36 linux-7vph kernel: CPU1 is up Mar 25 20:05:36 linux-7vph kernel: ACPI: Waking up from system sleep state S4 Mar 25 20:05:36 linux-7vph kernel: ACPI: EC: non-query interrupt received, switching to interrupt mode Mar 25 20:05:36 linux-7vph kernel: pci 0000:00:02.0: PME# disabled Mar 25 20:05:36 linux-7vph kernel: pci 0000:00:02.0: power state changed by ACPI to D0 Mar 25 20:05:36 linux-7vph kernel: pci 0000:00:02.0: setting latency timer to 64 Mar 25 20:05:36 linux-7vph kernel: pci 0000:00:02.1: PME# disabled Mar 25 20:05:36 linux-7vph kernel: pci 0000:00:03.0: PME# disabled Mar 25 20:05:36 linux-7vph kernel: e1000e 0000:00:19.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20 Mar 25 20:05:36 linux-7vph kernel: e1000e 0000:00:19.0: setting latency timer to 64 Mar 25 20:05:36 linux-7vph kernel: e1000e 0000:00:19.0: wake-up capability disabled by ACPI Mar 25 20:05:36 linux-7vph kernel: e1000e 0000:00:19.0: PME# disabled Mar 25 20:05:36 linux-7vph kernel: e1000e 0000:00:19.0: wake-up capability disabled by ACPI Mar 25 20:05:36 linux-7vph kernel: e1000e 0000:00:19.0: PME# disabled Mar 25 20:05:36 linux-7vph kernel: e1000e 0000:00:19.0: irq 29 for MSI/MSI-X Mar 25 20:05:36 linux-7vph kernel: uhci_hcd 0000:00:1a.0: power state changed by ACPI to D0 Mar 25 20:05:36 linux-7vph kernel: uhci_hcd 0000:00:1a.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20 Mar 25 20:05:36 linux-7vph kernel: uhci_hcd 0000:00:1a.0: setting latency timer to 64 Mar 25 20:05:36 linux-7vph kernel: uhci_hcd 0000:00:1a.1: PCI INT B -> GSI 21 (level, low) -> IRQ 21 Mar 25 20:05:36 linux-7vph kernel: uhci_hcd 0000:00:1a.1: setting latency timer to 64 Mar 25 20:05:36 linux-7vph kernel: uhci_hcd 0000:00:1a.2: power state changed by ACPI to D0 Mar 25 20:05:36 linux-7vph kernel: uhci_hcd 0000:00:1a.2: PCI INT C -> GSI 22 (level, low) -> IRQ 22 Mar 25 20:05:36 linux-7vph kernel: uhci_hcd 0000:00:1a.2: setting latency timer to 64 Mar 25 20:05:36 linux-7vph kernel: ehci_hcd 0000:00:1a.7: PME# disabled Mar 25 20:05:36 linux-7vph kernel: ehci_hcd 0000:00:1a.7: power state changed by ACPI to D0 Mar 25 20:05:36 linux-7vph kernel: ehci_hcd 0000:00:1a.7: PCI INT D -> GSI 23 (level, low) -> IRQ 23 Mar 25 20:05:36 linux-7vph kernel: ehci_hcd 0000:00:1a.7: setting latency timer to 64 Mar 25 20:05:36 linux-7vph kernel: ehci_hcd 0000:00:1a.7: PME# disabled Mar 25 20:05:36 linux-7vph kernel: HDA Intel 0000:00:1b.0: PCI INT B -> GSI 17 (level, low) -> IRQ 17 Mar 25 20:05:36 linux-7vph kernel: HDA Intel 0000:00:1b.0: setting latency timer to 64 Mar 25 20:05:36 linux-7vph kernel: pcieport-driver 0000:00:1c.0: setting latency timer to 64 Mar 25 20:05:36 linux-7vph kernel: pcieport-driver 0000:00:1c.1: setting latency timer to 64 Mar 25 20:05:36 linux-7vph kernel: pcieport-driver 0000:00:1c.3: setting latency timer to 64 Mar 25 20:05:36 linux-7vph kernel: pcieport-driver 0000:00:1c.4: setting latency timer to 64 Mar 25 20:05:36 linux-7vph kernel: uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0 Mar 25 20:05:36 linux-7vph kernel: uhci_hcd 0000:00:1d.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16 Mar 25 20:05:36 linux-7vph kernel: uhci_hcd 0000:00:1d.0: setting latency timer to 64 Mar 25 20:05:36 linux-7vph kernel: uhci_hcd 0000:00:1d.1: PCI INT B -> GSI 17 (level, low) -> IRQ 17 Mar 25 20:05:36 linux-7vph kernel: uhci_hcd 0000:00:1d.1: setting latency timer to 64 Mar 25 20:05:36 linux-7vph kernel: uhci_hcd 0000:00:1d.2: PCI INT C -> GSI 18 (level, low) -> IRQ 18 Mar 25 20:05:36 linux-7vph kernel: uhci_hcd 0000:00:1d.2: setting latency timer to 64 Mar 25 20:05:36 linux-7vph kernel: ehci_hcd 0000:00:1d.7: PME# disabled Mar 25 20:05:36 linux-7vph kernel: ehci_hcd 0000:00:1d.7: power state changed by ACPI to D0 Mar 25 20:05:36 linux-7vph kernel: ehci_hcd 0000:00:1d.7: PCI INT D -> GSI 19 (level, low) -> IRQ 19 Mar 25 20:05:36 linux-7vph kernel: ehci_hcd 0000:00:1d.7: setting latency timer to 64 Mar 25 20:05:36 linux-7vph kernel: ehci_hcd 0000:00:1d.7: PME# disabled Mar 25 20:05:36 linux-7vph kernel: pci 0000:00:1e.0: setting latency timer to 64 Mar 25 20:05:36 linux-7vph kernel: ahci 0000:00:1f.2: setting latency timer to 64 Mar 25 20:05:36 linux-7vph kernel: iwlagn 0000:03:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17 Mar 25 20:05:36 linux-7vph kernel: iwlagn 0000:03:00.0: irq 30 for MSI/MSI-X Mar 25 20:05:36 linux-7vph kernel: pci 0000:15:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16 Mar 25 20:05:36 linux-7vph kernel: Registered led device: iwl-phy0:radio Mar 25 20:05:36 linux-7vph kernel: Registered led device: iwl-phy0:assoc Mar 25 20:05:36 linux-7vph kernel: Registered led device: iwl-phy0:RX Mar 25 20:05:36 linux-7vph kernel: Registered led device: iwl-phy0:TX Mar 25 20:05:36 linux-7vph kernel: ohci1394: fw-host0: OHCI-1394 1.1 (PCI): IRQ=[17] MMIO=[f4801000-f48017ff] Max Packet=[2048] IR/IT contexts=[4/4] Mar 25 20:05:36 linux-7vph kernel: pci 0000:15:00.2: PME# disabled Mar 25 20:05:36 linux-7vph kernel: pci 0000:15:00.3: PME# disabled Mar 25 20:05:36 linux-7vph kernel: pci 0000:15:00.4: PME# disabled Mar 25 20:05:36 linux-7vph kernel: pci 0000:15:00.5: PME# disabled Mar 25 20:05:36 linux-7vph kernel: sd 0:0:0:0: [sda] Starting disk Mar 25 20:05:36 linux-7vph kernel: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300) Mar 25 20:05:36 linux-7vph kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300) Mar 25 20:05:36 linux-7vph kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 succeeded Mar 25 20:05:36 linux-7vph kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 filtered out Mar 25 20:05:36 linux-7vph kernel: ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 succeeded Mar 25 20:05:36 linux-7vph kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 filtered out Mar 25 20:05:36 linux-7vph kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 succeeded Mar 25 20:05:36 linux-7vph kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 filtered out Mar 25 20:05:36 linux-7vph kernel: ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 succeeded Mar 25 20:05:36 linux-7vph kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 filtered out Mar 25 20:05:36 linux-7vph kernel: ata1.00: configured for UDMA/133 Mar 25 20:05:36 linux-7vph kernel: ata1: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0x9 t4 Mar 25 20:05:36 linux-7vph kernel: ata1: irq_stat 0x00400040, connection status changed Mar 25 20:05:36 linux-7vph kernel: ata1.00: configured for UDMA/133 Mar 25 20:05:36 linux-7vph kernel: ata1: EH complete Mar 25 20:05:36 linux-7vph kernel: sd 0:0:0:0: [sda] 390721968 512-byte hardware sectors: (200 GB/186 GiB) Mar 25 20:05:36 linux-7vph kernel: sd 0:0:0:0: [sda] Write Protect is off Mar 25 20:05:36 linux-7vph kernel: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00 Mar 25 20:05:36 linux-7vph kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA Mar 25 20:05:36 linux-7vph kernel: sd 0:0:0:0: [sda] 390721968 512-byte hardware sectors: (200 GB/186 GiB) Mar 25 20:05:36 linux-7vph kernel: sd 0:0:0:0: [sda] Write Protect is off Mar 25 20:05:36 linux-7vph kernel: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00 Mar 25 20:05:36 linux-7vph kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA Mar 25 20:05:36 linux-7vph kernel: ata2.00: ACPI cmd e3/00:1f:00:00:00:a0 succeeded Mar 25 20:05:36 linux-7vph kernel: ata2.00: ACPI cmd e3/00:02:00:00:00:a0 succeeded Mar 25 20:05:36 linux-7vph kernel: ata2.00: ACPI cmd e3/00:1f:00:00:00:a0 succeeded Mar 25 20:05:36 linux-7vph kernel: ata2.00: ACPI cmd e3/00:02:00:00:00:a0 succeeded Mar 25 20:05:36 linux-7vph kernel: ata2.00: configured for UDMA/133 Mar 25 20:05:36 linux-7vph kernel: pci 0000:00:02.0: power state changed by ACPI to D0 Mar 25 20:05:36 linux-7vph kernel: pci 0000:00:02.0: restoring config space at offset 0x1 (was 0x900407, writing 0x900403) Mar 25 20:05:36 linux-7vph kernel: pci 0000:00:02.0: setting latency timer to 64 Mar 25 20:05:36 linux-7vph kernel: ata2: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0x9 t4 Mar 25 20:05:36 linux-7vph kernel: ata2: irq_stat 0x40000001 Mar 25 20:05:36 linux-7vph kernel: ata2.00: configured for UDMA/133 Mar 25 20:05:36 linux-7vph kernel: ata2: EH complete Mar 25 20:05:36 linux-7vph kernel: Restarting tasks ... done. Mar 25 20:05:36 linux-7vph kernel: ata1.00: exception Emask 0x10 SAct 0x3f SErr 0x50000 action 0xe frozen Mar 25 20:05:36 linux-7vph kernel: ata1.00: irq_stat 0x00400008, PHY RDY changed Mar 25 20:05:36 linux-7vph kernel: ata1: SError: { PHYRdyChg CommWake } Mar 25 20:05:36 linux-7vph kernel: ata1.00: cmd 60/10:00:af:e1:19/00:00:0f:00:00/40 tag 0 ncq 8192 in Mar 25 20:05:36 linux-7vph kernel: res 50/00:40:ff:38:1e/00:00:0d:00:00/40 Emask 0x10 (ATA bus error) Mar 25 20:05:36 linux-7vph kernel: ata1.00: status: { DRDY } Mar 25 20:05:36 linux-7vph kernel: ata1.00: cmd 60/08:08:97:d6:ab/00:00:0e:00:00/40 tag 1 ncq 4096 in Mar 25 20:05:36 linux-7vph kernel: res 50/00:40:ff:38:1e/00:00:0d:00:00/40 Emask 0x10 (ATA bus error) Mar 25 20:05:36 linux-7vph kernel: ata1.00: status: { DRDY } Mar 25 20:05:36 linux-7vph kernel: ata1.00: cmd 60/08:10:17:5a:03/00:00:0b:00:00/40 tag 2 ncq 4096 in Mar 25 20:05:36 linux-7vph kernel: res 50/00:40:ff:38:1e/00:00:0d:00:00/40 Emask 0x10 (ATA bus error) Mar 25 20:05:36 linux-7vph kernel: ata1.00: status: { DRDY } Mar 25 20:05:36 linux-7vph kernel: ata1.00: cmd 60/08:18:a7:38:1e/00:00:0d:00:00/40 tag 3 ncq 4096 in Mar 25 20:05:37 linux-7vph kernel: res 50/00:40:ff:38:1e/00:00:0d:00:00/40 Emask 0x10 (ATA bus error) Mar 25 20:05:37 linux-7vph kernel: ata1.00: status: { DRDY } Mar 25 20:05:37 linux-7vph kernel: ata1.00: cmd 60/08:20:c7:38:1e/00:00:0d:00:00/40 tag 4 ncq 4096 in Mar 25 20:05:37 linux-7vph kernel: res 50/00:40:ff:38:1e/00:00:0d:00:00/40 Emask 0x10 (ATA bus error) Mar 25 20:05:37 linux-7vph kernel: ata1.00: status: { DRDY } Mar 25 20:05:37 linux-7vph kernel: ata1.00: cmd 60/40:28:ff:38:1e/00:00:0d:00:00/40 tag 5 ncq 32768 in Mar 25 20:05:37 linux-7vph kernel: res 50/00:40:ff:38:1e/00:00:0d:00:00/40 Emask 0x10 (ATA bus error) Mar 25 20:05:37 linux-7vph kernel: ata1.00: status: { DRDY } Mar 25 20:05:37 linux-7vph kernel: ata1: hard resetting link Mar 25 20:05:37 linux-7vph kernel: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300) Mar 25 20:05:37 linux-7vph kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 succeeded Mar 25 20:05:37 linux-7vph kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 filtered out Mar 25 20:05:37 linux-7vph kernel: ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 succeeded Mar 25 20:05:37 linux-7vph kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 filtered out Mar 25 20:05:37 linux-7vph kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 succeeded Mar 25 20:05:37 linux-7vph kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 filtered out Mar 25 20:05:37 linux-7vph kernel: ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 succeeded Mar 25 20:05:37 linux-7vph kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 filtered out Mar 25 20:05:37 linux-7vph kernel: ata1.00: configured for UDMA/133 Mar 25 20:05:37 linux-7vph kernel: ata1.00: configured for UDMA/133 Mar 25 20:05:37 linux-7vph kernel: ata1: EH complete Mar 25 20:05:37 linux-7vph kernel: sd 0:0:0:0: [sda] 390721968 512-byte hardware sectors: (200 GB/186 GiB) Mar 25 20:05:37 linux-7vph kernel: sd 0:0:0:0: [sda] Write Protect is off Mar 25 20:05:37 linux-7vph kernel: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00 Mar 25 20:05:37 linux-7vph kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA Mar 25 20:05:37 linux-7vph kernel: sd 0:0:0:0: [sda] 390721968 512-byte hardware sectors: (200 GB/186 GiB) Mar 25 20:05:37 linux-7vph kernel: sd 0:0:0:0: [sda] Write Protect is off Mar 25 20:05:37 linux-7vph kernel: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00 Mar 25 20:05:37 linux-7vph kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [-- Attachment #3: hibernate-console.txt --] [-- Type: text/plain, Size: 12741 bytes --] Mar 25 20:01:51 linux-7vph kernel: Syncing filesystems ... done. Mar 25 20:01:51 linux-7vph kernel: Freezing user space processes ... (elapsed 0.00 seconds) done. Mar 25 20:01:51 linux-7vph kernel: Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done. Mar 25 20:01:51 linux-7vph kernel: PM: Shrinking memory... done (0 pages freed) Mar 25 20:01:51 linux-7vph kernel: PM: Freed 0 kbytes in 0.14 seconds (0.00 MB/s) Mar 25 20:01:51 linux-7vph kernel: Suspending console(s) (use no_console_suspend to debug) Mar 25 20:01:51 linux-7vph kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache Mar 25 20:01:51 linux-7vph kernel: ACPI handle has no context! Mar 25 20:01:51 linux-7vph kernel: iwlagn 0000:03:00.0: PCI INT A disabled Mar 25 20:01:51 linux-7vph kernel: ehci_hcd 0000:00:1d.7: PCI INT D disabled Mar 25 20:01:51 linux-7vph kernel: ehci_hcd 0000:00:1d.7: PME# disabled Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1d.2: PCI INT C disabled Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1d.1: PCI INT B disabled Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1d.0: PCI INT A disabled Mar 25 20:01:51 linux-7vph kernel: HDA Intel 0000:00:1b.0: PCI INT B disabled Mar 25 20:01:51 linux-7vph kernel: ehci_hcd 0000:00:1a.7: PCI INT D disabled Mar 25 20:01:51 linux-7vph kernel: ehci_hcd 0000:00:1a.7: PME# disabled Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1a.2: PCI INT C disabled Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1a.1: PCI INT B disabled Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1a.0: PCI INT A disabled Mar 25 20:01:51 linux-7vph kernel: e1000e 0000:00:19.0: PME# enabled Mar 25 20:01:51 linux-7vph kernel: e1000e 0000:00:19.0: wake-up capability enabled by ACPI Mar 25 20:01:51 linux-7vph kernel: e1000e 0000:00:19.0: PME# enabled Mar 25 20:01:51 linux-7vph kernel: e1000e 0000:00:19.0: wake-up capability enabled by ACPI Mar 25 20:01:51 linux-7vph kernel: e1000e 0000:00:19.0: PCI INT A disabled Mar 25 20:01:51 linux-7vph kernel: ACPI: Preparing to enter system sleep state S4 Mar 25 20:01:51 linux-7vph kernel: PM: Saving platform NVS memory Mar 25 20:01:51 linux-7vph kernel: Disabling non-boot CPUs ... Mar 25 20:01:51 linux-7vph kernel: CPU 1 is now offline Mar 25 20:01:51 linux-7vph kernel: SMP alternatives: switching to UP code Mar 25 20:01:51 linux-7vph kernel: CPU0 attaching NULL sched-domain. Mar 25 20:01:51 linux-7vph kernel: CPU1 attaching NULL sched-domain. Mar 25 20:01:51 linux-7vph kernel: CPU0 attaching NULL sched-domain. Mar 25 20:01:51 linux-7vph kernel: CPU1 is down Mar 25 20:01:51 linux-7vph kernel: Extended CMOS year: 2000 Mar 25 20:01:51 linux-7vph kernel: PM: Creating hibernation image: Mar 25 20:01:51 linux-7vph kernel: PM: Need to copy 37796 pages Mar 25 20:01:51 linux-7vph kernel: x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106 Mar 25 20:01:51 linux-7vph kernel: Intel machine check architecture supported. Mar 25 20:01:51 linux-7vph kernel: Intel machine check reporting enabled on CPU#0. Mar 25 20:01:51 linux-7vph kernel: PM: Restoring platform NVS memory Mar 25 20:01:51 linux-7vph kernel: Extended CMOS year: 2000 Mar 25 20:01:51 linux-7vph kernel: HDA Intel 0000:00:1b.0: restoring config space at offset 0x1 (was 0x100106, writing 0x100102) Mar 25 20:01:51 linux-7vph kernel: ahci 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b00403, writing 0x2b00407) Mar 25 20:01:51 linux-7vph kernel: Enabling non-boot CPUs ... Mar 25 20:01:51 linux-7vph kernel: SMP alternatives: switching to SMP code Mar 25 20:01:51 linux-7vph kernel: Booting processor 1 APIC 0x1 ip 0x6000 Mar 25 20:01:51 linux-7vph kernel: Initializing CPU#1 Mar 25 20:01:51 linux-7vph kernel: Calibrating delay using timer specific routine.. 5054.04 BogoMIPS (lpj=10108082) Mar 25 20:01:51 linux-7vph kernel: CPU: L1 I cache: 32K, L1 D cache: 32K Mar 25 20:01:51 linux-7vph kernel: CPU: L2 cache: 6144K Mar 25 20:01:51 linux-7vph kernel: [ds] using Core 2/Atom configuration Mar 25 20:01:51 linux-7vph kernel: CPU: Physical Processor ID: 0 Mar 25 20:01:51 linux-7vph kernel: CPU: Processor Core ID: 1 Mar 25 20:01:51 linux-7vph kernel: Intel machine check architecture supported. Mar 25 20:01:51 linux-7vph kernel: Intel machine check reporting enabled on CPU#1. Mar 25 20:01:51 linux-7vph kernel: x86 PAT enabled: cpu 1, old 0x7040600070406, new 0x7010600070106 Mar 25 20:01:51 linux-7vph kernel: CPU1: Intel(R) Core(TM)2 Duo CPU T9400 @ 2.53GHz stepping 06 Mar 25 20:01:51 linux-7vph kernel: CPU0 attaching NULL sched-domain. Mar 25 20:01:51 linux-7vph kernel: Switched to high resolution mode on CPU 1 Mar 25 20:01:51 linux-7vph kernel: CPU0 attaching sched-domain: Mar 25 20:01:51 linux-7vph kernel: domain 0: span 0-1 level MC Mar 25 20:01:51 linux-7vph kernel: groups: 0 1 Mar 25 20:01:51 linux-7vph kernel: CPU1 attaching sched-domain: Mar 25 20:01:51 linux-7vph kernel: domain 0: span 0-1 level MC Mar 25 20:01:51 linux-7vph kernel: groups: 1 0 Mar 25 20:01:51 linux-7vph kernel: CPU1 is up Mar 25 20:01:51 linux-7vph kernel: ACPI: Waking up from system sleep state S4 Mar 25 20:01:51 linux-7vph kernel: ACPI: EC: non-query interrupt received, switching to interrupt mode Mar 25 20:01:51 linux-7vph kernel: pci 0000:00:02.0: PME# disabled Mar 25 20:01:51 linux-7vph kernel: pci 0000:00:02.1: PME# disabled Mar 25 20:01:51 linux-7vph kernel: pci 0000:00:03.0: PME# disabled Mar 25 20:01:51 linux-7vph kernel: e1000e 0000:00:19.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20 Mar 25 20:01:51 linux-7vph kernel: e1000e 0000:00:19.0: setting latency timer to 64 Mar 25 20:01:51 linux-7vph kernel: e1000e 0000:00:19.0: wake-up capability disabled by ACPI Mar 25 20:01:51 linux-7vph kernel: e1000e 0000:00:19.0: PME# disabled Mar 25 20:01:51 linux-7vph kernel: e1000e 0000:00:19.0: wake-up capability disabled by ACPI Mar 25 20:01:51 linux-7vph kernel: e1000e 0000:00:19.0: PME# disabled Mar 25 20:01:51 linux-7vph kernel: e1000e 0000:00:19.0: irq 29 for MSI/MSI-X Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1a.0: power state changed by ACPI to D0 Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1a.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20 Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1a.0: setting latency timer to 64 Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1a.1: PCI INT B -> GSI 21 (level, low) -> IRQ 21 Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1a.1: setting latency timer to 64 Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1a.2: power state changed by ACPI to D0 Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1a.2: PCI INT C -> GSI 22 (level, low) -> IRQ 22 Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1a.2: setting latency timer to 64 Mar 25 20:01:51 linux-7vph kernel: ehci_hcd 0000:00:1a.7: PME# disabled Mar 25 20:01:51 linux-7vph kernel: ehci_hcd 0000:00:1a.7: power state changed by ACPI to D0 Mar 25 20:01:51 linux-7vph kernel: ehci_hcd 0000:00:1a.7: PCI INT D -> GSI 23 (level, low) -> IRQ 23 Mar 25 20:01:51 linux-7vph kernel: ehci_hcd 0000:00:1a.7: setting latency timer to 64 Mar 25 20:01:51 linux-7vph kernel: ehci_hcd 0000:00:1a.7: PME# disabled Mar 25 20:01:51 linux-7vph kernel: HDA Intel 0000:00:1b.0: PCI INT B -> GSI 17 (level, low) -> IRQ 17 Mar 25 20:01:51 linux-7vph kernel: HDA Intel 0000:00:1b.0: setting latency timer to 64 Mar 25 20:01:51 linux-7vph kernel: pcieport-driver 0000:00:1c.0: setting latency timer to 64 Mar 25 20:01:51 linux-7vph kernel: pcieport-driver 0000:00:1c.1: setting latency timer to 64 Mar 25 20:01:51 linux-7vph kernel: pcieport-driver 0000:00:1c.3: setting latency timer to 64 Mar 25 20:01:51 linux-7vph kernel: pcieport-driver 0000:00:1c.4: setting latency timer to 64 Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0 Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1d.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16 Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1d.0: setting latency timer to 64 Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1d.1: PCI INT B -> GSI 17 (level, low) -> IRQ 17 Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1d.1: setting latency timer to 64 Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1d.2: PCI INT C -> GSI 18 (level, low) -> IRQ 18 Mar 25 20:01:51 linux-7vph kernel: uhci_hcd 0000:00:1d.2: setting latency timer to 64 Mar 25 20:01:51 linux-7vph kernel: ehci_hcd 0000:00:1d.7: PME# disabled Mar 25 20:01:51 linux-7vph kernel: ehci_hcd 0000:00:1d.7: power state changed by ACPI to D0 Mar 25 20:01:51 linux-7vph kernel: ehci_hcd 0000:00:1d.7: PCI INT D -> GSI 19 (level, low) -> IRQ 19 Mar 25 20:01:51 linux-7vph kernel: ehci_hcd 0000:00:1d.7: setting latency timer to 64 Mar 25 20:01:51 linux-7vph kernel: ehci_hcd 0000:00:1d.7: PME# disabled Mar 25 20:01:51 linux-7vph kernel: pci 0000:00:1e.0: setting latency timer to 64 Mar 25 20:01:51 linux-7vph kernel: ahci 0000:00:1f.2: setting latency timer to 64 Mar 25 20:01:51 linux-7vph kernel: iwlagn 0000:03:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17 Mar 25 20:01:51 linux-7vph kernel: iwlagn 0000:03:00.0: irq 30 for MSI/MSI-X Mar 25 20:01:51 linux-7vph kernel: pci 0000:15:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16 Mar 25 20:01:51 linux-7vph kernel: Registered led device: iwl-phy0:radio Mar 25 20:01:51 linux-7vph kernel: Registered led device: iwl-phy0:assoc Mar 25 20:01:51 linux-7vph kernel: Registered led device: iwl-phy0:RX Mar 25 20:01:51 linux-7vph kernel: Registered led device: iwl-phy0:TX Mar 25 20:01:51 linux-7vph kernel: ohci1394: fw-host0: OHCI-1394 1.1 (PCI): IRQ=[17] MMIO=[f4801000-f48017ff] Max Packet=[2048] IR/IT contexts=[4/4] Mar 25 20:01:51 linux-7vph kernel: pci 0000:15:00.2: PME# disabled Mar 25 20:01:51 linux-7vph kernel: pci 0000:15:00.3: PME# disabled Mar 25 20:01:51 linux-7vph kernel: pci 0000:15:00.4: PME# disabled Mar 25 20:01:51 linux-7vph kernel: pci 0000:15:00.5: PME# disabled Mar 25 20:01:51 linux-7vph kernel: sd 0:0:0:0: [sda] Starting disk Mar 25 20:01:51 linux-7vph kernel: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300) Mar 25 20:01:51 linux-7vph kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300) Mar 25 20:01:51 linux-7vph kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 succeeded Mar 25 20:01:51 linux-7vph kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 filtered out Mar 25 20:01:51 linux-7vph kernel: ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 succeeded Mar 25 20:01:51 linux-7vph kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 filtered out Mar 25 20:01:51 linux-7vph kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 succeeded Mar 25 20:01:51 linux-7vph kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 filtered out Mar 25 20:01:51 linux-7vph kernel: ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 succeeded Mar 25 20:01:51 linux-7vph kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 filtered out Mar 25 20:01:51 linux-7vph kernel: ata1.00: configured for UDMA/133 Mar 25 20:01:51 linux-7vph kernel: ata1: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0x9 t4 Mar 25 20:01:51 linux-7vph kernel: ata1: irq_stat 0x00400040, connection status changed Mar 25 20:01:51 linux-7vph kernel: ata1.00: configured for UDMA/133 Mar 25 20:01:51 linux-7vph kernel: ata1: EH complete Mar 25 20:01:51 linux-7vph kernel: sd 0:0:0:0: [sda] 390721968 512-byte hardware sectors: (200 GB/186 GiB) Mar 25 20:01:51 linux-7vph kernel: sd 0:0:0:0: [sda] Write Protect is off Mar 25 20:01:51 linux-7vph kernel: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00 Mar 25 20:01:51 linux-7vph kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA Mar 25 20:01:51 linux-7vph kernel: sd 0:0:0:0: [sda] 390721968 512-byte hardware sectors: (200 GB/186 GiB) Mar 25 20:01:51 linux-7vph kernel: sd 0:0:0:0: [sda] Write Protect is off Mar 25 20:01:51 linux-7vph kernel: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00 Mar 25 20:01:51 linux-7vph kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA Mar 25 20:01:51 linux-7vph kernel: ata2.00: ACPI cmd e3/00:1f:00:00:00:a0 succeeded Mar 25 20:01:51 linux-7vph kernel: ata2.00: ACPI cmd e3/00:02:00:00:00:a0 succeeded Mar 25 20:01:51 linux-7vph kernel: ata2.00: ACPI cmd e3/00:1f:00:00:00:a0 succeeded Mar 25 20:01:51 linux-7vph kernel: ata2.00: ACPI cmd e3/00:02:00:00:00:a0 succeeded Mar 25 20:01:51 linux-7vph kernel: ata2.00: configured for UDMA/133 Mar 25 20:01:51 linux-7vph kernel: Restarting tasks ... <3>ata2: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0x9 t4 Mar 25 20:01:51 linux-7vph kernel: ata2: irq_stat 0x40000001 Mar 25 20:01:51 linux-7vph kernel: done. Mar 25 20:01:51 linux-7vph kernel: ata2.00: configured for UDMA/133 Mar 25 20:01:51 linux-7vph kernel: ata2: EH complete ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 2.6.29 regression: ATA bus errors on resume 2009-03-25 6:06 ` Jeff Garzik 2009-03-25 21:40 ` Niel Lambrechts @ 2009-03-25 22:16 ` James Bottomley 1 sibling, 0 replies; 9+ messages in thread From: James Bottomley @ 2009-03-25 22:16 UTC (permalink / raw) To: Jeff Garzik Cc: Niel Lambrechts, linux.kernel, Linux IDE mailing list, Arjan van de Ven, Rafael J. Wysocki, linux-scsi On Wed, 2009-03-25 at 02:06 -0400, Jeff Garzik wrote: > Niel Lambrechts wrote: > > On 03/25/2009 03:30 AM, Theodore Tso wrote: > >> On Tue, Mar 24, 2009 at 10:25:57PM +0200, Niel Lambrechts wrote: > >>> Hi, > >>> > >>> After upgrading to 2.6.29 I get the below errors after resuming from > >>> hibernating with s2disk. I ran fsck and tried doing the same thing again > >>> in 2.6.28.9-pae, but do not get any errors there. > >> The ext4 errors are interleaved with hardware errors, and the ext4 > >> errors are about I/O errors. > >> > >> EXT4-fs error (device sda6): __ext4_get_inode_loc: unable to read inode block - inode=2346519 > >> EXT4-fs error (device sda6) in ext4_reserve_inode_write: IO failure > >> > >> This looks more like a hibernation problem than an ext4 problem. > >> Looks like the hard drive is being left in some inconsistent state > >> after resuming from hibernation. > >> > >> - Ted > > > > Thanks for the info Theodore, this is definitely looks like some type of > > regression in 2.6.29, as the problem is not evident when I s2disk using > > 2.6.28.9, even after multiple suspend/resume cycles. > > > > I found some 'ATA bus errors' and 'SError' messages in > > /var/log/messages, so I've attached the messages from both 2.6.29 and > > 2.6.28 for comparison. > > Well, here is the interpretation of messages: > > > ata1.00: irq_stat 0x00400008, PHY RDY changed > > ata1: SError: { PHYRdyChg CommWake } > > Your SATA hardware flags a connect-or-disconnect event ("PHY RDY"), > which requires us to abort a bunch of queued commands: > > > ata1.00: cmd 60/18:00:77:88:6f/00:00:0e:00:00/40 tag 0 ncq 12288 in > > res 50/00:30:07:b3:10/00:00:0c:00:00/40 Emask 0x10 (ATA bus error) > [...] > > ata1.00: cmd 60/30:68:07:b3:10/00:00:0c:00:00/40 tag 13 ncq 24576 in > > res 50/00:30:07:b3:10/00:00:0c:00:00/40 Emask 0x10 (ATA bus error) > > ...through the 14th command (tag 13). > > > Mar 24 21:29:14 linux-7vph kernel: ata1: hard resetting link > > Mar 24 21:29:14 linux-7vph kernel: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300) > > Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 succeeded > > Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 filtered out > > Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 succeeded > > Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 filtered out > > Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 succeeded > > Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 filtered out > > Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 succeeded > > Mar 24 21:29:14 linux-7vph kernel: ata1.00: ACPI cmd ef/10:03:00:00:00:a0 filtered out > > Mar 24 21:29:14 linux-7vph kernel: ata1.00: configured for UDMA/133 > > Mar 24 21:29:14 linux-7vph kernel: ata1.00: configured for UDMA/133 > > > SATA link is reset, and ACPI is re-run. > > > Mar 24 21:29:14 linux-7vph kernel: sd 0:0:0:0: [sda] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE,SUGGEST_OK > > Mar 24 21:29:14 linux-7vph kernel: sd 0:0:0:0: [sda] Sense Key : Aborted Command [current] [descriptor] > > Mar 24 21:29:14 linux-7vph kernel: Descriptor sense data with sense descriptors (in hex): > > Mar 24 21:29:14 linux-7vph kernel: 72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00 > > Mar 24 21:29:14 linux-7vph kernel: 0c 10 b3 07 > > Mar 24 21:29:14 linux-7vph kernel: sd 0:0:0:0: [sda] Add. Sense: No additional sense information > > Mar 24 21:29:14 linux-7vph kernel: end_request: I/O error, dev sda, sector 242190455 > > The SCSI subsystem aborts each of the queued commands. No .. this is the SCSI subsystem receives an ABORTED COMMAND return in sense data for each of the outstanding I/Os The only place these are generated is in ata_sense_to_error() which only occurs if there's some type of ata error. If I had to theorise, I'd say the system suspended with commands outstanding to the device. On resume, the device gets reset and returns some type of ATA error which gets translated to ABORTED COMMAND which causes a failure. In the mid layer, we translate ABORTED_COMMAND into a retry until the command runs out of them ... could it be there's a race readying the device and we run through the retries before it can accept the command? James ^ permalink raw reply [flat|nested] 9+ messages in thread
end of thread, other threads:[~2009-03-30 8:59 UTC | newest]
Thread overview: 9+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
[not found] <cjtH6-3Ll-13@gated-at.bofh.it>
[not found] ` <cjtH6-3Ll-15@gated-at.bofh.it>
[not found] ` <cjtH6-3Ll-11@gated-at.bofh.it>
[not found] ` <cjutt-577-11@gated-at.bofh.it>
[not found] ` <cjJCb-47c-23@gated-at.bofh.it>
2009-03-27 19:10 ` 2.6.29 regression: ATA bus errors on resume Niel Lambrechts
2009-03-27 22:30 ` Arjan van de Ven
2009-03-28 10:22 ` Niel Lambrechts
2009-03-28 14:06 ` Rafael J. Wysocki
2009-03-30 8:43 ` Tejun Heo
2009-03-30 8:55 ` Tejun Heo
[not found] <cjlqb-7sp-1@gated-at.bofh.it>
[not found] ` <cjq6y-6sq-11@gated-at.bofh.it>
[not found] ` <49C9BEC8.9020403@devnull.org>
2009-03-25 6:06 ` Jeff Garzik
2009-03-25 21:40 ` Niel Lambrechts
2009-03-25 22:16 ` James Bottomley
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).