Bug 12155 - Regression in 2.6.28-rc and 2.6.27-stable - hibernate related
Regression in 2.6.28-rc and 2.6.27-stable - hibernate related
Status: CLOSED CODE_FIX
Product: Process Management
Classification: Unclassified
Component: Scheduler
All Linux
: P1 normal
Assigned To: Ingo Molnar
:
Depends on:
Blocks: 7216 11808 56331
  Show dependency treegraph
 
Reported: 2008-12-03 14:25 UTC by Rafael J. Wysocki
Modified: 2013-04-09 06:23 UTC (History)
5 users (show)

See Also:
Kernel Version: 2.6.28-rc
Tree: Mainline
Regression: Yes


Attachments
dmesg from a clean 2.6.27.4 boot (45.22 KB, application/octet-stream)
2008-12-07 14:23 UTC, Fabio Comolli
Details
Output of lspci -vv from the same session (17.73 KB, application/octet-stream)
2008-12-07 14:24 UTC, Fabio Comolli
Details
Output of acpidump (106.43 KB, text/plain)
2008-12-07 14:25 UTC, Fabio Comolli
Details
Output of dmidecode (5.62 KB, text/plain)
2008-12-07 14:25 UTC, Fabio Comolli
Details
Extract from /var/log/messages when system refused to suspend (211.58 KB, application/octet-stream)
2008-12-09 00:44 UTC, Fabio Comolli
Details
Changes committed between 2.6.27.4 and 2.6.27.5 (63.00 KB, text/plain)
2008-12-10 01:52 UTC, Rafael J. Wysocki
Details
Output of the git bisect log command. (1.25 KB, application/octet-stream)
2008-12-13 00:17 UTC, Fabio Comolli
Details

Description Rafael J. Wysocki 2008-12-03 14:25:33 UTC
Subject    : Regression in 2.6.28-rc and 2.6.27-stable - hibernate related
Submitter  : "Fabio Comolli" <fabio.comolli@gmail.com>
Date       : 2008-11-23 16:17
References : http://marc.info/?l=linux-kernel&m=122745709926361&w=4

This entry is being used for tracking a regression from 2.6.27.  Please don't
close it until the problem is fixed in the mainline.
Comment 1 ykzhao 2008-12-03 17:46:05 UTC
Hi, Fabio
    Will you please use the git-bisect to identify which commit causes the regression?
    thanks.
Comment 2 Zhang Rui 2008-12-03 19:39:49 UTC
no, git-bisect doesn't work well in this case.
Rafael, could you cc this thread to linux-acpi ML?
Comment 3 Rafael J. Wysocki 2008-12-04 16:25:12 UTC
Done.
Comment 4 Rafael J. Wysocki 2008-12-07 14:10:22 UTC
Fabio says 2.6.27.8 breaks for him even more than the previous kernels and he is afraid of breaking his box while testing this issue.

The last kernel working for him is 2.6.27.4 .

Fabio, please attach the hardware information for your system here (ie. the output of dmesg after a clean boot, the output of 'lspci -vv', the output of 'acpidump' and the output of 'dmidecode', preferably as plain text attachments).
Comment 5 Fabio Comolli 2008-12-07 14:23:56 UTC
Created attachment 19198 [details]
dmesg from a clean 2.6.27.4 boot
Comment 6 Fabio Comolli 2008-12-07 14:24:48 UTC
Created attachment 19199 [details]
Output of lspci -vv from the same session
Comment 7 Fabio Comolli 2008-12-07 14:25:19 UTC
Created attachment 19200 [details]
Output of acpidump
Comment 8 Fabio Comolli 2008-12-07 14:25:42 UTC
Created attachment 19201 [details]
Output of dmidecode
Comment 9 Fabio Comolli 2008-12-07 14:26:01 UTC
Done.
Comment 10 Zhang Rui 2008-12-08 01:16:07 UTC
Nov 23 16:43:14 hawking kernel: sd 0:0:0:0: [sda] Starting disk
Nov 23 16:43:14 hawking kernel: Restarting tasks ... done.
Nov 23 16:43:52 hawking kernel: ata1.01: exception Emask 0x0 SAct 0x0
SErr 0x0 action 0x6 frozen
Nov 23 16:43:52 hawking kernel: ata1.01: cmd
a0/00:00:00:00:00/00:00:00:00:00/b0 tag 0
Nov 23 16:43:52 hawking kernel:          cdb 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00
Nov 23 16:43:52 hawking kernel:          res
40/00:03:00:00:00/00:00:00:00:00/b0 Emask 0x4 (timeout)
Nov 23 16:43:52 hawking kernel: ata1.01: status: { DRDY }
Nov 23 16:43:52 hawking kernel: ata1: soft resetting link
Nov 23 16:43:57 hawking kernel: ata1.01: qc timeout (cmd 0xa1)
Nov 23 16:43:57 hawking kernel: ata1.01: failed to IDENTIFY (I/O
error, err_mask=0x4)
Nov 23 16:43:57 hawking kernel: ata1.01: revalidation failed (errno=-5)
Nov 23 16:43:57 hawking kernel: ata1: soft resetting link
Nov 23 16:44:08 hawking kernel: ata1.01: qc timeout (cmd 0xa1)
Nov 23 16:44:08 hawking kernel: ata1.01: failed to IDENTIFY (I/O
error, err_mask=0x4)
Nov 23 16:44:08 hawking kernel: ata1.01: revalidation failed (errno=-5)
Nov 23 16:44:08 hawking kernel: ata1: soft resetting link
Nov 23 16:44:38 hawking kernel: ata1.00: configured for UDMA/100
Nov 23 16:44:38 hawking kernel: ata1.01: configured for MWDMA2
Nov 23 16:44:38 hawking kernel: ata1: EH complete
Nov 23 16:44:39 hawking kernel: sd 0:0:0:0: [sda] 156301488 512-byte
hardware sectors: (80.0 GB/74.5 GiB)
Nov 23 16:44:39 hawking kernel: sd 0:0:0:0: [sda] Write Protect is off
Nov 23 16:44:39 hawking kernel: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
Nov 23 16:44:39 hawking kernel: sd 0:0:0:0: [sda] Write cache:
enabled, read cache: enabled, doesn't support DPO or FUA
Nov 23 16:44:39 hawking kernel: sd 0:0:0:0: [sda] 156301488 512-byte
hardware sectors: (80.0 GB/74.5 GiB)
Nov 23 16:44:39 hawking kernel: sd 0:0:0:0: [sda] Write Protect is off
Nov 23 16:44:39 hawking kernel: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
Nov 23 16:44:39 hawking kernel: sd 0:0:0:0: [sda] Write cache:
enabled, read cache: enabled, doesn't support DPO or FUA

It seems that the long delay is caused by the scsi failure.
cc Tejun.

Fabio, could you please try libata.noacpi and see if it helps?
Comment 11 Fabio Comolli 2008-12-08 01:36:45 UTC
Hi.

On Mon, Dec 8, 2008 at 10:16 AM,  <bugme-daemon@bugzilla.kernel.org> wrote:
> http://bugzilla.kernel.org/show_bug.cgi?id=12155
>
>
> rui.zhang@intel.com changed:
>
>           What    |Removed                     |Added
> ----------------------------------------------------------------------------
>                 CC|                            |tj@kernel.org
>
>
>
>
> ------- Comment #10 from rui.zhang@intel.com  2008-12-08 01:16 -------
> Nov 23 16:43:14 hawking kernel: sd 0:0:0:0: [sda] Starting disk
> Nov 23 16:43:14 hawking kernel: Restarting tasks ... done.
> Nov 23 16:43:52 hawking kernel: ata1.01: exception Emask 0x0 SAct 0x0
> SErr 0x0 action 0x6 frozen
> Nov 23 16:43:52 hawking kernel: ata1.01: cmd
> a0/00:00:00:00:00/00:00:00:00:00/b0 tag 0
> Nov 23 16:43:52 hawking kernel:          cdb 00 00 00 00 00 00 00 00
> 00 00 00 00 00 00 00 00
> Nov 23 16:43:52 hawking kernel:          res
> 40/00:03:00:00:00/00:00:00:00:00/b0 Emask 0x4 (timeout)
> Nov 23 16:43:52 hawking kernel: ata1.01: status: { DRDY }
> Nov 23 16:43:52 hawking kernel: ata1: soft resetting link
> Nov 23 16:43:57 hawking kernel: ata1.01: qc timeout (cmd 0xa1)
> Nov 23 16:43:57 hawking kernel: ata1.01: failed to IDENTIFY (I/O
> error, err_mask=0x4)
> Nov 23 16:43:57 hawking kernel: ata1.01: revalidation failed (errno=-5)
> Nov 23 16:43:57 hawking kernel: ata1: soft resetting link
> Nov 23 16:44:08 hawking kernel: ata1.01: qc timeout (cmd 0xa1)
> Nov 23 16:44:08 hawking kernel: ata1.01: failed to IDENTIFY (I/O
> error, err_mask=0x4)
> Nov 23 16:44:08 hawking kernel: ata1.01: revalidation failed (errno=-5)
> Nov 23 16:44:08 hawking kernel: ata1: soft resetting link
> Nov 23 16:44:38 hawking kernel: ata1.00: configured for UDMA/100
> Nov 23 16:44:38 hawking kernel: ata1.01: configured for MWDMA2
> Nov 23 16:44:38 hawking kernel: ata1: EH complete
> Nov 23 16:44:39 hawking kernel: sd 0:0:0:0: [sda] 156301488 512-byte
> hardware sectors: (80.0 GB/74.5 GiB)
> Nov 23 16:44:39 hawking kernel: sd 0:0:0:0: [sda] Write Protect is off
> Nov 23 16:44:39 hawking kernel: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
> Nov 23 16:44:39 hawking kernel: sd 0:0:0:0: [sda] Write cache:
> enabled, read cache: enabled, doesn't support DPO or FUA
> Nov 23 16:44:39 hawking kernel: sd 0:0:0:0: [sda] 156301488 512-byte
> hardware sectors: (80.0 GB/74.5 GiB)
> Nov 23 16:44:39 hawking kernel: sd 0:0:0:0: [sda] Write Protect is off
> Nov 23 16:44:39 hawking kernel: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
> Nov 23 16:44:39 hawking kernel: sd 0:0:0:0: [sda] Write cache:
> enabled, read cache: enabled, doesn't support DPO or FUA
>
> It seems that the long delay is caused by the scsi failure.
> cc Tejun.
>
> Fabio, could you please try libata.noacpi and see if it helps?
>

Will try latest git with libata.noacpi probably today or tomorrow.

Comment 12 Fabio Comolli 2008-12-08 05:58:47 UTC
Bug reproduced with latest GIT and libata.noacpi=1.
Comment 13 Tejun Heo 2008-12-08 18:19:37 UTC
Can you attach full kernel log from boot to resume?  I'm still a bit lost as to what could cause this sort of regression.
Comment 14 Fabio Comolli 2008-12-09 00:44:19 UTC
Created attachment 19221 [details]
Extract from /var/log/messages when system refused to suspend
Comment 15 Fabio Comolli 2008-12-09 00:45:03 UTC
Well, I tried to reproduce the problem in a totally clean environment (2.6.27.8, no binary-only modules). I then compiled the kernel with drm.ko and radeon.ko and configured the X server to use the radeon driver.

The system survived two hibernate/resume cycles and then refused to suspend. The dmesg buffer has been filled with stacktraces, so the only thing I can give to you is something  cut from /var/log/messages. Please find it attached.

I'll try to reproduce the hang with this clean environment and with fglrx / cisco_ipsec modules.
Comment 16 Fabio Comolli 2008-12-09 02:57:36 UTC
OK. I reproduced the bug at second resume with 2.6.27.8 and without any bynary-only modules. After the resume the system hung for about 5 minutes and then "resurrected".

It seems that it's much easier to reproduce the hang if there is a long delay (> 1 hour) between the hibernation and the resuming.

The dmesg log is:


[    0.000000] Linux version 2.6.27.8-00004-g1a27ee8 (fcomolli@hawking) (gcc version 4.3.1 20080507 (prerelease) [gcc-4_3-branch revision 135036] (SUSE Linux) ) #2 Tue Dec 9 08:30:49 CET 2008
[    0.000000] BIOS-provided physical RAM map:
[    0.000000]  BIOS-e820: 0000000000000000 - 000000000009f800 (usable)
[    0.000000]  BIOS-e820: 000000000009f800 - 00000000000a0000 (reserved)
[    0.000000]  BIOS-e820: 00000000000dc000 - 0000000000100000 (reserved)
[    0.000000]  BIOS-e820: 0000000000100000 - 000000007fee0000 (usable)
[    0.000000]  BIOS-e820: 000000007fee0000 - 000000007feeb000 (ACPI data)
[    0.000000]  BIOS-e820: 000000007feeb000 - 000000007ff00000 (ACPI NVS)
[    0.000000]  BIOS-e820: 000000007ff00000 - 0000000080000000 (reserved)
[    0.000000]  BIOS-e820: 00000000e0000000 - 00000000f0006000 (reserved)
[    0.000000]  BIOS-e820: 00000000f0008000 - 00000000f000c000 (reserved)
[    0.000000]  BIOS-e820: 00000000fed20000 - 00000000fed90000 (reserved)
[    0.000000]  BIOS-e820: 00000000ff000000 - 0000000100000000 (reserved)
[    0.000000] DMI present.
[    0.000000] last_pfn = 0x7fee0 max_arch_pfn = 0x100000
[    0.000000] kernel direct mapping tables up to 38000000 @ 7000-c000
[    0.000000] RAMDISK: 37b4a000 - 37fef975
[    0.000000] ACPI: RSDP 000F76A0, 0014 (r0 HP    )
[    0.000000] ACPI: RSDT 7FEE5277, 0044 (r1 HP     309E      6040000  LTP        0)
[    0.000000] ACPI: FACP 7FEEAE88, 0074 (r1 HP     309E      6040000 LOHR       5F)
[    0.000000] ACPI: DSDT 7FEE5B1C, 536C (r1 HP     309E      6040000 MSFT  100000E)
[    0.000000] ACPI: FACS 7FEFBFC0, 0040
[    0.000000] ACPI: APIC 7FEEAEFC, 0068 (r1 HP     309E      6040000 LOHR       5F)
[    0.000000] ACPI: BOOT 7FEEAFD8, 0028 (r1 HP     309E      6040000  LTP        1)
[    0.000000] ACPI: MCFG 7FEEAF9C, 003C (r1 HP     309E      6040000 LOHR       5F)
[    0.000000] ACPI: SSDT 7FEE56D3, 0235 (r1 HP     309E         3000 INTL 20030224)
[    0.000000] ACPI: SSDT 7FEE54FB, 01D8 (r1 HP     309E         3001 INTL 20030224)
[    0.000000] ACPI: SSDT 7FEE53E7, 0114 (r1 HP     309E         3000 INTL 20030224)
[    0.000000] ACPI: SSDT 7FEE52BB, 012C (r1 HP     309E            1 INTL 20030224)
[    0.000000] ACPI: DMI detected: Hewlett-Packard
[    0.000000] 1150MB HIGHMEM available.
[    0.000000] 896MB LOWMEM available.
[    0.000000]   mapped low ram: 0 - 38000000
[    0.000000]   low ram: 00000000 - 38000000
[    0.000000]   bootmap 00008000 - 0000f000
[    0.000000] (7 early reservations) ==> bootmem [0000000000 - 0038000000]
[    0.000000]   #0 [0000000000 - 0000001000]   BIOS data page ==> [0000000000 - 0000001000]
[    0.000000]   #1 [0000100000 - 0000a93280]    TEXT DATA BSS ==> [0000100000 - 0000a93280]
[    0.000000]   #2 [0037b4a000 - 0037fef975]          RAMDISK ==> [0037b4a000 - 0037fef975]
[    0.000000]   #3 [0000a94000 - 0000a98000]    INIT_PG_TABLE ==> [0000a94000 - 0000a98000]
[    0.000000]   #4 [000009f800 - 0000100000]    BIOS reserved ==> [000009f800 - 0000100000]
[    0.000000]   #5 [0000007000 - 0000008000]          PGTABLE ==> [0000007000 - 0000008000]
[    0.000000]   #6 [0000008000 - 000000f000]          BOOTMAP ==> [0000008000 - 000000f000]
[    0.000000] Zone PFN ranges:
[    0.000000]   DMA      0x00000000 -> 0x00001000
[    0.000000]   Normal   0x00001000 -> 0x00038000
[    0.000000]   HighMem  0x00038000 -> 0x0007fee0
[    0.000000] Movable zone start PFN for each node
[    0.000000] early_node_map[2] active PFN ranges
[    0.000000]     0: 0x00000000 -> 0x0000009f
[    0.000000]     0: 0x00000100 -> 0x0007fee0
[    0.000000] On node 0 totalpages: 523903
[    0.000000] free_area_init_node: node 0, pgdat c053012c, node_mem_map c1000000
[    0.000000]   DMA zone: 3967 pages, LIFO batch:0
[    0.000000]   Normal zone: 223520 pages, LIFO batch:31
[    0.000000]   HighMem zone: 292322 pages, LIFO batch:31
[    0.000000] ACPI: PM-Timer IO Port: 0x1008
[    0.000000] ACPI: Local APIC address 0xfee00000
[    0.000000] ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x01] lapic_id[0x01] disabled)
[    0.000000] ACPI: LAPIC_NMI (acpi_id[0x00] high edge lint[0x1])
[    0.000000] ACPI: LAPIC_NMI (acpi_id[0x01] high edge lint[0x1])
[    0.000000] ACPI: IOAPIC (id[0x01] address[0xfec00000] gsi_base[0])
[    0.000000] IOAPIC[0]: apic_id 1, version 32, address 0xfec00000, GSI 0-23
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[    0.000000] ACPI: IRQ0 used by override.
[    0.000000] ACPI: IRQ2 used by override.
[    0.000000] ACPI: IRQ9 used by override.
[    0.000000] Enabling APIC mode:  Flat.  Using 1 I/O APICs
[    0.000000] Using ACPI (MADT) for SMP configuration information
[    0.000000] mapped APIC to ffffb000 (fee00000)
[    0.000000] mapped IOAPIC to ffffa000 (fec00000)
[    0.000000] PM: Registered nosave memory: 000000000009f000 - 00000000000a0000
[    0.000000] PM: Registered nosave memory: 00000000000a0000 - 00000000000dc000
[    0.000000] PM: Registered nosave memory: 00000000000dc000 - 0000000000100000
[    0.000000] Allocating PCI resources starting at 88000000 (gap: 80000000:60000000)
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 519809
[    0.000000] Kernel command line: root=/dev/sda2 resume=/dev/sda3 i8042.nomux=1 pciehp.pciehp_force=1 quiet splash=silent vga=791
[    0.000000] bootsplash: silent mode.
[    0.000000] Enabling fast FPU save and restore... done.
[    0.000000] Enabling unmasked SIMD FPU exception support... done.
[    0.000000] Initializing CPU#0
[    0.000000] PID hash table entries: 4096 (order: 12, 16384 bytes)
[    0.000000] TSC: PIT calibration confirmed by PMTIMER.
[    0.000000] TSC: using PIT calibration value
[    0.000000] Detected 1729.495 MHz processor.
[    0.004000] Console: colour dummy device 80x25
[    0.004000] console [tty0] enabled
[    0.004000] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[    0.004000] ... MAX_LOCKDEP_SUBCLASSES:    8
[    0.004000] ... MAX_LOCK_DEPTH:          48
[    0.004000] ... MAX_LOCKDEP_KEYS:        8191
[    0.004000] ... CLASSHASH_SIZE:           4096
[    0.004000] ... MAX_LOCKDEP_ENTRIES:     8192
[    0.004000] ... MAX_LOCKDEP_CHAINS:      16384
[    0.004000] ... CHAINHASH_SIZE:          8192
[    0.004000]  memory used by lock dependency info: 2463 kB
[    0.004000]  per task-struct memory footprint: 1920 bytes
[    0.004000] ------------------------
[    0.004000] | Locking API testsuite:
[    0.004000] ----------------------------------------------------------------------------
[    0.004000]                                  | spin |wlock |rlock |mutex | wsem | rsem |
[    0.004000]   --------------------------------------------------------------------------
[    0.004000]                      A-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]                  A-B-B-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]              A-B-B-C-C-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]              A-B-C-A-B-C deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]          A-B-B-C-C-D-D-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]          A-B-C-D-B-D-D-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]          A-B-C-D-B-C-D-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]                     double unlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]                   initialize held:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]                  bad unlock order:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]   --------------------------------------------------------------------------
[    0.004000]               recursive read-lock:             |  ok  |             |  ok  |
[    0.004000]            recursive read-lock #2:             |  ok  |             |  ok  |
[    0.004000]             mixed read-write-lock:             |  ok  |             |  ok  |
[    0.004000]             mixed write-read-lock:             |  ok  |             |  ok  |
[    0.004000]   --------------------------------------------------------------------------
[    0.004000]      hard-irqs-on + irq-safe-A/12:  ok  |  ok  |  ok  |
[    0.004000]      soft-irqs-on + irq-safe-A/12:  ok  |  ok  |  ok  |
[    0.004000]      hard-irqs-on + irq-safe-A/21:  ok  |  ok  |  ok  |
[    0.004000]      soft-irqs-on + irq-safe-A/21:  ok  |  ok  |  ok  |
[    0.004000]        sirq-safe-A => hirqs-on/12:  ok  |  ok  |  ok  |
[    0.004000]        sirq-safe-A => hirqs-on/21:  ok  |  ok  |  ok  |
[    0.004000]          hard-safe-A + irqs-on/12:  ok  |  ok  |  ok  |
[    0.004000]          soft-safe-A + irqs-on/12:  ok  |  ok  |  ok  |
[    0.004000]          hard-safe-A + irqs-on/21:  ok  |  ok  |  ok  |
[    0.004000]          soft-safe-A + irqs-on/21:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #1/123:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #1/123:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #1/132:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #1/132:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #1/213:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #1/213:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #1/231:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #1/231:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #1/312:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #1/312:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #1/321:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #1/321:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #2/123:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #2/123:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #2/132:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #2/132:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #2/213:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #2/213:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #2/231:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #2/231:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #2/312:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #2/312:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #2/321:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #2/321:  ok  |  ok  |  ok  |
[    0.004000]       hard-irq lock-inversion/123:  ok  |  ok  |  ok  |
[    0.004000]       soft-irq lock-inversion/123:  ok  |  ok  |  ok  |
[    0.004000]       hard-irq lock-inversion/132:  ok  |  ok  |  ok  |
[    0.004000]       soft-irq lock-inversion/132:  ok  |  ok  |  ok  |
[    0.004000]       hard-irq lock-inversion/213:  ok  |  ok  |  ok  |
[    0.004000]       soft-irq lock-inversion/213:  ok  |  ok  |  ok  |
[    0.004000]       hard-irq lock-inversion/231:  ok  |  ok  |  ok  |
[    0.004000]       soft-irq lock-inversion/231:  ok  |  ok  |  ok  |
[    0.004000]       hard-irq lock-inversion/312:  ok  |  ok  |  ok  |
[    0.004000]       soft-irq lock-inversion/312:  ok  |  ok  |  ok  |
[    0.004000]       hard-irq lock-inversion/321:  ok  |  ok  |  ok  |
[    0.004000]       soft-irq lock-inversion/321:  ok  |  ok  |  ok  |
[    0.004000]       hard-irq read-recursion/123:  ok  |
[    0.004000]       soft-irq read-recursion/123:  ok  |
[    0.004000]       hard-irq read-recursion/132:  ok  |
[    0.004000]       soft-irq read-recursion/132:  ok  |
[    0.004000]       hard-irq read-recursion/213:  ok  |
[    0.004000]       soft-irq read-recursion/213:  ok  |
[    0.004000]       hard-irq read-recursion/231:  ok  |
[    0.004000]       soft-irq read-recursion/231:  ok  |
[    0.004000]       hard-irq read-recursion/312:  ok  |
[    0.004000]       soft-irq read-recursion/312:  ok  |
[    0.004000]       hard-irq read-recursion/321:  ok  |
[    0.004000]       soft-irq read-recursion/321:  ok  |
[    0.004000] -------------------------------------------------------
[    0.004000] Good, all 218 testcases passed! |
[    0.004000] ---------------------------------
[    0.004000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[    0.004000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.004000] Memory: 2062868k/2096000k available (2694k kernel code, 31904k reserved, 1626k data, 228k init, 1178496k highmem)
[    0.004000] virtual kernel memory layout:
[    0.004000]     fixmap  : 0xfffac000 - 0xfffff000   ( 332 kB)
[    0.004000]     pkmap   : 0xff800000 - 0xffc00000   (4096 kB)
[    0.004000]     vmalloc : 0xf8800000 - 0xff7fe000   ( 111 MB)
[    0.004000]     lowmem  : 0xc0000000 - 0xf8000000   ( 896 MB)
[    0.004000]       .init : 0xc053c000 - 0xc0575000   ( 228 kB)
[    0.004000]       .data : 0xc03a1804 - 0xc0538148   (1626 kB)
[    0.004000]       .text : 0xc0100000 - 0xc03a1804   (2694 kB)
[    0.004000] Checking if this processor honours the WP bit even in supervisor mode...Ok.
[    0.004000] CPA: page pool initialized 1 of 1 pages preallocated
[    0.004028] Calibrating delay loop (skipped), value calculated using timer frequency.. 3458.99 BogoMIPS (lpj=6917980)
[    0.004164] Mount-cache hash table entries: 512
[    0.005077] CPU: L1 I cache: 32K, L1 D cache: 32K
[    0.005080] CPU: L2 cache: 2048K
[    0.005084] Intel machine check architecture supported.
[    0.005088] Intel machine check reporting enabled on CPU#0.
[    0.005099] CPU: Intel(R) Pentium(R) M processor 1.73GHz stepping 08
[    0.005115] Checking 'hlt' instruction... OK.
[    0.020295] Freeing SMP alternatives: 0k freed
[    0.020298] ACPI: Core revision 20080609
[    0.036525] ENABLING IO-APIC IRQs
[    0.036766] ..TIMER: vector=0x31 apic1=0 pin1=2 apic2=-1 pin2=-1
[    0.080005] net_namespace: 388 bytes
[    0.080005] NET: Registered protocol family 16
[    0.080005] No dock devices found.
[    0.080005] ACPI: bus type pci registered
[    0.080005] PCI: MCFG configuration 0: base e0000000 segment 0 buses 0 - 255
[    0.080005] PCI: MCFG area at e0000000 reserved in E820
[    0.080005] PCI: Using MMCONFIG for extended config space
[    0.080005] PCI: Using configuration type 1 for base access
[    0.091944] ACPI: EC: Look up EC in DSDT
[    0.100552] ACPI: Interpreter enabled
[    0.100558] ACPI: (supports S0 S3 S4 S5)
[    0.100621] ACPI: Using IOAPIC for interrupt routing
[    0.109985] ACPI: EC: non-query interrupt received, switching to interrupt mode
[    0.122248] ACPI: EC: GPE = 0x1b, I/O: command/status = 0x66, data = 0x62
[    0.122251] ACPI: EC: driver started in interrupt mode
[    0.124113] ACPI: PCI Root Bridge [PCI0] (0000:00)
[    0.124532] pci 0000:00:01.0: PME# supported from D0 D3hot D3cold
[    0.124539] pci 0000:00:01.0: PME# disabled
[    0.124714] pci 0000:00:1c.0: PME# supported from D0 D3hot D3cold
[    0.124721] pci 0000:00:1c.0: PME# disabled
[    0.124811] PCI: 0000:00:1d.0 reg 20 io port: [1800, 181f]
[    0.124912] PCI: 0000:00:1d.1 reg 20 io port: [1820, 183f]
[    0.125019] PCI: 0000:00:1d.2 reg 20 io port: [1840, 185f]
[    0.125120] PCI: 0000:00:1d.3 reg 20 io port: [1860, 187f]
[    0.125226] PCI: 0000:00:1d.7 reg 10 32bit mmio: [c8000000, c80003ff]
[    0.125311] pci 0000:00:1d.7: PME# supported from D0 D3hot D3cold
[    0.125318] pci 0000:00:1d.7: PME# disabled
[    0.125474] PCI: 0000:00:1e.2 reg 10 io port: [1c00, 1cff]
[    0.125485] PCI: 0000:00:1e.2 reg 14 io port: [1880, 18bf]
[    0.125497] PCI: 0000:00:1e.2 reg 18 32bit mmio: [c8000800, c80009ff]
[    0.125508] PCI: 0000:00:1e.2 reg 1c 32bit mmio: [c8000400, c80004ff]
[    0.125561] pci 0000:00:1e.2: PME# supported from D0 D3hot D3cold
[    0.125568] pci 0000:00:1e.2: PME# disabled
[    0.125625] PCI: 0000:00:1e.3 reg 10 io port: [2400, 24ff]
[    0.125636] PCI: 0000:00:1e.3 reg 14 io port: [2000, 207f]
[    0.125706] pci 0000:00:1e.3: PME# supported from D0 D3hot D3cold
[    0.125713] pci 0000:00:1e.3: PME# disabled
[    0.125850] pci 0000:00:1f.0: Force enabled HPET at 0xfed00000
[    0.125859] pci 0000:00:1f.0: quirk: region 1000-107f claimed by ICH6 ACPI/GPIO/TCO
[    0.125865] pci 0000:00:1f.0: quirk: region 1180-11bf claimed by ICH6 GPIO
[    0.125906] PCI: 0000:00:1f.1 reg 10 io port: [0, 7]
[    0.125917] PCI: 0000:00:1f.1 reg 14 io port: [0, 3]
[    0.125928] PCI: 0000:00:1f.1 reg 18 io port: [0, 7]
[    0.125939] PCI: 0000:00:1f.1 reg 1c io port: [0, 3]
[    0.125950] PCI: 0000:00:1f.1 reg 20 io port: [18c0, 18cf]
[    0.126069] PCI: 0000:00:1f.3 reg 20 io port: [18e0, 18ff]
[    0.126174] PCI: 0000:01:00.0 reg 10 32bit mmio: [d0000000, d7ffffff]
[    0.126184] PCI: 0000:01:00.0 reg 14 io port: [3000, 30ff]
[    0.126193] PCI: 0000:01:00.0 reg 18 32bit mmio: [c8100000, c810ffff]
[    0.126222] PCI: 0000:01:00.0 reg 30 32bit mmio: [0, 1ffff]
[    0.126249] pci 0000:01:00.0: supports D1
[    0.126250] pci 0000:01:00.0: supports D2
[    0.126324] PCI: bridge 0000:00:01.0 io port: [3000, 3fff]
[    0.126329] PCI: bridge 0000:00:01.0 32bit mmio: [c8100000, c81fffff]
[    0.126335] PCI: bridge 0000:00:01.0 32bit mmio pref: [d0000000, d7ffffff]
[    0.126427] PCI: bridge 0000:00:1c.0 io port: [0, fff]
[    0.126433] PCI: bridge 0000:00:1c.0 32bit mmio: [0, fffff]
[    0.126445] PCI: bridge 0000:00:1c.0 64bit mmio pref: [0, fffff]
[    0.126543] PCI: 0000:06:05.0 reg 10 32bit mmio: [c8206000, c8206fff]
[    0.126641] pci 0000:06:05.0: PME# supported from D0 D3hot D3cold
[    0.126649] pci 0000:06:05.0: PME# disabled
[    0.126719] PCI: 0000:06:06.0 reg 10 32bit mmio: [c8207000, c8207fff]
[    0.126751] pci 0000:06:06.0: supports D1
[    0.126753] pci 0000:06:06.0: supports D2
[    0.126755] pci 0000:06:06.0: PME# supported from D0 D1 D2 D3hot D3cold
[    0.126763] pci 0000:06:06.0: PME# disabled
[    0.126841] PCI: 0000:06:06.2 reg 10 32bit mmio: [c8208000, c82087ff]
[    0.126855] PCI: 0000:06:06.2 reg 14 32bit mmio: [c8200000, c8203fff]
[    0.126944] pci 0000:06:06.2: supports D1
[    0.126946] pci 0000:06:06.2: supports D2
[    0.126948] pci 0000:06:06.2: PME# supported from D0 D1 D2 D3hot
[    0.126956] pci 0000:06:06.2: PME# disabled
[    0.127025] PCI: 0000:06:06.3 reg 10 32bit mmio: [c8204000, c8205fff]
[    0.127121] pci 0000:06:06.3: supports D1
[    0.127123] pci 0000:06:06.3: supports D2
[    0.127125] pci 0000:06:06.3: PME# supported from D0 D1 D2 D3hot
[    0.127133] pci 0000:06:06.3: PME# disabled
[    0.127202] PCI: 0000:06:06.4 reg 10 32bit mmio: [c8209000, c82090ff]
[    0.127216] PCI: 0000:06:06.4 reg 14 32bit mmio: [c8208c00, c8208cff]
[    0.127230] PCI: 0000:06:06.4 reg 18 32bit mmio: [c8208800, c82088ff]
[    0.127304] pci 0000:06:06.4: supports D1
[    0.127306] pci 0000:06:06.4: supports D2
[    0.127308] pci 0000:06:06.4: PME# supported from D0 D1 D2 D3hot
[    0.127316] pci 0000:06:06.4: PME# disabled
[    0.127399] PCI: 0000:06:07.0 reg 10 io port: [4000, 40ff]
[    0.127413] PCI: 0000:06:07.0 reg 14 32bit mmio: [c8209400, c82094ff]
[    0.127498] pci 0000:06:07.0: supports D1
[    0.127500] pci 0000:06:07.0: supports D2
[    0.127502] pci 0000:06:07.0: PME# supported from D1 D2 D3hot D3cold
[    0.127511] pci 0000:06:07.0: PME# disabled
[    0.127579] pci 0000:00:1e.0: transparent bridge
[    0.127586] PCI: bridge 0000:00:1e.0 io port: [4000, 4fff]
[    0.127593] PCI: bridge 0000:00:1e.0 32bit mmio: [c8200000, c82fffff]
[    0.127671] bus 00 -> node 0
[    0.127686] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
[    0.128423] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PEGP._PRT]
[    0.128775] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.RP01._PRT]
[    0.129161] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PCIB._PRT]
[    0.140252] ACPI: PCI Interrupt Link [LNKA] (IRQs 1 3 4 5 6 7 10 12 14 15) *11
[    0.140467] ACPI: PCI Interrupt Link [LNKB] (IRQs 1 3 4 5 6 7 11 12 14 15) *10
[    0.140667] ACPI: PCI Interrupt Link [LNKC] (IRQs 1 3 4 5 6 7 *10 12 14 15)
[    0.140877] ACPI: PCI Interrupt Link [LNKD] (IRQs 1 3 4 5 6 7 11 12 14 15) *10
[    0.141087] ACPI: PCI Interrupt Link [LNKE] (IRQs 1 3 4 5 6 7 10 12 14 15) *11
[    0.141285] ACPI: PCI Interrupt Link [LNKF] (IRQs 1 3 4 5 6 7 *11 12 14 15)
[    0.141482] ACPI: PCI Interrupt Link [LNKG] (IRQs 1 3 4 5 6 7 *10 12 14 15)
[    0.141679] ACPI: PCI Interrupt Link [LNKH] (IRQs 1 3 4 5 6 7 *11 12 14 15)
[    0.142368] Linux Plug and Play Support v0.97 (c) Adam Belay
[    0.142516] pnp: PnP ACPI init
[    0.142547] ACPI: bus type pnp registered
[    0.145072] pnp 00:04: io resource (0x4e-0x4f) overlaps 0000:00:1c.0 BAR 7 (0x0-0xfff), disabling
[    0.145076] pnp 00:04: io resource (0x61-0x61) overlaps 0000:00:1c.0 BAR 7 (0x0-0xfff), disabling
[    0.145080] pnp 00:04: io resource (0x63-0x63) overlaps 0000:00:1c.0 BAR 7 (0x0-0xfff), disabling
[    0.145083] pnp 00:04: io resource (0x65-0x65) overlaps 0000:00:1c.0 BAR 7 (0x0-0xfff), disabling
[    0.145087] pnp 00:04: io resource (0x67-0x67) overlaps 0000:00:1c.0 BAR 7 (0x0-0xfff), disabling
[    0.145090] pnp 00:04: io resource (0x80-0x80) overlaps 0000:00:1c.0 BAR 7 (0x0-0xfff), disabling
[    0.145094] pnp 00:04: io resource (0x92-0x92) overlaps 0000:00:1c.0 BAR 7 (0x0-0xfff), disabling
[    0.145097] pnp 00:04: io resource (0xb2-0xb3) overlaps 0000:00:1c.0 BAR 7 (0x0-0xfff), disabling
[    0.145101] pnp 00:04: io resource (0x200-0x20f) overlaps 0000:00:1c.0 BAR 7 (0x0-0xfff), disabling
[    0.145104] pnp 00:04: io resource (0x800-0x80f) overlaps 0000:00:1c.0 BAR 7 (0x0-0xfff), disabling
[    0.148281] pnp: PnP ACPI: found 8 devices
[    0.148284] ACPI: ACPI bus type pnp unregistered
[    0.149417] SCSI subsystem initialized
[    0.149518] libata version 3.00 loaded.
[    0.150100] usbcore: registered new interface driver usbfs
[    0.150254] usbcore: registered new interface driver hub
[    0.150440] usbcore: registered new device driver usb
[    0.151743] PCI: Using ACPI for IRQ routing
[    0.151751] pci 0000:00:1c.0: BAR 7: can't allocate resource
[    0.151760] pci 0000:00:1c.0: BAR 8: can't allocate resource
[    0.151766] pci 0000:00:1c.0: BAR 9: can't allocate resource
[    0.152281] hpet clockevent registered
[    0.152290] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
[    0.152295] hpet0: 3 64-bit timers, 14318180 Hz
[    0.153456] ACPI: RTC can wake from S4
[    0.153486] system 00:04: ioport range 0x1000-0x107f has been reserved
[    0.153486] system 00:04: ioport range 0x1180-0x11bf has been reserved
[    0.153486] system 00:04: iomem range 0xe0000000-0xefffffff could not be reserved
[    0.153486] system 00:04: iomem range 0xf0000000-0xf0003fff could not be reserved
[    0.153486] system 00:04: iomem range 0xf0004000-0xf0004fff could not be reserved
[    0.153486] system 00:04: iomem range 0xf0005000-0xf0005fff could not be reserved
[    0.153486] system 00:04: iomem range 0xf0008000-0xf000bfff could not be reserved
[    0.153486] system 00:04: iomem range 0xfed20000-0xfed8ffff could not be reserved
[    0.190675] pci 0000:00:01.0: PCI bridge, secondary bus 0000:01
[    0.190680] pci 0000:00:01.0:   IO window: 0x3000-0x3fff
[    0.190688] pci 0000:00:01.0:   MEM window: 0xc8100000-0xc81fffff
[    0.190693] pci 0000:00:01.0:   PREFETCH window: 0x000000d0000000-0x000000d7ffffff
[    0.190702] pci 0000:00:1c.0: PCI bridge, secondary bus 0000:02
[    0.190704] pci 0000:00:1c.0:   IO window: disabled
[    0.190713] pci 0000:00:1c.0:   MEM window: disabled
[    0.190720] pci 0000:00:1c.0:   PREFETCH window: disabled
[    0.190739] pci 0000:06:06.0: CardBus bridge, secondary bus 0000:07
[    0.190741] pci 0000:06:06.0:   IO window: 0x004400-0x0044ff
[    0.190749] pci 0000:06:06.0:   IO window: 0x004800-0x0048ff
[    0.190757] pci 0000:06:06.0:   PREFETCH window: 0x88000000-0x8bffffff
[    0.190766] pci 0000:06:06.0:   MEM window: 0x8c000000-0x8fffffff
[    0.190774] pci 0000:00:1e.0: PCI bridge, secondary bus 0000:06
[    0.190779] pci 0000:00:1e.0:   IO window: 0x4000-0x4fff
[    0.190788] pci 0000:00:1e.0:   MEM window: 0xc8200000-0xc82fffff
[    0.190795] pci 0000:00:1e.0:   PREFETCH window: 0x00000088000000-0x0000008bffffff
[    0.190821] pci 0000:00:01.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[    0.190828] pci 0000:00:01.0: setting latency timer to 64
[    0.190843] pci 0000:00:1c.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[    0.190852] pci 0000:00:1c.0: setting latency timer to 64
[    0.190865] pci 0000:00:1e.0: setting latency timer to 64
[    0.190882] pci 0000:06:06.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22
[    0.190890] pci 0000:06:06.0: setting latency timer to 64
[    0.190896] bus: 00 index 0 io port: [0, ffff]
[    0.190899] bus: 00 index 1 mmio: [0, ffffffff]
[    0.190901] bus: 01 index 0 io port: [3000, 3fff]
[    0.190903] bus: 01 index 1 mmio: [c8100000, c81fffff]
[    0.190906] bus: 01 index 2 mmio: [d0000000, d7ffffff]
[    0.190908] bus: 01 index 3 mmio: [0, 0]
[    0.190910] bus: 02 index 0 mmio: [0, fff]
[    0.190912] bus: 02 index 1 mmio: [0, fffff]
[    0.190914] bus: 02 index 2 mmio: [0, fffff]
[    0.190916] bus: 02 index 3 mmio: [0, 0]
[    0.190919] bus: 06 index 0 io port: [4000, 4fff]
[    0.190921] bus: 06 index 1 mmio: [c8200000, c82fffff]
[    0.190923] bus: 06 index 2 mmio: [88000000, 8bffffff]
[    0.190926] bus: 06 index 3 io port: [0, ffff]
[    0.190928] bus: 06 index 4 mmio: [0, ffffffff]
[    0.190930] bus: 07 index 0 io port: [4400, 44ff]
[    0.190932] bus: 07 index 1 io port: [4800, 48ff]
[    0.190935] bus: 07 index 2 mmio: [88000000, 8bffffff]
[    0.190937] bus: 07 index 3 mmio: [8c000000, 8fffffff]
[    0.190974] NET: Registered protocol family 2
[    0.191273] IP route cache hash table entries: 32768 (order: 5, 131072 bytes)
[    0.192132] TCP established hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.193318] TCP bind hash table entries: 65536 (order: 9, 2359296 bytes)
[    0.199882] TCP: Hash tables configured (established 131072 bind 65536)
[    0.199932] TCP reno registered
[    0.200282] NET: Registered protocol family 1
[    0.201191] checking if image is initramfs... it is
[    0.580023] Freeing initrd memory: 4758k freed
[    0.580451] Simple Boot Flag at 0x36 set to 0x1
[    0.581339] IA-32 Microcode Update Driver: v1.14a <tigran@aivazian.fsnet.co.uk>
[    0.583623] highmem bounce pool size: 64 pages
[    0.584174] fuse init (API version 7.9)
[    0.584423] msgmni has been set to 1738
[    0.584783] io scheduler noop registered
[    0.584806] io scheduler cfq registered (default)
[    0.584965] pci 0000:01:00.0: Boot video device
[    0.585429] pcieport-driver 0000:00:01.0: setting latency timer to 64
[    0.585506] pcieport-driver 0000:00:01.0: found MSI capability
[    0.585574] pci_express 0000:00:01.0:pcie00: allocate port service
[    0.585732] pci_express 0000:00:01.0:pcie03: allocate port service
[    0.585980] pcieport-driver 0000:00:1c.0: setting latency timer to 64
[    0.586052] pcieport-driver 0000:00:1c.0: found MSI capability
[    0.586128] pci_express 0000:00:1c.0:pcie00: allocate port service
[    0.586281] pci_express 0000:00:1c.0:pcie02: allocate port service
[    0.586443] pci_express 0000:00:1c.0:pcie03: allocate port service
[    0.587025] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[    0.587151] pciehp: HPC vendor_id 8086 device_id 2660 ss_vid 0 ss_did 0
[    0.587464] hpdriver 0000:00:1c.0:pcie02: service driver hpdriver loaded
[    0.587604] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
[    0.588241] vesafb: framebuffer at 0xd0000000, mapped to 0xf8880000, using 6144k, total 16384k
[    0.588244] vesafb: mode is 1024x768x16, linelength=2048, pages=9
[    0.588247] vesafb: protected mode interface info at c000:aeb4
[    0.588250] vesafb: pmi: set display start = c00caf42, set palette = c00caf82
[    0.588252] vesafb: scrolling: redraw
[    0.588255] vesafb: Truecolor: size=0:5:6:5, shift=0:11:5:0
[    0.589174] bootsplash 3.1.6-2004/03/31: looking for picture...<6> silentjpeg size 166113 bytes,<6>...found (1024x768, 154167 bytes, v3).
[    0.656058] Switched to high resolution mode on CPU 0
[    0.712265] Console: switching to colour frame buffer device 124x44
[    0.803749] fb0: VESA VGA frame buffer device
[    0.805484] ACPI: AC Adapter [AC] (off-line)
[    0.849071] ACPI: Battery Slot [BAT0] (battery present)
[    0.849595] input: Power Button (FF) as /class/input/input0
[    0.849625] ACPI: Power Button (FF) [PWRF]
[    0.849946] input: Lid Switch as /class/input/input1
[    0.851425] ACPI: Lid Switch [LID0]
[    0.851703] input: Sleep Button (CM) as /class/input/input2
[    0.851708] ACPI: Sleep Button (CM) [SLPB]
[    0.851967] input: Power Button (CM) as /class/input/input3
[    0.851971] ACPI: Power Button (CM) [PWB]
[    0.853482] ACPI: CPU0 (power states: C1[C1] C2[C2] C3[C3] C4[C3])
[    0.853730] processor ACPI0007:00: registered as cooling_device0
[    0.867413] thermal LNXTHERM:01: registered as thermal_zone0
[    0.873056] ACPI: Thermal Zone [THR0] (64 C)
[    0.882413] thermal LNXTHERM:02: registered as thermal_zone1
[    0.888444] ACPI: Thermal Zone [THR1] (58 C)
[    0.900370] Linux agpgart interface v0.103
[    0.900639] Serial: 8250/16550 driver4 ports, IRQ sharing disabled
[    0.902277] serial 0000:00:1e.3: PCI INT B -> GSI 20 (level, low) -> IRQ 20
[    0.902287] serial 0000:00:1e.3: PCI INT B disabled
[    0.908245] brd: module loaded
[    0.910959] loop: module loaded
[    0.911403] tifm_7xx1 0000:06:06.3: PCI INT A -> GSI 22 (level, low) -> IRQ 22
[    0.911833] PPP generic driver version 2.4.2
[    0.912219] PPP Deflate Compression module registered
[    0.918301] PPP MPPE Compression module registered
[    0.918306] NET: Registered protocol family 24
[    0.918419] 8139too Fast Ethernet driver 0.9.28
[    0.918451] 8139too 0000:06:07.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
[    0.919856] eth0: RealTek RTL8139 at 0xf8860400, 00:0a:e4:dd:8b:30, IRQ 20
[    0.919859] eth0:  Identified 8139 chip type 'RTL-8100B/8139D'
[    0.920169] usbcore: registered new interface driver cdc_ether
[    0.920309] usbcore: registered new interface driver rndis_host
[    0.920323] ipw2200: Intel(R) PRO/Wireless 2200/2915 Network Driver, 1.2.2kmr
[    0.920326] ipw2200: Copyright(c) 2003-2006 Intel Corporation
[    0.920689] ipw2200 0000:06:05.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
[    0.920759] ipw2200: Detected Intel PRO/Wireless 2200BG Network Connection
[    0.920935] firmware: using built-in firmware ipw2200-bss.fw
[    1.072625] ipw2200: Detected geography ZZR (14 802.11bg channels, 0 802.11a channels)
[    1.073030] Driver 'sd' needs updating - please use bus_type methods
[    1.073165] Driver 'sr' needs updating - please use bus_type methods
[    1.073554] ata_piix 0000:00:1f.1: version 2.12
[    1.073577] ata_piix 0000:00:1f.1: PCI INT A -> GSI 18 (level, low) -> IRQ 18
[    1.073772] ata_piix 0000:00:1f.1: setting latency timer to 64
[    1.073928] scsi0 : ata_piix
[    1.074305] scsi1 : ata_piix
[    1.075806] ata1: PATA max UDMA/100 cmd 0x1f0 ctl 0x3f6 bmdma 0x18c0 irq 14
[    1.075809] ata2: PATA max UDMA/100 cmd 0x170 ctl 0x376 bmdma 0x18c8 irq 15
[    1.264714] ata1.00: ATA-6: HTS721080G9AT00, MC4OA51A, max UDMA/100
[    1.264717] ata1.00: 156301488 sectors, multi 16: LBA48 
[    1.264741] ata1.01: ATAPI: TSSTcorpCD/DVDW TS-L532M, HR08, max MWDMA2
[    1.280639] ata1.00: configured for UDMA/100
[    1.312492] ata1.01: configured for MWDMA2
[    1.312547] ata2: port disabled. ignoring.
[    1.313121] scsi 0:0:0:0: Direct-Access     ATA      HTS721080G9AT00  MC4O PQ: 0 ANSI: 5
[    1.313878] sd 0:0:0:0: [sda] 156301488 512-byte hardware sectors (80026 MB)
[    1.313919] sd 0:0:0:0: [sda] Write Protect is off
[    1.313922] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[    1.313996] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    1.314470] sd 0:0:0:0: [sda] 156301488 512-byte hardware sectors (80026 MB)
[    1.314509] sd 0:0:0:0: [sda] Write Protect is off
[    1.314512] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[    1.314587] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    1.314605]  sda: sda1 sda2 sda3 sda4
[    1.333599] sd 0:0:0:0: [sda] Attached SCSI disk
[    1.334333] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    1.341141] scsi 0:0:1:0: CD-ROM            TSSTcorp CD/DVDW TS-L532M HR08 PQ: 0 ANSI: 5
[    1.350846] sr0: scsi3-mmc drive: 24x/24x writer cd/rw xa/form2 cdda tray
[    1.350850] Uniform CD-ROM driver Revision: 3.20
[    1.351413] sr 0:0:1:0: Attached scsi CD-ROM sr0
[    1.351755] sr 0:0:1:0: Attached scsi generic sg1 type 5
[    1.352218] firewire_ohci 0000:06:06.2: PCI INT C -> GSI 21 (level, low) -> IRQ 21
[    1.424013] firewire_ohci: Added fw-ohci device 0000:06:06.2, OHCI version 1.10
[    1.424616] Yenta: CardBus bridge found at 0000:06:06.0 [103c:309d]
[    1.424649] Yenta: Enabling burst memory read transactions
[    1.424658] Yenta: Using CSCINT to route CSC interrupts to PCI
[    1.424660] Yenta: Routing CardBus interrupts to PCI
[    1.424668] Yenta TI: socket 0000:06:06.0, mfunc 0x01aa1b02, devctl 0x64
[    1.657035] Yenta: ISA IRQ mask 0x0cf8, PCI irq 22
[    1.657039] Socket status: 30000006
[    1.657042] Yenta: Raising subordinate bus# of parent bus (#06) from #07 to #0a
[    1.657049] pcmcia: parent PCI bridge I/O window: 0x4000 - 0x4fff
[    1.657070] cs: IO port probe 0x4000-0x4fff: clean.
[    1.658321] pcmcia: parent PCI bridge Memory window: 0xc8200000 - 0xc82fffff
[    1.658325] pcmcia: parent PCI bridge Memory window: 0x88000000 - 0x8bffffff
[    1.912366] ehci_hcd 0000:00:1d.7: PCI INT A -> GSI 23 (level, low) -> IRQ 23
[    1.912382] ehci_hcd 0000:00:1d.7: setting latency timer to 64
[    1.912387] ehci_hcd 0000:00:1d.7: EHCI Host Controller
[    1.913132] ehci_hcd 0000:00:1d.7: new USB bus registered, assigned bus number 1
[    1.917106] ehci_hcd 0000:00:1d.7: debug port 1
[    1.917116] ehci_hcd 0000:00:1d.7: cache line size of 32 is not supported
[    1.917143] ehci_hcd 0000:00:1d.7: irq 23, io mem 0xc8000000
[    1.924536] firewire_core: created device fw0: GUID 05e40a003c175052, S400
[    1.932014] ehci_hcd 0000:00:1d.7: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
[    1.932439] usb usb1: configuration #1 chosen from 1 choice
[    1.932712] hub 1-0:1.0: USB hub found
[    1.932758] hub 1-0:1.0: 8 ports detected
[    2.140928] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    2.140932] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.140934] usb usb1: Product: EHCI Host Controller
[    2.140937] usb usb1: Manufacturer: Linux 2.6.27.8-00004-g1a27ee8 ehci_hcd
[    2.140939] usb usb1: SerialNumber: 0000:00:1d.7
[    2.141141] USB Universal Host Controller Interface driver v3.0
[    2.141192] uhci_hcd 0000:00:1d.0: PCI INT A -> GSI 23 (level, low) -> IRQ 23
[    2.141205] uhci_hcd 0000:00:1d.0: setting latency timer to 64
[    2.141210] uhci_hcd 0000:00:1d.0: UHCI Host Controller
[    2.141389] uhci_hcd 0000:00:1d.0: new USB bus registered, assigned bus number 2
[    2.141432] uhci_hcd 0000:00:1d.0: irq 23, io base 0x00001800
[    2.141863] usb usb2: configuration #1 chosen from 1 choice
[    2.142065] hub 2-0:1.0: USB hub found
[    2.142114] hub 2-0:1.0: 2 ports detected
[    2.244494] usb usb2: New USB device found, idVendor=1d6b, idProduct=0001
[    2.244497] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.244500] usb usb2: Product: UHCI Host Controller
[    2.244502] usb usb2: Manufacturer: Linux 2.6.27.8-00004-g1a27ee8 uhci_hcd
[    2.244505] usb usb2: SerialNumber: 0000:00:1d.0
[    2.244547] uhci_hcd 0000:00:1d.1: PCI INT B -> GSI 19 (level, low) -> IRQ 19
[    2.244560] uhci_hcd 0000:00:1d.1: setting latency timer to 64
[    2.244565] uhci_hcd 0000:00:1d.1: UHCI Host Controller
[    2.244761] uhci_hcd 0000:00:1d.1: new USB bus registered, assigned bus number 3
[    2.244818] uhci_hcd 0000:00:1d.1: irq 19, io base 0x00001820
[    2.245180] usb usb3: configuration #1 chosen from 1 choice
[    2.245375] hub 3-0:1.0: USB hub found
[    2.245398] hub 3-0:1.0: 2 ports detected
[    2.452508] usb usb3: New USB device found, idVendor=1d6b, idProduct=0001
[    2.452511] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.452514] usb usb3: Product: UHCI Host Controller
[    2.452516] usb usb3: Manufacturer: Linux 2.6.27.8-00004-g1a27ee8 uhci_hcd
[    2.452519] usb usb3: SerialNumber: 0000:00:1d.1
[    2.452557] uhci_hcd 0000:00:1d.2: PCI INT C -> GSI 18 (level, low) -> IRQ 18
[    2.452571] uhci_hcd 0000:00:1d.2: setting latency timer to 64
[    2.452576] uhci_hcd 0000:00:1d.2: UHCI Host Controller
[    2.452756] uhci_hcd 0000:00:1d.2: new USB bus registered, assigned bus number 4
[    2.452818] uhci_hcd 0000:00:1d.2: irq 18, io base 0x00001840
[    2.453190] usb usb4: configuration #1 chosen from 1 choice
[    2.453384] hub 4-0:1.0: USB hub found
[    2.453401] hub 4-0:1.0: 2 ports detected
[    2.556475] usb usb4: New USB device found, idVendor=1d6b, idProduct=0001
[    2.556479] usb usb4: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.556481] usb usb4: Product: UHCI Host Controller
[    2.556484] usb usb4: Manufacturer: Linux 2.6.27.8-00004-g1a27ee8 uhci_hcd
[    2.556486] usb usb4: SerialNumber: 0000:00:1d.2
[    2.556525] uhci_hcd 0000:00:1d.3: PCI INT D -> GSI 16 (level, low) -> IRQ 16
[    2.556538] uhci_hcd 0000:00:1d.3: setting latency timer to 64
[    2.556543] uhci_hcd 0000:00:1d.3: UHCI Host Controller
[    2.556729] uhci_hcd 0000:00:1d.3: new USB bus registered, assigned bus number 5
[    2.556784] uhci_hcd 0000:00:1d.3: irq 16, io base 0x00001860
[    2.557158] usb usb5: configuration #1 chosen from 1 choice
[    2.557352] hub 5-0:1.0: USB hub found
[    2.557380] hub 5-0:1.0: 2 ports detected
[    2.564021] usb 3-1: new full speed USB device using uhci_hcd and address 2
[    2.660484] usb usb5: New USB device found, idVendor=1d6b, idProduct=0001
[    2.660488] usb usb5: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.660490] usb usb5: Product: UHCI Host Controller
[    2.660493] usb usb5: Manufacturer: Linux 2.6.27.8-00004-g1a27ee8 uhci_hcd
[    2.660495] usb usb5: SerialNumber: 0000:00:1d.3
[    2.735153] usb 3-1: configuration #1 chosen from 1 choice
[    2.740217] usb 3-1: New USB device found, idVendor=03f0, idProduct=171d
[    2.740220] usb 3-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    2.740223] usb 3-1: Product: HP Integrated Module
[    2.740225] usb 3-1: Manufacturer: Broadcom Corp
[    2.740441] usbcore: registered new interface driver usblp
[    2.740447] Initializing USB Mass Storage driver...
[    2.740654] usbcore: registered new interface driver usb-storage
[    2.740660] USB Mass Storage support registered.
[    2.741035] usbcore: registered new interface driver usbserial
[    2.741171] usbserial: USB Serial support registered for generic
[    2.741428] usbcore: registered new interface driver usbserial_generic
[    2.741431] usbserial: USB Serial Driver core
[    2.741565] usbserial: USB Serial support registered for PocketPC PDA
[    2.741567] ipaq: USB PocketPC PDA driver v0.5
[    2.741797] usbcore: registered new interface driver ipaq
[    2.741933] usbserial: USB Serial support registered for pl2303
[    2.742127] usbcore: registered new interface driver pl2303
[    2.742129] pl2303: Prolific PL2303 USB to serial adaptor driver
[    2.742478] PNP: PS/2 Controller [PNP0303:PS2K,PNP0f13:PS2M] at 0x60,0x64 irq 1,12
[    2.748438] serio: i8042 KBD port at 0x60,0x64 irq 1
[    2.748462] serio: i8042 AUX port at 0x60,0x64 irq 12
[    2.748849] mice: PS/2 mouse device common for all mice
[    2.750850] rtc_cmos 00:05: rtc core: registered rtc_cmos as rtc0
[    2.750889] rtc0: alarms up to one month, y3k, hpet irqs
[    2.751042] iTCO_wdt: Intel TCO WatchDog Timer Driver v1.03 (30-Apr-2008)
[    2.770992] input: AT Translated Set 2 keyboard as /class/input/input4
[    2.771810] iTCO_wdt: Found a ICH6-M TCO device (Version=2, TCOBASE=0x1060)
[    2.771996] iTCO_wdt: initialized. heartbeat=30 sec (nowayout=0)
[    2.772262] device-mapper: ioctl: 4.14.0-ioctl (2008-04-23) initialised: dm-devel@redhat.com
[    2.773013] cpuidle: using governor ladder
[    2.774364] cpuidle: using governor menu
[    2.775470] Advanced Linux Sound Architecture Driver Version 1.0.17.
[    2.782441] Intel ICH 0000:00:1e.2: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[    2.782471] Intel ICH 0000:00:1e.2: setting latency timer to 64
[    2.784249] Marking TSC unstable due to TSC halts in idle
[    3.026821] input: PS/2 Mouse as /class/input/input5
[    3.044445] input: AlpsPS/2 ALPS GlidePoint as /class/input/input6
[    3.152022] Clocksource tsc unstable (delta = -355729302 ns)
[    3.684032] intel8x0_measure_ac97_clock: measured 55908 usecs
[    3.684035] intel8x0: measured clock 196 rejected
[    3.684037] intel8x0: clocking to 48000
[    3.687217] ALSA device list:
[    3.687219]   #0: Intel ICH6 with AD1981B at irq 17
[    3.688595] TCP cubic registered
[    3.688598] Initializing XFRM netlink socket
[    3.688633] NET: Registered protocol family 17
[    3.688670] NET: Registered protocol family 15
[    3.688679] ieee80211: 802.11 data/management/control stack, git-1.1.13
[    3.688681] ieee80211: Copyright (C) 2004-2005 Intel Corporation <jketreno@linux.intel.com>
[    3.688694] ieee80211_crypt: registered algorithm 'NULL'
[    3.688697] ieee80211_crypt: registered algorithm 'WEP'
[    3.688701] ieee80211_crypt: registered algorithm 'CCMP'
[    3.688704] ieee80211_crypt: registered algorithm 'TKIP'
[    3.689750] Using IPI Shortcut mode
[    3.704225] rtc_cmos 00:05: setting system clock to 2008-12-09 09:55:54 UTC (1228816554)
[    3.704531] Freeing unused kernel memory: 228k freed
[    4.876705] PM: Starting manual resume from disk
[    5.269767] kjournald starting.  Commit interval 5 seconds
[    5.270221] EXT3 FS on sda2, internal journal
[    5.270476] EXT3-fs: mounted filesystem with ordered data mode.
[    9.468577] cs: IO port probe 0x100-0x3af: excluding 0x200-0x20f
[    9.470914] cs: IO port probe 0x3e0-0x4ff: excluding 0x4d0-0x4d7
[    9.471971] cs: IO port probe 0x820-0x8ff: clean.
[    9.472875] cs: IO port probe 0xc00-0xcf7: clean.
[    9.474219] cs: IO port probe 0xa00-0xaff: clean.
[   10.252919] Adding 2104504k swap on /dev/sda3.  Priority:-1 extents:1 across:2104504k
[   12.904341] kjournald starting.  Commit interval 5 seconds
[   12.904747] EXT3 FS on sda4, internal journal
[   12.904773] EXT3-fs: mounted filesystem with ordered data mode.
[   14.955393] [drm] Initialized drm 1.1.0 20060810
[   15.007273] pci 0000:01:00.0: power state changed by ACPI to D0
[   15.014347] pci 0000:01:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[   15.021358] pci 0000:01:00.0: setting latency timer to 64
[   15.024551] [drm] Initialized radeon 1.29.0 20080528 on minor 0
[   31.693688] bootsplash: status on console 0 changed to on
[  170.968361] [drm] Setting GART location based on new memory map
[  170.969576] [drm] Loading R400 Microcode
[  170.969622] [drm] Num pipes: 2
[  170.969631] [drm] writeback test succeeded in 1 usecs
[  171.278529] evdev.c(EVIOCGBIT): Suspicious buffer size 511, limiting output to 64 bytes. See http://userweb.kernel.org/~dtor/eviocgbit-bug.html
[  317.381790] [drm] Num pipes: 2
[  318.127627] Syncing filesystems ... done.
[  318.128777] Freezing user space processes ... (elapsed 0.00 seconds) done.
[  318.130527] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done.
[  318.130759] PM: Shrinking memory... done (0 pages freed)
[  318.192195] PM: Freed 0 kbytes in 0.06 seconds (0.00 MB/s)
[  318.192198] Suspending console(s) (use no_console_suspend to debug)
[  318.193455] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[  318.226637] pciehp_suspend ENTRY
[  318.226977] ACPI handle has no context!
[  318.226996] tifm_7xx1 0000:06:06.3: PCI INT A disabled
[  318.227006] ACPI handle has no context!
[  318.240294] ACPI handle has no context!
[  318.256336] eth1: Going into suspend...
[  318.259286] ipw2200 0000:06:05.0: PCI INT A disabled
[  318.259297] ACPI handle has no context!
[  318.272394] ata2: port disabled. ignoring.
[  318.272477] ata_piix 0000:00:1f.1: PCI INT A disabled
[  318.272940] Intel ICH 0000:00:1e.2: PCI INT A disabled
[  318.273139] ehci_hcd 0000:00:1d.7: PCI INT A disabled
[  318.273210] uhci_hcd 0000:00:1d.3: PCI INT D disabled
[  318.273265] uhci_hcd 0000:00:1d.2: PCI INT C disabled
[  318.273320] uhci_hcd 0000:00:1d.1: PCI INT B disabled
[  318.273374] uhci_hcd 0000:00:1d.0: PCI INT A disabled
[  318.273389] pciehp_suspend ENTRY
[  318.273903] ACPI: Preparing to enter system sleep state S4
[  318.275933] PM: Creating hibernation image: 
[  318.276155] PM: Need to copy 130959 pages
[  318.276155] Intel machine check architecture supported.
[  318.276155] Intel machine check reporting enabled on CPU#0.
[  611.799546] Force enabled HPET at resume
[  611.799722] ACPI: Waking up from system sleep state S4
[  611.799819] ACPI: EC: non-query interrupt received, switching to interrupt mode
[  611.799819] pcieport-driver 0000:00:01.0: setting latency timer to 64
[  611.799819] pcieport-driver 0000:00:1c.0: setting latency timer to 64
[  611.799819] pciehp_resume ENTRY
[  611.799819] uhci_hcd 0000:00:1d.0: PCI INT A -> GSI 23 (level, low) -> IRQ 23
[  611.799819] uhci_hcd 0000:00:1d.0: setting latency timer to 64
[  611.799819] uhci_hcd 0000:00:1d.1: PCI INT B -> GSI 19 (level, low) -> IRQ 19
[  611.799819] uhci_hcd 0000:00:1d.1: setting latency timer to 64
[  611.799819] uhci_hcd 0000:00:1d.2: PCI INT C -> GSI 18 (level, low) -> IRQ 18
[  611.799819] uhci_hcd 0000:00:1d.2: setting latency timer to 64
[  611.799819] uhci_hcd 0000:00:1d.3: PCI INT D -> GSI 16 (level, low) -> IRQ 16
[  611.799819] uhci_hcd 0000:00:1d.3: setting latency timer to 64
[  611.799819] ehci_hcd 0000:00:1d.7: PCI INT A -> GSI 23 (level, low) -> IRQ 23
[  611.799819] ehci_hcd 0000:00:1d.7: setting latency timer to 64
[  611.799819] pci 0000:00:1e.0: setting latency timer to 64
[  611.799819] Intel ICH 0000:00:1e.2: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[  611.799819] Intel ICH 0000:00:1e.2: setting latency timer to 64
[  611.799819] ata_piix 0000:00:1f.1: restoring config space at offset 0x1 (was 0x2880001, writing 0x2880005)
[  611.799819] ata_piix 0000:00:1f.1: PCI INT A -> GSI 18 (level, low) -> IRQ 18
[  611.799819] ata_piix 0000:00:1f.1: setting latency timer to 64
[  611.799819] ata2: port disabled. ignoring.
[  611.799819] pci 0000:01:00.0: restoring config space at offset 0x1 (was 0x100103, writing 0x100107)
[  611.799819] pci 0000:01:00.0: power state changed by ACPI to D0
[  611.799819] pci 0000:01:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[  611.799819] pci 0000:01:00.0: setting latency timer to 64
[  611.799819] eth1: Coming out of suspend...
[  611.799819] ipw2200 0000:06:05.0: enabling device (0000 -> 0002)
[  611.799819] ipw2200 0000:06:05.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
[  611.799819] ipw2200 0000:06:05.0: restoring config space at offset 0xf (was 0x18030100, writing 0x1803010b)
[  611.799819] ipw2200 0000:06:05.0: restoring config space at offset 0x4 (was 0x0, writing 0xc8206000)
[  611.799819] ipw2200 0000:06:05.0: restoring config space at offset 0x3 (was 0x0, writing 0x8008)
[  611.799819] ipw2200 0000:06:05.0: restoring config space at offset 0x1 (was 0x2900002, writing 0x2900116)
[  611.799819] ata1.01: ACPI cmd ef/03:0c:00:00:00:b0 filtered out
[  611.799819] ata1.01: ACPI cmd ef/03:22:00:00:00:b0 filtered out
[  611.799819] ata1.00: ACPI cmd ef/03:0c:00:00:00:a0 filtered out
[  611.799819] ata1.00: ACPI cmd ef/03:45:00:00:00:a0 filtered out
[  611.799819] ata1.00: configured for UDMA/100
[  611.799819] ata1.01: configured for MWDMA2
[  611.799819] sd 0:0:0:0: [sda] 156301488 512-byte hardware sectors (80026 MB)
[  611.799819] sd 0:0:0:0: [sda] Write Protect is off
[  611.799819] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[  611.799819] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[  611.799819] sd 0:0:0:0: [sda] 156301488 512-byte hardware sectors (80026 MB)
[  611.799819] sd 0:0:0:0: [sda] Write Protect is off
[  611.799819] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[  611.799819] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[  611.799819] firewire_ohci 0000:06:06.2: restoring config space at offset 0xf (was 0x4020300, writing 0x402030b)
[  611.799819] firewire_ohci 0000:06:06.2: restoring config space at offset 0x5 (was 0x0, writing 0xc8200000)
[  611.799819] firewire_ohci 0000:06:06.2: restoring config space at offset 0x4 (was 0x0, writing 0xc8208000)
[  611.799819] firewire_ohci 0000:06:06.2: restoring config space at offset 0x3 (was 0x800000, writing 0x808008)
[  611.799819] firewire_ohci 0000:06:06.2: restoring config space at offset 0x1 (was 0x2100000, writing 0x2100116)
[  611.799819] tifm_7xx1 0000:06:06.3: restoring config space at offset 0xf (was 0x40701ff, writing 0x407010a)
[  611.799819] tifm_7xx1 0000:06:06.3: restoring config space at offset 0x4 (was 0x0, writing 0xc8204000)
[  611.799819] tifm_7xx1 0000:06:06.3: restoring config space at offset 0x3 (was 0x800000, writing 0x808008)
[  611.799819] tifm_7xx1 0000:06:06.3: restoring config space at offset 0x1 (was 0x2100000, writing 0x2100106)
[  611.799819] tifm_7xx1 0000:06:06.3: PCI INT A -> GSI 22 (level, low) -> IRQ 22
[  611.799819] pciehp_resume ENTRY
[  611.799819] sd 0:0:0:0: [sda] Starting disk
[  611.799819] Restarting tasks ... done.
[  611.799819] [drm] Loading R400 Microcode
[  611.799819] [drm] Num pipes: 2
[  611.799819] evdev.c(EVIOCGBIT): Suspicious buffer size 511, limiting output to 64 bytes. See http://userweb.kernel.org/~dtor/eviocgbit-bug.html
[  611.799819] [drm] Num pipes: 2
[  611.799819] Syncing filesystems ... done.
[  611.799819] Freezing user space processes ... (elapsed 0.00 seconds) done.
[  611.799819] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done.
[  611.799819] PM: Shrinking memory... done (0 pages freed)
[  611.799819] PM: Freed 0 kbytes in 0.06 seconds (0.00 MB/s)
[  611.799819] Suspending console(s) (use no_console_suspend to debug)
[  611.799819] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[  611.799819] pciehp_suspend ENTRY
[  611.799819] ACPI handle has no context!
[  611.799819] tifm_7xx1 0000:06:06.3: PCI INT A disabled
[  611.799819] ACPI handle has no context!
[  611.799819] ACPI handle has no context!
[  611.799819] eth1: Going into suspend...
[  611.799819] ipw2200 0000:06:05.0: PCI INT A disabled
[  611.799819] ACPI handle has no context!
[  611.799819] ata2: port disabled. ignoring.
[  611.799819] ata_piix 0000:00:1f.1: PCI INT A disabled
[  611.799819] Intel ICH 0000:00:1e.2: PCI INT A disabled
[  611.799819] ehci_hcd 0000:00:1d.7: PCI INT A disabled
[  611.799819] uhci_hcd 0000:00:1d.3: PCI INT D disabled
[  611.799819] uhci_hcd 0000:00:1d.2: PCI INT C disabled
[  611.799819] uhci_hcd 0000:00:1d.1: PCI INT B disabled
[  611.799819] uhci_hcd 0000:00:1d.0: PCI INT A disabled
[  611.799819] pciehp_suspend ENTRY
[  611.799819] ACPI: Preparing to enter system sleep state S4
[  611.799819] PM: Creating hibernation image: 
[  611.799819] PM: Need to copy 131763 pages
[  611.799819] Intel machine check architecture supported.
[  611.799819] Intel machine check reporting enabled on CPU#0.
[  629.991434] Force enabled HPET at resume
[  629.991559] ACPI: Waking up from system sleep state S4
[  629.991607] ACPI: EC: non-query interrupt received, switching to interrupt mode
[  629.991607] pcieport-driver 0000:00:01.0: setting latency timer to 64
[  629.991607] pcieport-driver 0000:00:1c.0: setting latency timer to 64
[  629.991607] pciehp_resume ENTRY
[  629.991607] uhci_hcd 0000:00:1d.0: PCI INT A -> GSI 23 (level, low) -> IRQ 23
[  629.991607] uhci_hcd 0000:00:1d.0: setting latency timer to 64
[  629.991607] uhci_hcd 0000:00:1d.1: PCI INT B -> GSI 19 (level, low) -> IRQ 19
[  629.991607] uhci_hcd 0000:00:1d.1: setting latency timer to 64
[  629.991607] uhci_hcd 0000:00:1d.2: PCI INT C -> GSI 18 (level, low) -> IRQ 18
[  629.991607] uhci_hcd 0000:00:1d.2: setting latency timer to 64
[  629.991607] uhci_hcd 0000:00:1d.3: PCI INT D -> GSI 16 (level, low) -> IRQ 16
[  629.991607] uhci_hcd 0000:00:1d.3: setting latency timer to 64
[  629.991607] ehci_hcd 0000:00:1d.7: PCI INT A -> GSI 23 (level, low) -> IRQ 23
[  629.991607] ehci_hcd 0000:00:1d.7: setting latency timer to 64
[  629.991607] pci 0000:00:1e.0: setting latency timer to 64
[  629.991607] Intel ICH 0000:00:1e.2: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[  629.991607] Intel ICH 0000:00:1e.2: setting latency timer to 64
[  629.991607] ata_piix 0000:00:1f.1: restoring config space at offset 0x1 (was 0x2880001, writing 0x2880005)
[  629.991607] ata_piix 0000:00:1f.1: PCI INT A -> GSI 18 (level, low) -> IRQ 18
[  629.991607] ata_piix 0000:00:1f.1: setting latency timer to 64
[  629.991607] ata2: port disabled. ignoring.
[  629.991607] pci 0000:01:00.0: restoring config space at offset 0x1 (was 0x100103, writing 0x100107)
[  629.991607] pci 0000:01:00.0: power state changed by ACPI to D0
[  629.991607] pci 0000:01:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[  629.991607] pci 0000:01:00.0: setting latency timer to 64
[  629.991607] eth1: Coming out of suspend...
[  629.991607] ipw2200 0000:06:05.0: enabling device (0000 -> 0002)
[  629.991607] ipw2200 0000:06:05.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
[  629.991607] ipw2200 0000:06:05.0: restoring config space at offset 0xf (was 0x18030100, writing 0x1803010b)
[  629.991607] ipw2200 0000:06:05.0: restoring config space at offset 0x4 (was 0x0, writing 0xc8206000)
[  629.991607] ipw2200 0000:06:05.0: restoring config space at offset 0x3 (was 0x0, writing 0x8008)
[  629.991607] ipw2200 0000:06:05.0: restoring config space at offset 0x1 (was 0x2900002, writing 0x2900116)
[  629.991607] ata1.01: ACPI cmd ef/03:0c:00:00:00:b0 filtered out
[  629.991607] ata1.01: ACPI cmd ef/03:22:00:00:00:b0 filtered out
[  629.991607] ata1.00: ACPI cmd ef/03:0c:00:00:00:a0 filtered out
[  629.991607] ata1.00: ACPI cmd ef/03:45:00:00:00:a0 filtered out
[  629.991607] ata1.00: configured for UDMA/100
[  629.991607] ata1.01: configured for MWDMA2
[  629.991607] sd 0:0:0:0: [sda] 156301488 512-byte hardware sectors (80026 MB)
[  629.991607] sd 0:0:0:0: [sda] Write Protect is off
[  629.991607] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[  629.991607] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[  629.991607] sd 0:0:0:0: [sda] 156301488 512-byte hardware sectors (80026 MB)
[  629.991607] sd 0:0:0:0: [sda] Write Protect is off
[  629.991607] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[  629.991607] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[  629.991607] firewire_ohci 0000:06:06.2: restoring config space at offset 0xf (was 0x4020300, writing 0x402030b)
[  629.991607] firewire_ohci 0000:06:06.2: restoring config space at offset 0x5 (was 0x0, writing 0xc8200000)
[  629.991607] firewire_ohci 0000:06:06.2: restoring config space at offset 0x4 (was 0x0, writing 0xc8208000)
[  629.991607] firewire_ohci 0000:06:06.2: restoring config space at offset 0x3 (was 0x800000, writing 0x808008)
[  629.991607] firewire_ohci 0000:06:06.2: restoring config space at offset 0x1 (was 0x2100000, writing 0x2100116)
[  629.991607] tifm_7xx1 0000:06:06.3: restoring config space at offset 0xf (was 0x40701ff, writing 0x407010a)
[  629.991607] tifm_7xx1 0000:06:06.3: restoring config space at offset 0x4 (was 0x0, writing 0xc8204000)
[  629.991607] tifm_7xx1 0000:06:06.3: restoring config space at offset 0x3 (was 0x800000, writing 0x808008)
[  629.991607] tifm_7xx1 0000:06:06.3: restoring config space at offset 0x1 (was 0x2100000, writing 0x2100106)
[  629.991607] tifm_7xx1 0000:06:06.3: PCI INT A -> GSI 22 (level, low) -> IRQ 22
[  629.991607] pciehp_resume ENTRY
[  629.991607] sd 0:0:0:0: [sda] Starting disk
[  629.991607] Restarting tasks ... done.
[  629.991607] [drm] Loading R400 Microcode
[  629.991607] [drm] Num pipes: 2
[  629.991607] evdev.c(EVIOCGBIT): Suspicious buffer size 511, limiting output to 64 bytes. See http://userweb.kernel.org/~dtor/eviocgbit-bug.html
Comment 17 Tejun Heo 2008-12-09 23:09:00 UTC
Fabio, in the log, the 5min delay seemed to happen way before ATA is asked to resume.

[  318.276155] Intel machine check architecture supported.
[  318.276155] Intel machine check reporting enabled on CPU#0.
[  611.799546] Force enabled HPET at resume
[  611.799722] ACPI: Waking up from system sleep state S4
[  611.799819] ACPI: EC: non-query interrupt received, switching to interrupt mode

ATA part didn't cause any problem in the reported dmesg.  Rafael, can you please help here?  It seems like we're seeing two separate resume related issues.
Comment 18 Zhang Rui 2008-12-09 23:50:57 UTC
right, two problems here.

Problem 1, long latency when resuming from disk.
Problem 2, suspend to disk failed after two successful try.

Fabio, can you verify if the first problem can be reproduced in 2.6.27.8 or the latest 2.6.28-rc release?
Comment 19 Fabio Comolli 2008-12-10 00:25:09 UTC
(In reply to comment #18)
> right, two problems here.
> 
> Problem 1, long latency when resuming from disk.
> Problem 2, suspend to disk failed after two successful try.
> 
> Fabio, can you verify if the first problem can be reproduced in 2.6.27.8 or the
> latest 2.6.28-rc release?
> 

Well, it seems that there is some communication problem between me and you kernel developers. Sorry about that but I'm not an English native speaker and probably I didn't make myself clear enough. Let's try to summarize.

The system _never_ had problems during resume. It always resumed correctly.

The main problem is that after a successful resume from disk, when userspace has already been up and running (i.e. I am usually able to unlock my gnome session), sometimes the system freezes for about 4-5 minutes.

After that the laptop usually "revives" (I don't known how to explain differently, sorry). It usually does it without printing anything in the logs (post #16 is an example of that). Tejun, the delay before the HPET line is present in every hibernate/resume cycle, good or bad.

Only two times there were some lines in the logs that pointed to ATA, as in post #10 quoted by Zhang Rui. In this post you can see that ATA froze _after_ userspace was done, i.e. after the line "Restarting tasks: done".

Only once  ATA did not come back and the disk was gone. My rootfs journal aborted and my laptop was totally unusable. I had to powercycle it and go through a full fsck. Of course, I don't have logs for this, I just read those information from a dmesg command output.

Let's try to summarize the facts so far:

* the latency problem after resume (after, not during) is present with every stable release between 2.6.27.5 and 2.6.27.8 included. It never happened with .4;
* it's present in every 2.6.28-rc I tried and it's also present in current mainline;
* it's also present if I use Tuxonice instead of in-kernel hibernation;
* it can be reproduced with and without fglrx / cisco_ipsec binary only modules (without fglrx the kernel was compiled to support my radeon card and the xorg.conf file has been modified accordingly);
* my hard disk survived a smartctl -t long test without problems;
* windows on the same laptop (dual boot) does not show the problem and a full hd test that I ran on Windows completed succesfullly.

The log in post #14 is in my opinion a separate issue as the system refused to suspend; this happened only once and I did not want to lose those information.

If something is not clear enough, please ask.

Thanks to all of you for your time,
Fabio


Comment 20 Rafael J. Wysocki 2008-12-10 01:46:15 UTC
OK, so we'll have to go back to the differences between .27.4 and .27.5 and see which commit could potentially cause the problem to appear for you.
Comment 21 Rafael J. Wysocki 2008-12-10 01:52:12 UTC
Created attachment 19239 [details]
Changes committed between 2.6.27.4 and 2.6.27.5

Attached is a log of changes between 2.6.27.4 and 2.6.27.5.

Fabio, your last comment indicates that one of these changes caused the problem to appear on your system and, IIRC, you verified that it wasn't one of the ACPI EC changes.  Unfortunately, I don't see which of the other changes can potentially make the difference for you.  Perhaps the other people looking at this bug will find it.

Quite frankly, I think that carrying out bisection of these changes would be the fastest way to identify the guilty commit.  That's only 59 changes, so you'll need 6 or 5 kernel compilations to do that.
Comment 22 Fabio Comolli 2008-12-10 05:00:49 UTC
Rafael,
I already tried bisection twice. With two different results.
The problem is that the bug is not always present so it's easy to mark as "good" a kernel that isn't good at all.
I can try a third bisection but quite frankly I don't have any idea how to decide that a kernel is good other than see if it survives a dozen hibernate/resume cycles.
If no one comes with an idea tonight I will try another bisection session.
Comment 23 Fabio Comolli 2008-12-11 13:54:38 UTC
Hi all.
I'm almost finished with my bisection session. The log so far says:

fcomolli@hawking:~/software/GIT-TREES/linux-2.6.27.y> git bisect log
git-bisect start
# good: [056c71459d3acf9fefcb2dc67abeef10e649d508] Linux 2.6.27.4
git-bisect good 056c71459d3acf9fefcb2dc67abeef10e649d508
# bad: [788a5f3f70e2a9c46020bdd3a195f2a866441c5d] Linux 2.6.27.5
git-bisect bad 788a5f3f70e2a9c46020bdd3a195f2a866441c5d
# good: [7bdb542c453c14e54af9ebe5c4a827e4a678c47d] powerpc/numa: Make memory reserve code more robust
git-bisect good 7bdb542c453c14e54af9ebe5c4a827e4a678c47d
# bad: [dcfdc4faa0dbe2aa4c68a43c79dc7eb630788351] x86: register a platform RTC device if PNP doesn't describe it
git-bisect bad dcfdc4faa0dbe2aa4c68a43c79dc7eb630788351
# good: [3fc8395149818a686df0ec8c4da5397a645ffe8a] DVB: s5h1411: Perform s5h1411 soft reset after tuning
git-bisect good 3fc8395149818a686df0ec8c4da5397a645ffe8a
# bad: [5e55aa8db085dad1aabb4574c73c23c7ae571e7b] sched_clock: prevent scd->clock from moving backwards
git-bisect bad 5e55aa8db085dad1aabb4574c73c23c7ae571e7b

I decide to mark a release as "good" if it survived a minimum of 10 hibernate/resume cycles on a two-day span. Usually a bad release fails before reaching a count of 4.

The release I'm currently testing is 2.6.27.4-00038-gf20f02a; its count is now at 7. I'll mark it as good probably tomorrow.

Quite frankly, I'm 99% certain that the bad commit is:

[5e55aa8db085dad1aabb4574c73c23c7ae571e7b] sched_clock: prevent scd->clock from moving backwards

but of course I may very well be wrong.

Any comments?
Comment 24 Rafael J. Wysocki 2008-12-12 14:27:23 UTC
Commit 5e55aa8db085dad1aabb4574c73c23c7ae571e7b has already been fingered as the guilty one in bug #12149, but the reporter in there said the problem wasn't reproducible with the mainline.

Your comment #19 means that it _is_ present in the mainline too, though.  Can you just try to revert that commit and see if the problem goes away?
Comment 25 Fabio Comolli 2008-12-13 00:17:01 UTC
Created attachment 19270 [details]
Output of the git bisect log command.
Comment 26 Fabio Comolli 2008-12-13 00:17:44 UTC
(In reply to comment #24)
> Commit 5e55aa8db085dad1aabb4574c73c23c7ae571e7b has already been fingered as
> the guilty one in bug #12149, but the reporter in there said the problem wasn't
> reproducible with the mainline.
> 
> Your comment #19 means that it _is_ present in the mainline too, though.

Very much so.

> Can you just try to revert that commit and see if the problem goes away?
> 

I'm finishing my tests with 2.6.27.8 with the guilty commit reverted. If all goes well I'll post my results here and begin testing 2.6.28-rc8.

For complete reference, I'm attaching the output of my git-bisect-log.
Comment 27 Rafael J. Wysocki 2008-12-13 10:02:56 UTC
Notify-Also : Dave Kleikamp <shaggy@linux.vnet.ibm.com>
Comment 28 Fabio Comolli 2008-12-13 10:46:39 UTC
Both kernel with the commit reverted seem to work fine so far. 
Comment 29 Rafael J. Wysocki 2008-12-13 10:52:56 UTC
Caused by:

commit 5e55aa8db085dad1aabb4574c73c23c7ae571e7b
Author: Dave Kleikamp <shaggy@linux.vnet.ibm.com>
Date:   Sun Oct 26 18:20:14 2008 -0400

    sched_clock: prevent scd->clock from moving backwards

    Signed-off-by: Dave Kleikamp <shaggy@linux.vnet.ibm.com>
    Acked-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
    Signed-off-by: Ingo Molnar <mingo@elte.hu>
    Cc: Chuck Ebbert <cebbert@redhat.com>
    Signed-off-by: Greg Kroah-Hartman <gregkh@suse.de>
Comment 30 Rafael J. Wysocki 2008-12-13 10:53:25 UTC
First-Bad-Commit : 5e55aa8db085dad1aabb4574c73c23c7ae571e7b
Comment 31 Dave Kleikamp 2008-12-14 15:20:02 UTC
Comment #14 of bug #12149 seems to shed some light on why my patch caused the regression.  I don't have time to dig into it now, but I'll take a look at it Monday.  I think it's best to revert the patch for now and figure out a more complete solution later.
Comment 32 Zhang Rui 2008-12-14 17:57:44 UTC
move this bug out of acpi category. :)
Comment 34 Thomas Gleixner 2008-12-22 15:27:14 UTC
Not fixed, just papered over the real problem.
See http://lkml.org/lkml/2008/12/22/192 ...
Comment 35 Frank Groeneveld 2008-12-28 07:30:47 UTC
I'm experiencing the same problem with my Intel Atom 330 (Dual Core cpu). Anything I can do to help?
Comment 36 Fabio Comolli 2008-12-28 07:39:45 UTC
Hi Frank.
Well, for me v2.6.28 and v2.6.27.10 are ok because they both have the "bad" commit reverted. Thomas reopened the bug in post 34, please see the lkml post in that comment.

v2.6.28-rc9 with that patch applied also is ok for me.

Please try vanilla 2.6.28 and 2.6.28 with that patch applied and report back to Thomas and Rafael.
Comment 37 Frank Groeneveld 2008-12-28 07:45:32 UTC
Well, for 2.6.28 without any patching this bug occurs on my system. What patch are you talking about? Do you want me to revert this:
 
> I digged more in the bugzillas. Toralf added some debug to
> __update_sched_clock():
> 
> -       max_clock = wrap_max(scd->clock, scd->tick_gtod + TICK_NSEC);
> +       max_clock = scd->tick_gtod + TICK_NSEC;
> +       if (scd->clock > max_clock)
> +               printk(KERN_INFO "%d %d\n", scd->clock, max_clock);

Or something else?
Comment 38 Rafael J. Wysocki 2009-01-11 10:35:35 UTC
On Sunday 11 January 2009, Fabio Comolli wrote:
> It's been solved in 2.6.28-final and backported to 2.6.27.10 (a revert
> of a Dave Kelikamp's commit).
> 
> On Sun, Jan 11, 2009 at 12:41 PM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> > This message has been generated automatically as a part of a report
> > of regressions introduced between 2.6.27 and 2.6.28.
> >
> > The following bug entry is on the current list of known regressions
> > introduced between 2.6.27 and 2.6.28.  Please verify if it still should
> > be listed and let me know (either way).
> >
> >
> > Bug-Entry       : http://bugzilla.kernel.org/show_bug.cgi?id=12155
> > Subject         : Regression in 2.6.28-rc and 2.6.27-stable - hibernate related
> > Submitter       : Fabio Comolli <fabio.comolli@gmail.com>
> > Date            : 2008-11-23 16:17 (50 days old)

Comment 39 Rafael J. Wysocki 2009-01-11 10:39:55 UTC
Fixed by commit 1c5745aa380efb6417b5681104b007c8612fb496 .

Note You need to log in before you can comment on or make changes to this bug.