#11867 HIGH 12.1.0: occasional failure to wake from sleep using rtcwake
Zarro Boogs per Child
bugtracker at laptop.org
Wed May 16 21:49:05 EDT 2012
#11867: occasional failure to wake from sleep using rtcwake
--------------------+-------------------------------------------------------
Reporter: Quozl | Owner:
Type: defect | Status: new
Priority: high | Milestone: 12.1.0
Component: kernel | Version: Development build as of this date
Keywords: | Next_action: never set
Verified: 0 | Deployment_affected:
Blockedby: | Blocking:
--------------------+-------------------------------------------------------
symptom: after being directed to sleep for 240 seconds, the laptop does
not wake at the expected time, but can be woken by keyboard activity.
frequency: very low, twice in 24 hour runin. also seen in #10757 testing.
only seen on units with the slow toshiba microsd.
impact: prevents successful manufacturing runin test.
(powerd should not be affected, since other wake sources iwll generally
occur ... such as battery state of charge change.)
XO-1.5 12.1.0 os10
Output from sus.log, came from runin-sus:
{{{
res: 1337131338 : 1502.09 : Cycle: 1 Duration: 254s
res: 1337132784 : 2949.05 : Cycle: 2 Duration: 241s
res: 1337134245 : 4409.13 : Cycle: 3 Duration: 248s
res: 1337135713 : 5877.31 : Cycle: 4 Duration: 253s
res: 1337137170 : 7335.05 : Cycle: 5 Duration: 244s
res: 1337138637 : 8801.67 : Cycle: 6 Duration: 245s
res: 1337140082 : 10246.96 : Cycle: 7 Duration: 241s
res: 1337141552 : 11716.19 : Cycle: 8 Duration: 251s
res: 1337143020 : 13184.13 : Cycle: 9 Duration: 248s
res: 1337144484 : 14648.14 : Cycle: 10 Duration: 244s
res: 1337145944 : 16108.10 : Cycle: 11 Duration: 249s
res: 1337147401 : 17566.22 : Cycle: 12 Duration: 250s
res: 1337148848 : 19012.57 : Cycle: 13 Duration: 242s
res: 1337150304 : 20468.99 : Cycle: 14 Duration: 244s
res: 1337151750 : 21914.10 : Cycle: 15 Duration: 241s
res: 1337153215 : 23379.21 : Cycle: 16 Duration: 248s
res: 1337207314 : 77478.20 : Cycle: 17 Duration: 52888s
res: 1337208774 : 78939.04 : Cycle: 18 Duration: 246s
res: 1337213997 : 84161.16 : Cycle: 19 Duration: 4017s
res: 1337215479 : 85644.12 : Cycle: 20 Duration: 246s
}}}
Unaffected cycle 16 began here (''VIA DMA timeout! '' lines removed):
{{{
<6>[21045.388102] PM: Syncing filesystems ...
<3>[21102.310026] olpc-ec: timeout waiting for EC to read command!
<3>[21102.430420] power_supply olpc-battery: driver failed to report
`capacity' property: 4294967291
<4>[21102.742954] hpet1: lost 1 rtc interrupts
<4>[21103.152177] hpet1: lost 1 rtc interrupts
<4>[21104.026367] hpet1: lost 1 rtc interrupts
<4>[21160.538686] done.
<7>[21160.540769] PM: Preparing system for mem sleep
<4>[21160.540792] Freezing user space processes ...
<4>[21166.150231] hpet1: lost 1 rtc interrupts
<4>[21170.980102] (elapsed 10.43 seconds) done.
<4>[21170.984259] Freezing remaining freezable tasks ... (elapsed 0.01
seconds) done.
<7>[21171.002774] PM: Entering mem sleep
<6>[21171.003284] dcon_source_switch to DCON
<6>[21171.038906] olpc-dcon: The DCON has control
<6>[21171.043785] i8042 kbd 00:04: wake-up capability enabled by ACPI
<6>[21171.050182] i8042 aux 00:03: wake-up capability disabled by ACPI
<7>[21171.057428] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<6>[21171.058470] libertas_sdio mmc1:0001:1: mmc1:0001:1: suspend: PM
flags = 0x3
<4>[21171.065607] viafb_suspend!
<6>[21171.069217] libertas_sdio mmc1:0001:1: Suspend without wake params
-- powering down card
<6>[21171.090797] mmc1: card 0001 removed
<7>[21171.094421] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[21171.095445] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[21171.096521] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<6>[21171.180070] PM: suspend of devices complete after 176.904 msecs
<6>[21171.186464] ehci_hcd 0000:00:10.4: wake-up capability enabled by
ACPI
<6>[21171.210099] uhci_hcd 0000:00:10.2: wake-up capability enabled by
ACPI
<6>[21171.230095] uhci_hcd 0000:00:10.1: wake-up capability enabled by
ACPI
<6>[21171.250094] uhci_hcd 0000:00:10.0: wake-up capability enabled by
ACPI
<6>[21171.270316] PM: late suspend of devices complete after 84.262 msecs
<6>[21171.276790] ACPI: Preparing to enter system sleep state S3
<6>[21171.380103] PM: Saving platform NVS memory
<6>[21171.380103] ACPI: Low-level resume complete
<6>[21171.380103] PM: Restoring platform NVS memory
<6>[21171.380103] ACPI: Waking up from system sleep state S3
<6>[21171.410123] uhci_hcd 0000:00:10.0: wake-up capability disabled by
ACPI
<6>[21171.430103] uhci_hcd 0000:00:10.1: wake-up capability disabled by
ACPI
<6>[21171.450103] uhci_hcd 0000:00:10.2: wake-up capability disabled by
ACPI
<6>[21171.470109] ehci_hcd 0000:00:10.4: wake-up capability disabled by
ACPI
<6>[21171.477122] PM: early resume of devices complete after 86.730 msecs
<6>[21171.483751] viafb_resume!
<6>[21171.486858] viafb_resume: Init 3d engine!
<7>[21171.491154] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[21171.491193] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[21171.491212] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[21171.491234] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[21171.491251] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[21171.491272] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<4>[21171.501356] usb usb2: root hub lost power or was reset
<4>[21171.501420] usb usb3: root hub lost power or was reset
<4>[21171.501477] usb usb4: root hub lost power or was reset
<7>[21171.501625] pci 0000:00:13.0: setting latency timer to 64
<6>[21171.552957] i8042 kbd 00:04: wake-up capability disabled by ACPI
<4>[21171.961312] dcon_source_switch to CPU
<6>[21171.965144] PM: resume of devices complete after 481.558 msecs
<7>[21171.972296] PM: Finishing wakeup.
<4>[21171.972304] Restarting tasks ...
<6>[21171.996258] olpc-dcon: The CPU has control
<4>[21172.087766] done.
<7>[21172.146239] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[21172.211522] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[21172.274157] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[21172.344826] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<6>[21172.485021] mmc1: new SDIO card at address 0001
}}}
Affected cycle 17 looks like this:
{{{
<6>[22511.070953] PM: Syncing filesystems ...
<4>[22544.497663] hpet1: lost 1 rtc interrupts
<4>[22544.916356] hpet1: lost 1 rtc interrupts
<4>[22545.313836] hpet1: lost 1 rtc interrupts
<4>[22545.729357] hpet1: lost 1 rtc interrupts
<4>[22545.729357] hpet1: lost 1 rtc interrupts
<4>[22613.009868] hpet1: lost 1 rtc interrupts
<4>[22613.265259] done.
<7>[22613.267207] PM: Preparing system for mem sleep
<4>[22613.267231] Freezing user space processes ...
<4>[22615.499932] hpet1: lost 1 rtc interrupts
<4>[22627.970101] (elapsed 14.69 seconds) done.
<4>[22627.974239] Freezing remaining freezable tasks ... (elapsed 0.01
seconds) done.
<7>[22627.992744] PM: Entering mem sleep
<6>[22627.993264] dcon_source_switch to DCON
<6>[22628.023962] olpc-dcon: The DCON has control
<6>[22628.028745] i8042 kbd 00:04: wake-up capability enabled by ACPI
<6>[22628.035337] i8042 aux 00:03: wake-up capability disabled by ACPI
<7>[22628.042614] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<6>[22628.043654] libertas_sdio mmc1:0001:1: mmc1:0001:1: suspend: PM
flags = 0x3
<4>[22628.050856] viafb_suspend!
<6>[22628.054474] libertas_sdio mmc1:0001:1: Suspend without wake params
-- powering down card
<6>[22628.070759] mmc1: card 0001 removed
<7>[22628.074365] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[22628.075390] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[22628.076468] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<6>[22628.170071] PM: suspend of devices complete after 176.926 msecs
<6>[22628.176521] ehci_hcd 0000:00:10.4: wake-up capability enabled by
ACPI
<6>[22628.200100] uhci_hcd 0000:00:10.2: wake-up capability enabled by
ACPI
<6>[22628.220095] uhci_hcd 0000:00:10.1: wake-up capability enabled by
ACPI
<6>[22628.240095] uhci_hcd 0000:00:10.0: wake-up capability enabled by
ACPI
<6>[22628.260316] PM: late suspend of devices complete after 84.206 msecs
<6>[22628.266822] ACPI: Preparing to enter system sleep state S3
<6>[22628.370097] PM: Saving platform NVS memory
<6>[22628.370097] ACPI: Low-level resume complete
<6>[22628.370097] PM: Restoring platform NVS memory
<6>[22628.370097] ACPI: Waking up from system sleep state S3
<6>[22628.400126] uhci_hcd 0000:00:10.0: wake-up capability disabled by
ACPI
<6>[22628.420104] uhci_hcd 0000:00:10.1: wake-up capability disabled by
ACPI
<6>[22628.440102] uhci_hcd 0000:00:10.2: wake-up capability disabled by
ACPI
<6>[22628.460109] ehci_hcd 0000:00:10.4: wake-up capability disabled by
ACPI
<6>[22628.467100] PM: early resume of devices complete after 86.685 msecs
<6>[22628.473680] viafb_resume!
<6>[22628.476836] viafb_resume: Init 3d engine!
<7>[22628.481125] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[22628.481164] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[22628.481182] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[22628.481204] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[22628.481221] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[22628.481242] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<4>[22628.491326] usb usb2: root hub lost power or was reset
<4>[22628.491389] usb usb3: root hub lost power or was reset
<4>[22628.491447] usb usb4: root hub lost power or was reset
<7>[22628.491594] pci 0000:00:13.0: setting latency timer to 64
<6>[22628.530715] i8042 kbd 00:04: wake-up capability disabled by ACPI
<4>[22628.951310] dcon_source_switch to CPU
<6>[22628.955091] PM: resume of devices complete after 481.573 msecs
<7>[22628.962271] PM: Finishing wakeup.
<4>[22628.962279] Restarting tasks ...
<6>[22628.985106] olpc-dcon: The CPU has control
<4>[22629.023188] done.
<7>[22629.080288] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[22629.145716] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[22629.216869] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<7>[22629.294055] sdhci-pci 0000:00:0c.0: setting latency timer to 64
<6>[22629.391650] mmc1: new SDIO card at address 0001
<7>[22630.631029] olpc-ec: debugfs cmd 0x3b with 1 args 00 40 d2 b2 e9,
want 0 returns
<3>[22630.640019] olpc-ec: timeout waiting for EC accept data!
<3>[22630.683568] olpc-ec: timeout waiting for EC to quiesce!
<3>[22630.738551] power_supply olpc-battery: driver failed to report
`present' property: 4294967291
<3>[22630.760022] olpc-ec: timeout waiting for EC to quiesce!
<3>[22630.788557] power_supply olpc-battery: driver failed to report
`status' property: 4294967291
<7>[22630.812259] olpc-ec: response 00 00 00 00 00 00 00 00 (0 bytes
expected)
<3>[22630.820026] olpc-ec: timeout waiting for EC to quiesce!
<3>[22630.848397] power_supply olpc-battery: driver failed to report
`capacity' property: 4294967291
}}}
My gut feel is that synchronising the filesystem and completing suspend
exceeds the wakeup time set by rtcwake.
--
Ticket URL: <http://dev.laptop.org/ticket/11867>
One Laptop Per Child <http://laptop.org/>
OLPC bug tracking system
More information about the Bugs
mailing list