[OLPC-devel] Thoughts on S3 resume.

Fri Aug 11 13:52:11 EDT 2006

On Fri, Aug 11, 2006 at 07:25:00AM +0100, Matthew Garrett wrote:
> and the hardware actually suspending. This doesn't give us any 
> information about where it's blocking - that's going to require more 
> debugging code sprinkled through acpi_enter_sleep_state_prep and 
> acpi_enter_sleep_state in drivers/acpi/hardware/hwsleep.c . It's 
> possible that it's the BIOS being insanely slow, or alternatively it 
> could be Linux just behaving oddly. In any case, it might give us a clue 
> as to why
> 
> > [   24.524549] Back to C!
> 
> takes so long.

Thanks, log attached.  Here's the relevant part, around hwsleep.c:328:

[  209.855951] Set PM1{A,B}control
[  209.855981] ACPI_FLUSH_CPU_CACHE() complete
[   24.545169] Write SLP_TYP/SLP_EN PM1A, status = 0
[   24.545201] Write SLP_TYP/SLP_EN PM1B, status = 0

> > [   24.653027] platform i8042: resuming
> > [   26.914341] Restarting tasks... done
> > [   26.950518] Thawing cpus ...
> 
> Driver resume takes about 10msec. We then sit around for 250msec while 
> not much seems to happen, then

Looks like we misread this; it's 2.25s, not 0.25s, so would be good to
know what's happening here.

> around 40 or so to get userspace running again. Doesn't look like the 
> bottleneck is going to be in the driver code.

Still need to test the wireless driver, though.

- Chris.
-- 
Chris Ball   <cjb at mrao.cam.ac.uk>    <http://blog.printf.net/>
-------------- next part --------------
# busybox lsmod
Module                  Size  Used by    Not tainted
# busybox echo -n "mem" > /sys/power/state
[  209.436424] PM: Preparing system for mem sleep
[  209.485649] Freezing cpus ...
[  209.503777] Stopping tasks: =======|
[  209.527247] In acpi_enter_sleep_state_prep
[  209.552426] Called acpi_get_sleep_type_data, status = 0
[  209.694977] Called _PTS method, status = 0
[  209.720010] Called _GTS method, status = 5
[  209.822992] Called _STS method, status = 0
[  209.847990] platform i8042: suspend
[  209.848025] serial8250 serial8250: suspend
[  209.848134] vesafb vesafb.0: suspend
[  209.848164] platform pcspkr: suspend
[  209.848191] pnp 00:04: suspend
[  209.848217] pnp 00:03: suspend
[  209.848242] pnp 00:02: suspend
[  209.848267] pnp 00:01: suspend
[  209.848292] pnp 00:00: suspend
[  209.848320] pci 0000:00:0f.5: suspend
[  209.849184] pci 0000:00:0f.4: suspend
[  209.850028] pci 0000:00:0f.3: suspend
[  209.850676] pci 0000:00:0f.2: suspend
[  209.851325] pci 0000:00:0f.0: suspend
[  209.852049] pci 0000:00:01.1: suspend
[  209.852804] pci 0000:00:01.0: suspend
[  209.853453] acpi acpi: suspend
[  209.853492] PM: Entering mem sleep
[  209.853695] In acpi_enter_sleep_state, sleep_state = 3
[  209.855622] Disable/cleared all GPEs, status = 0
[  209.855651] Enabled all wakeup GPEs, status = 0
[  209.855925] Fill in SLP_TYP data, status = 0
[  209.855951] Set PM1{A,B}control
[  209.855981] ACPI_FLUSH_CPU_CACHE() complete
[   24.545169] Write SLP_TYP/SLP_EN PM1A, status = 0
[   24.545201] Write SLP_TYP/SLP_EN PM1B, status = 0
[   24.545292] Back to C!
[   24.546386] BUG: sleeping function called from invalid context at include/asm
/semaphore.h:99
[   24.546426] in_atomic():0, irqs_disabled():1
[   24.548298]  [<c04051ee>] show_trace_log_lvl+0x58/0x159
[   24.548640]  [<c0405802>] show_trace+0xd/0x10
[   24.548946]  [<c040591b>] dump_stack+0x19/0x1b
[   24.549253]  [<c041de7f>] __might_sleep+0x8d/0x95
[   24.550255]  [<c05038ec>] acpi_os_wait_semaphore+0x55/0xb2
[   24.556016]  [<c05198ae>] acpi_ut_acquire_mutex+0x39/0x77
[   24.562228]  [<c0511d4d>] acpi_ns_get_node+0x42/0x84
[   24.568268]  [<c0511690>] acpi_ns_evaluate+0x2c/0xf4
[   24.574284]  [<c051550a>] acpi_rs_set_srs_method_data+0xc3/0xde
[   24.580410]  [<c0514e5d>] acpi_set_current_resources+0x2e/0x39
[   24.586524]  [<c051cea7>] acpi_pci_link_set+0xfb/0x1a1
[   24.592840]  [<c051cf98>] irqrouter_resume+0x4b/0x62
[   24.599161]  [<c054bdde>] __sysdev_resume+0x14/0x57
[   24.606432]  [<c054bf56>] sysdev_resume+0x19/0x4b
[   24.613704]  [<c05505a2>] device_power_up+0x8/0xf
[   24.621144]  [<c0443e17>] suspend_enter+0x3f/0x5e
[   24.623041]  [<c0443f93>] enter_state+0x15d/0x1c3
[   24.624940]  [<c044407f>] state_store+0x86/0x9c
[   24.626823]  [<c04a8eb0>] subsys_attr_store+0x20/0x25
[   24.630600]  [<c04a8fb4>] sysfs_write_file+0xab/0xd1
[   24.634398]  [<c0472297>] vfs_write+0xab/0x157
[   24.637186]  [<c04728dc>] sys_write+0x3b/0x60
[   24.639994]  [<c0403faf>] syscall_call+0x7/0xb
[   24.640273] DWARF2 unwinder stuck at syscall_call+0x7/0xb
[   24.640299] Leftover inexact backtrace:
[   24.640321]  [<c0405802>] show_trace+0xd/0x10
[   24.640366]  [<c040591b>] dump_stack+0x19/0x1b
[   24.640407]  [<c041de7f>] __might_sleep+0x8d/0x95
[   24.640451]  [<c05038ec>] acpi_os_wait_semaphore+0x55/0xb2
[   24.640499]  [<c05198ae>] acpi_ut_acquire_mutex+0x39/0x77
[   24.640545]  [<c0511d4d>] acpi_ns_get_node+0x42/0x84
[   24.640592]  [<c0511690>] acpi_ns_evaluate+0x2c/0xf4
[   24.640634]  [<c051550a>] acpi_rs_set_srs_method_data+0xc3/0xde
[   24.640685]  [<c0514e5d>] acpi_set_current_resources+0x2e/0x39
[   24.640732]  [<c051cea7>] acpi_pci_link_set+0xfb/0x1a1
[   24.640778]  [<c051cf98>] irqrouter_resume+0x4b/0x62
[   24.640820]  [<c054bdde>] __sysdev_resume+0x14/0x57
[   24.640872]  [<c054bf56>] sysdev_resume+0x19/0x4b
[   24.640914]  [<c05505a2>] device_power_up+0x8/0xf
[   24.640960]  [<c0443e17>] suspend_enter+0x3f/0x5e
[   24.641013]  [<c0443f93>] enter_state+0x15d/0x1c3
[   24.641050]  [<c044407f>] state_store+0x86/0x9c
[   24.641086]  [<c04a8eb0>] subsys_attr_store+0x20/0x25
[   24.641132]  [<c04a8fb4>] sysfs_write_file+0xab/0xd1
[   24.641172]  [<c0472297>] vfs_write+0xab/0x157
[   24.641221]  [<c04728dc>] sys_write+0x3b/0x60
[   24.641262]  [<c0403faf>] syscall_call+0x7/0xb
[   24.665222] PM: Finishing wakeup.
[   24.665830] acpi acpi: resuming
[   24.665875] pci 0000:00:01.0: resuming
[   24.666510] pci 0000:00:01.1: resuming
[   24.667227] pci 0000:00:0f.0: resuming
[   24.667850] pci 0000:00:0f.2: resuming
[   24.668466] pci 0000:00:0f.3: resuming
[   24.669082] pci 0000:00:0f.4: resuming
[   24.669883] pci 0000:00:0f.5: resuming
[   24.670604] pnp 00:00: resuming
[   24.670631] pnp 00:01: resuming
[   24.670656] pnp 00:02: resuming
[   24.670680] pnp 00:03: resuming
[   24.670705] pnp 00:04: resuming
[   24.670730] platform pcspkr: resuming
[   24.670757] vesafb vesafb.0: resuming
[   24.670785] serial8250 serial8250: resuming
[   24.671029] platform i8042: resuming
[   27.230174] Restarting tasks... done
[   27.252449] Thawing cpus ...
#