My Thinkpad X40 (1.25 GB, ipw2200) has had fairly reliable swsusp since
2.6.13 or thereabouts, and as recently as 2.6.15-rc1-mm1 I had about 20
successful suspend/resume cycles.  But now that I'm running
2.6.15-rc3-mm1 I'm seeing intermittent failures like this:

...
[17212376.112000] Suspending device 0000:00:00.0
[17212376.112000] Suspending device pci0000:00
[17212376.112000] Suspending device platform
[17212376.112000] cpufreq: suspend failed to assert current frequency is what timing core thinks it is.
[17212376.112000] ................................................................................................swsusp: Need to copy 120410 pages
[17212376.112000] sh: page allocation failure. order:0, mode:0x8120
[17212376.112000]  [__alloc_pages+572/816] __alloc_pages+0x23c/0x330
[17212376.112000]  [get_zeroed_page+39/80] get_zeroed_page+0x27/0x50
[17212376.112000]  [alloc_data_pages+201/208] alloc_data_pages+0xc9/0xd0
[17212376.112000]  [swsusp_alloc+63/128] swsusp_alloc+0x3f/0x80
[17212376.112000]  [swsusp_save+55/144] swsusp_save+0x37/0x90
[17212376.112000]  [swsusp_arch_suspend+42/44] swsusp_arch_suspend+0x2a/0x2c
[17212376.112000]  [swsusp_suspend+72/176] swsusp_suspend+0x48/0xb0
[17212376.112000]  [pm_suspend_disk+85/176] pm_suspend_disk+0x55/0xb0
[17212376.112000]  [enter_state+141/176] enter_state+0x8d/0xb0
[17212376.112000]  [state_store+146/158] state_store+0x92/0x9e
[17212376.112000]  [subsys_attr_store+61/80] subsys_attr_store+0x3d/0x50
[17212376.112000]  [flush_write_buffer+62/80] flush_write_buffer+0x3e/0x50
[17212376.112000]  [sysfs_write_file+84/128] sysfs_write_file+0x54/0x80
[17212376.112000]  [vfs_write+233/432] vfs_write+0xe9/0x1b0
[17212376.112000]  [sys_write+81/128] sys_write+0x51/0x80
[17212376.112000]  [sysenter_past_esp+84/117] sysenter_past_esp+0x54/0x75

(The "suspend failed to assert current frequency..." messages have been
present since .14 or somesuch, and don't seem to have any deleterious
effects.)

This has happened 3 times so far, always on the second suspend after
boot.  (boot, suspend, resume, suspend <fails>).  Once it's failed I
have not managed to get it to succeed; attempting to suspend again
results in the same failure.  But on my most recent boot I have not been
able to get it to fail through 4 suspend-resume cycles.

I suspend with a shell script that does

sudo sh -c 'echo shutdown > /sys/power/disk; echo disk > /sys/power/state'

On one of the failing cases I looked at memory usage and did not see
anything remarkable; there was about 400 MB free.

Full dmesg from failure below, and .config attached.

-andy

[17212374.240000] Stopping tasks: ===============================================================|
[17212374.252000] Shrinking memory...  ^H-^H\^H|^H/^H-^H\^H|^H/^H-^H\^H|^Hdone (188889 pages freed)
[17212375.900000] Suspending device 1-1:unknown codec
[17212375.900000] Suspending device 0-0:AD1981B
[17212375.900000] Suspending device 4-0:1.0
[17212375.900000] Suspending device usb4
[17212375.900000] Suspending device 3-0:1.0
[17212375.900000] Suspending device usb3
[17212375.900000] Suspending device 2-0:1.0
[17212375.900000] Suspending device usb2
[17212375.900000] Suspending device 1-0:1.0
[17212375.900000] Suspending device usb1
[17212375.900000] Suspending device 0.0
[17212375.900000] Suspending device ide0
[17212375.900000] Suspending device serio1
[17212375.900000] Suspending device serio0
[17212375.900000] Suspending device serial8250
[17212375.900000] Suspending device i8042
[17212375.900000] Suspending device 0000:02:02.0
[17212375.900000] Suspending device 0000:02:01.0
[17212376.080000] ACPI: PCI interrupt for device 0000:02:01.0 disabled
[17212376.096000] Suspending device 0000:02:00.1
[17212376.096000] Suspending device 0000:02:00.0
[17212376.096000] ACPI: PCI interrupt for device 0000:02:00.0 disabled
[17212376.096000] Suspending device 0000:00:1f.6
[17212376.096000] ACPI: PCI interrupt for device 0000:00:1f.6 disabled
[17212376.096000] Suspending device 0000:00:1f.5
[17212376.096000] ACPI: PCI interrupt for device 0000:00:1f.5 disabled
[17212376.096000] Suspending device 0000:00:1f.3
[17212376.096000] Suspending device 0000:00:1f.1
[17212376.096000] Suspending device 0000:00:1f.0
[17212376.096000] Suspending device 0000:00:1e.0
[17212376.096000] Suspending device 0000:00:1d.7
[17212376.096000] ACPI: PCI interrupt for device 0000:00:1d.7 disabled
[17212376.112000] Suspending device 0000:00:1d.2
[17212376.112000] ACPI: PCI interrupt for device 0000:00:1d.2 disabled
[17212376.112000] Suspending device 0000:00:1d.1
[17212376.112000] ACPI: PCI interrupt for device 0000:00:1d.1 disabled
[17212376.112000] Suspending device 0000:00:1d.0
[17212376.112000] ACPI: PCI interrupt for device 0000:00:1d.0 disabled
[17212376.112000] Suspending device 0000:00:02.1
[17212376.112000] Suspending device 0000:00:02.0
[17212376.112000] Suspending device 0000:00:00.3
[17212376.112000] Suspending device 0000:00:00.1
[17212376.112000] Suspending device 0000:00:00.0
[17212376.112000] Suspending device pci0000:00
[17212376.112000] Suspending device platform
[17212376.112000] cpufreq: suspend failed to assert current frequency is what timing core thinks it is.
[17212376.112000] ................................................................................................swsusp: Need to copy 120410 pages
[17212376.112000] sh: page allocation failure. order:0, mode:0x8120
[17212376.112000]  [__alloc_pages+572/816] __alloc_pages+0x23c/0x330
[17212376.112000]  [get_zeroed_page+39/80] get_zeroed_page+0x27/0x50
[17212376.112000]  [alloc_data_pages+201/208] alloc_data_pages+0xc9/0xd0
[17212376.112000]  [swsusp_alloc+63/128] swsusp_alloc+0x3f/0x80
[17212376.112000]  [swsusp_save+55/144] swsusp_save+0x37/0x90
[17212376.112000]  [swsusp_arch_suspend+42/44] swsusp_arch_suspend+0x2a/0x2c
[17212376.112000]  [swsusp_suspend+72/176] swsusp_suspend+0x48/0xb0
[17212376.112000]  [pm_suspend_disk+85/176] pm_suspend_disk+0x55/0xb0
[17212376.112000]  [enter_state+141/176] enter_state+0x8d/0xb0
[17212376.112000]  [state_store+146/158] state_store+0x92/0x9e
[17212376.112000]  [subsys_attr_store+61/80] subsys_attr_store+0x3d/0x50
[17212376.112000]  [flush_write_buffer+62/80] flush_write_buffer+0x3e/0x50
[17212376.112000]  [sysfs_write_file+84/128] sysfs_write_file+0x54/0x80
[17212376.112000]  [vfs_write+233/432] vfs_write+0xe9/0x1b0
[17212376.112000]  [sys_write+81/128] sys_write+0x51/0x80
[17212376.112000]  [sysenter_past_esp+84/117] sysenter_past_esp+0x54/0x75
[17212376.112000] Mem-info:
[17212376.112000] DMA per-cpu:
[17212376.112000] cpu 0 hot: high 12, batch 2 used:0
[17212376.112000] cpu 0 cold: high 4, batch 1 used:0
[17212376.112000] DMA32 per-cpu: empty
[17212376.112000] Normal per-cpu:
[17212376.112000] cpu 0 hot: high 384, batch 64 used:0
[17212376.112000] cpu 0 cold: high 128, batch 32 used:0
[17212376.112000] HighMem per-cpu:
[17212376.112000] cpu 0 hot: high 384, batch 64 used:0
[17212376.112000] cpu 0 cold: high 128, batch 32 used:0
[17212376.112000] Free pages:      279928kB (274968kB HighMem)
[17212376.112000] Active:19941 inactive:41880 dirty:0 writeback:0 unstable:0 free:69982 slab:47006 mapped:19466 pagetables: 230
[17212376.112000] DMA free:3548kB min:68kB low:84kB high:100kB active:4kB inactive:8kB present:16384kB pages_scanned:0 all_unreclaimable? no
[17212376.112000] lowmem_reserve[]: 0 0 880 1254
[17212376.112000] DMA32 free:0kB min:0kB low:0kB high:0kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no
[17212376.112000] lowmem_reserve[]: 0 0 880 1254
[17212376.112000] Normal free:1412kB min:3756kB low:4692kB high:5632kB active:0kB inactive:140676kB present:901120kB pages_scanned:0 all_unreclaimable? no
[17212376.112000] lowmem_reserve[]: 0 0 0 2999
[17212376.112000] HighMem free:274968kB min:372kB low:772kB high:1172kB active:79760kB inactive:26836kB present:383872kB pages_scanned:0 all_unreclaimable? no
[17212376.112000] lowmem_reserve[]: 0 0 0 0
[17212376.112000] DMA: 1*4kB 1*8kB 1*16kB 0*32kB 1*64kB 1*128kB 1*256kB 0*512kB 1*1024kB 1*2048kB 0*4096kB = 3548kB
[17212376.112000] DMA32: empty
[17212376.112000] Normal: 1*4kB 0*8kB 0*16kB 0*32kB 0*64kB 1*128kB 1*256kB 0*512kB 1*1024kB 0*2048kB 0*4096kB = 1412kB
[17212376.112000] HighMem: 2130*4kB 1170*8kB 720*16kB 398*32kB 184*64kB 91*128kB 60*256kB 37*512kB 15*1024kB 16*2048kB 31*4096kB = 274968kB
[17212376.112000] Swap cache: add 0, delete 0, find 0/0, race 0+0
[17212376.112000] Free swap  = 500432kB
[17212376.112000] Total swap = 500432kB
[17212376.112000] Free swap:       500432kB
[17212376.112000] 325344 pages of RAM
[17212376.112000] 95968 pages of HIGHMEM
[17212376.112000] 3657 reserved pages
[17212376.112000] 65501 pages shared
[17212376.112000] 0 pages swap cached
[17212376.112000] 0 pages dirty
[17212376.112000] 0 pages writeback
[17212376.112000] 19466 pages mapped
[17212376.112000] 47006 pages slab
[17212376.112000] 230 pages pagetables
[17212376.112000] suspend: Allocating image pages failed.
[17212376.112000] Error -12 suspending
[17212376.112000] Intel machine check architecture supported.
[17212376.112000] Intel machine check reporting enabled on CPU#0.
[17212376.112000] swsusp: Restoring Highmem
[17212376.112000] cpufreq: resume failed to assert current frequency is what timing core thinks it is.
[17212379.120000] ACPI: PCI Interrupt 0000:00:02.0[A] -> GSI 16 (level, low) -> IRQ 169
[17212379.120000] ACPI: PCI Interrupt 0000:00:1d.0[A] -> GSI 16 (level, low) -> IRQ 169
[17212379.120000] PCI: Setting latency timer of device 0000:00:1d.0 to 64
[17212379.120000] ACPI: PCI Interrupt 0000:00:1d.1[B] -> GSI 19 (level, low) -> IRQ 193
[17212379.120000] PCI: Setting latency timer of device 0000:00:1d.1 to 64
[17212379.120000] ACPI: PCI Interrupt 0000:00:1d.2[C] -> GSI 18 (level, low) -> IRQ 185
[17212379.120000] PCI: Setting latency timer of device 0000:00:1d.2 to 64
[17212379.140000] PCI: Enabling device 0000:00:1d.7 (0000 -> 0002)
[17212379.140000] ACPI: PCI Interrupt 0000:00:1d.7[D] -> GSI 23 (level, low) -> IRQ 201
[17212379.140000] PCI: Setting latency timer of device 0000:00:1d.7 to 64
[17212379.140000] usb usb4: root hub lost power or was reset
[17212379.144000] ehci_hcd 0000:00:1d.7: debug port 1
[17212379.144000] PCI: cache line size of 32 is not supported by device 0000:00:1d.7
[17212379.148000] ehci_hcd 0000:00:1d.7: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
[17212379.148000] PCI: Setting latency timer of device 0000:00:1e.0 to 64
[17212379.148000] ACPI: PCI Interrupt 0000:00:1f.1[A] -> GSI 18 (level, low) -> IRQ 185
[17212379.148000] ACPI: PCI Interrupt 0000:00:1f.5[B] -> GSI 17 (level, low) -> IRQ 177
[17212379.148000] PCI: Setting latency timer of device 0000:00:1f.5 to 64
[17212379.400000] ACPI: PCI Interrupt 0000:00:1f.6[B] -> GSI 17 (level, low) -> IRQ 177
[17212379.400000] PCI: Setting latency timer of device 0000:00:1f.6 to 64
[17212380.404000] ACPI: PCI Interrupt 0000:02:00.0[A] -> GSI 16 (level, low) -> IRQ 169
[17212380.456000] ACPI: PCI Interrupt 0000:02:01.0[A] -> GSI 20 (level, low) -> IRQ 209
[17212381.244000] Restarting tasks... done