-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On Friday, 2012-07-06 at 14:57 +0100, Dave Howorth wrote:
Ugh! Yet more function calls.
Yet more printk I suppose :(
Yes... I compiled them already, a few there and a few more in dpm_prepare(). /** * dpm_prepare - Prepare all non-sysdev devices for a system PM transition. * @state: PM transition of the system being carried out. * * Execute the ->prepare() callback(s) for all devices. */ static int dpm_prepare(pm_message_t state) { struct list_head list; int error = 0; printk(KERN_INFO "I was here: 5.0\n"); INIT_LIST_HEAD(&list); printk(KERN_INFO "I was here: 5.1\n"); mutex_lock(&dpm_list_mtx); printk(KERN_INFO "I was here: 5.2\n"); transition_started = true; while (!list_empty(&dpm_list)) { struct device *dev = to_device(dpm_list.next); get_device(dev); dev->power.status = DPM_PREPARING; mutex_unlock(&dpm_list_mtx); pm_runtime_get_noresume(dev); if (pm_runtime_barrier(dev) && device_may_wakeup(dev)) { /* Wake-up requested during system sleep transition. */ pm_runtime_put_sync(dev); error = -EBUSY; } else { error = device_prepare(dev, state); } mutex_lock(&dpm_list_mtx); if (error) { dev->power.status = DPM_ON; if (error == -EAGAIN) { put_device(dev); error = 0; continue; } printk(KERN_ERR "PM: Failed to prepare device %s " "for power transition: error %d\n", kobject_name(&dev->kobj), error); put_device(dev); break; } dev->power.status = DPM_SUSPENDING; if (!list_empty(&dev->power.entry)) list_move_tail(&dev->power.entry, &list); put_device(dev); } printk(KERN_INFO "I was here: 5.10\n"); list_splice(&list, &dpm_list); printk(KERN_INFO "I was here: 5.11\n"); mutex_unlock(&dpm_list_mtx); return error; } /** * dpm_suspend_start - Prepare devices for PM transition and suspend them. * @state: PM transition of the system being carried out. * * Prepare all non-sysdev devices for system PM transition and execute "suspend" * callbacks for them. */ int dpm_suspend_start(pm_message_t state) { int error; printk(KERN_INFO "I was here: 4.0\n"); might_sleep(); printk(KERN_INFO "I was here: 4.1\n"); error = dpm_prepare(state); printk(KERN_INFO "I was here: 4.2\n"); if (!error) error = dpm_suspend(state); printk(KERN_INFO "I was here: 4.3\n"); return error; } EXPORT_SYMBOL_GPL(dpm_suspend_start); I haven't hibernated yet... I'll try now. [...] Done two cycles, no crash. Got two photos for comparison to the logs. I will also mark in this sucessfull log the point of failure in the failed session I posted earlier. http://susepaste.org/70504465 http://susepaste.org/25591075 <5.4> 2012-07-06 19:51:27 Telcontar pm-utils - - - Hibernating (1)... <5.4> 2012-07-06 19:51:29 Telcontar pm-utils - - - Hibernating (95)... These are markers I put in the scripts. <5.4> 2012-07-06 19:51:33 Telcontar router - - - (Thawing 1) Logging the current IP= 83.37.57.120 <0.7> 2012-07-06 19:51:34 Telcontar kernel - - - [ 787.702275] PM: Marking nosave pages: 000000000009f000 - 0000000000100000 <0.7> 2012-07-06 19:51:34 Telcontar kernel - - - [ 787.702280] PM: Marking nosave pages: 00000000bff90000 - 0000000100000000 <0.7> 2012-07-06 19:51:34 Telcontar kernel - - - [ 787.702907] PM: Basic memory bitmaps created <0.4> 2012-07-06 19:51:35 Telcontar kernel - - - [ 788.398380] Syncing filesystems ... done. <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.014785] Freezing user space processes ... (elapsed 0.01 seconds) done. <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.027339] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done. <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.039878] I was here: 1.0 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.040392] I was here: 1.1 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.040908] I was here: 1.2 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.041424] I was here: 2.0 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.041927] I was here: 2.1 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.042427] PM: Preallocating image memory... done (allocated 718651 pages) <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.321245] PM: Allocated 2874604 kbytes in 0.27 seconds (10646.68 MB/s) <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.321730] I was here: 2.2 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.322233] I was here: 2.3 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.322720] I was here: 2.4 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.323203] I was here: 4.0 <== dpm_suspend_start() <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.323679] I was here: 4.1 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.324161] I was here: 5.0 <== dpm_prepare() <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.324637] I was here: 5.1 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.325111] I was here: 5.2 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.325877] I was here: 5.10 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.326094] I was here: 5.11 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.326519] I was here: 4.2 <0.5> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.327314] sd 5:0:1:0: [sdd] Synchronizing SCSI cache <0.5> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.327333] sd 5:0:0:0: [sdc] Synchronizing SCSI cache <0.5> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.327428] sd 4:0:1:0: [sdb] Synchronizing SCSI cache <0.5> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.327437] sd 4:0:0:0: [sda] Synchronizing SCSI cache <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.327641] i8042 kbd 00:08: wake-up capability enabled by ACPI <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.327833] serial 00:06: disabled Is that the serial port being disabled? <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.328067] HDA Intel 0000:03:00.0: PCI INT A disabled <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.328069] pata_jmicron 0000:05:00.1: PCI INT B disabled <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.328079] [drm] nouveau 0000:01:00.0: Disabling fbcon acceleration... <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.328081] [drm] nouveau 0000:01:00.0: Unpinning framebuffer(s)... <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.328120] [drm] nouveau 0000:01:00.0: Evicting buffers... <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.328125] ACPI handle has no context! <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.328268] ahci 0000:04:00.0: PCI INT A disabled <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.328392] ata_piix 0000:00:1f.5: PCI INT B disabled <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.328524] ahci 0000:05:00.0: PCI INT A disabled <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.328619] pata_jmicron 0000:04:00.1: PCI INT B disabled <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.329045] ACPI handle has no context! <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.350337] [drm] nouveau 0000:01:00.0: Idling channels... <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.350521] [drm] nouveau 0000:01:00.0: Suspending GPU objects... <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.453240] ata_piix 0000:00:1f.2: PCI INT B disabled <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.794931] [drm] nouveau 0000:01:00.0: And we're gone! At this point, as can be seen in a video, the process stops for about 3 seconds. Then the display blinks, and lines start appearing again, but not from that exact point, but earlier (around 4.2). The line above "And we're gone!" is in the photo. Then it starts with things about the ata, which doesn't show in the log below. Instead of the "4.3" point, the photo shows "2.0, 2.9, 1.3, 1.4, and back to s2disk (steps 1.3) Suspicion: the next part of the log might be from restore cycle, in the middle of messages of the hibernation cycle. Section not in the photo. <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.796287] PM: freeze of devices complete after 469.327 msecs <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.796290] I was here: 4.3 <=== end of "dpm_suspend_start()". <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.796292] I was here: 2.5 <=== hibernation_snapshot() <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.796851] PM: late freeze of devices complete after 0.557 msecs <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.796854] Disabling non-boot CPUs ... <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.810385] CPU 1 is now offline <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.826253] CPU 2 is now offline <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.842112] CPU 3 is now offline <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.842116] SMP alternatives: switching to UP code <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.846997] PM: Creating hibernation image: <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.847000] PM: Need to copy 718329 pages <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.847000] PM: Normal pages needed: 718329 + 1024, available pages: 1378451 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.847000] microcode: CPU0 updated to revision 0xa0b, date = 2010-09-28 <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.847000] Enabling non-boot CPUs ... <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.848017] SMP alternatives: switching to SMP code <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.852554] Booting Node 0 Processor 1 APIC 0x1 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.955229] NMI watchdog enabled, takes one hw-pmu counter. <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.956266] microcode: CPU1 updated to revision 0xa0b, date = 2010-09-28 <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.962017] CPU1 is up <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 789.962197] Booting Node 0 Processor 2 APIC 0x2 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.065373] NMI watchdog enabled, takes one hw-pmu counter. <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.066467] microcode: CPU2 updated to revision 0xa0b, date = 2010-09-28 <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.071055] CPU2 is up <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.071241] Booting Node 0 Processor 3 APIC 0x3 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.174467] NMI watchdog enabled, takes one hw-pmu counter. <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.175554] microcode: CPU3 updated to revision 0xa0b, date = 2010-09-28 <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.180016] CPU3 is up <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.182044] pci 0000:00:00.0: restoring config space at offset 0x1 (was 0x20900006, writing 0x900006) <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.182457] ata_piix 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b00003, writing 0x2b00007) <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.182496] ata_piix 0000:00:1f.5: restoring config space at offset 0x1 (was 0x2b00003, writing 0x2b00007) <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.182628] HDA Intel 0000:03:00.0: restoring config space at offset 0x1 (was 0x2900006, writing 0x2900002) <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.182680] ahci 0000:04:00.0: restoring config space at offset 0x1 (was 0x100003, writing 0x100007) <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.182736] pata_jmicron 0000:04:00.1: restoring config space at offset 0x1 (was 0x100001, writing 0x100005) <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.182787] ahci 0000:05:00.0: restoring config space at offset 0x1 (was 0x100003, writing 0x100007) <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.182842] pata_jmicron 0000:05:00.1: restoring config space at offset 0x1 (was 0x100001, writing 0x100005) <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.182890] r8169 0000:06:00.0: restoring config space at offset 0x1 (was 0x100007, writing 0x100407) <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.182959] r8169 0000:07:00.0: restoring config space at offset 0x1 (was 0x100007, writing 0x100407) <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.183162] PM: early restore of devices complete after 1.176 msecs <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.183186] I was here: 2.6 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.308754] I was here: 2.7 <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.308923] uhci_hcd 0000:00:1a.0: setting latency timer to 64 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.308927] pci 0000:00:06.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16 <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.308930] pci 0000:00:06.0: setting latency timer to 64 <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.308936] uhci_hcd 0000:00:1a.1: setting latency timer to 64 <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.308976] usb usb4: root hub lost power or was reset <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.308978] usb usb3: root hub lost power or was reset <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.308992] uhci_hcd 0000:00:1a.2: setting latency timer to 64 <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.308994] ehci_hcd 0000:00:1a.7: setting latency timer to 64 <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309027] usb usb5: root hub lost power or was reset <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309045] pci 0000:00:1c.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17 <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309051] pci 0000:00:1c.0: setting latency timer to 64 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309058] pci 0000:00:1c.2: PCI INT C -> GSI 18 (level, low) -> IRQ 18 <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309064] pci 0000:00:1c.2: setting latency timer to 64 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309071] pci 0000:00:1c.3: PCI INT D -> GSI 19 (level, low) -> IRQ 19 <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309073] usb usb1: root hub lost power or was reset <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309079] pci 0000:00:1c.3: setting latency timer to 64 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309087] pci 0000:00:1c.4: PCI INT A -> GSI 17 (level, low) -> IRQ 17 <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309092] pci 0000:00:1c.4: setting latency timer to 64 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309099] pci 0000:00:1c.5: PCI INT B -> GSI 16 (level, low) -> IRQ 16 <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309104] pci 0000:00:1c.5: setting latency timer to 64 <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309112] uhci_hcd 0000:00:1d.0: setting latency timer to 64 <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309152] uhci_hcd 0000:00:1d.1: setting latency timer to 64 <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309153] usb usb6: root hub lost power or was reset <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309167] uhci_hcd 0000:00:1d.2: setting latency timer to 64 <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309203] usb usb7: root hub lost power or was reset <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309217] usb usb8: root hub lost power or was reset <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309225] ehci_hcd 0000:00:1d.7: setting latency timer to 64 <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309235] pci 0000:00:1e.0: setting latency timer to 64 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309247] ata_piix 0000:00:1f.2: PCI INT B -> GSI 19 (level, low) -> IRQ 19 <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309253] ata_piix 0000:00:1f.2: setting latency timer to 64 <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309255] usb usb2: root hub lost power or was reset <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309323] ata_piix 0000:00:1f.5: PCI INT B -> GSI 19 (level, low) -> IRQ 19 <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309330] ata_piix 0000:00:1f.5: setting latency timer to 64 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309343] [drm] nouveau 0000:01:00.0: We're back, enabling device... <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309352] nouveau 0000:01:00.0: setting latency timer to 64 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309357] [drm] nouveau 0000:01:00.0: POSTing device... <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.309360] [drm] nouveau 0000:01:00.0: Parsing VBIOS init table 0 at offset 0xD2F4 <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.310048] pci 0000:02:00.0: setting latency timer to 64 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.310091] HDA Intel 0000:03:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.310125] ahci 0000:04:00.0: PCI INT A -> GSI 18 (level, low) -> IRQ 18 <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.310135] ahci 0000:04:00.0: setting latency timer to 64 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.310150] pata_jmicron 0000:04:00.1: PCI INT B -> GSI 19 (level, low) -> IRQ 19 <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.310157] pata_jmicron 0000:04:00.1: setting latency timer to 64 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.310174] ahci 0000:05:00.0: PCI INT A -> GSI 19 (level, low) -> IRQ 19 <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.310181] ahci 0000:05:00.0: setting latency timer to 64 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.310197] pata_jmicron 0000:05:00.1: PCI INT B -> GSI 16 (level, low) -> IRQ 16 <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.310205] pata_jmicron 0000:05:00.1: setting latency timer to 64 <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.313127] ehci_hcd 0000:00:1d.7: cache line size of 32 is not supported <0.5> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.313278] sd 4:0:0:0: [sda] Starting disk <0.5> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.313316] sd 4:0:1:0: [sdb] Starting disk <0.5> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.313331] sd 5:0:0:0: [sdc] Starting disk <0.5> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.313345] sd 5:0:1:0: [sdd] Starting disk <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.314012] ehci_hcd 0000:00:1a.7: cache line size of 32 is not supported <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.314012] ehci_hcd 0000:00:1a.7: cache line size of 32 is not supported <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.315916] serial 00:06: activated <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.317319] i8042 kbd 00:08: wake-up capability disabled by ACPI <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.319053] r8169 0000:06:00.0: eth0: link down <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.319085] r8169 0000:07:00.0: eth1: link down <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.338135] [drm] nouveau 0000:01:00.0: Parsing VBIOS init table 1 at offset 0xD741 <0.5> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.366075] firewire_core: skipped bus generations, destroying all nodes <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.398021] [drm] nouveau 0000:01:00.0: Parsing VBIOS init table 2 at offset 0xE791 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.398049] [drm] nouveau 0000:01:00.0: Parsing VBIOS init table 3 at offset 0xE8B2 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.400764] [drm] nouveau 0000:01:00.0: Parsing VBIOS init table 4 at offset 0xEB22 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.400768] [drm] nouveau 0000:01:00.0: Parsing VBIOS init table at offset 0xEB87 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.421071] [drm] nouveau 0000:01:00.0: Reinitialising engines... <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.422786] [drm] nouveau 0000:01:00.0: Restoring GPU objects... <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.437704] [drm] nouveau 0000:01:00.0: Restoring mode... The photo continues from here, next to the " And we're gone!" message above. But messages from hibernation and thawing can bot be mixed in the written log, which is confusing. (You can also compare the log below here to the bad quality photo: it can not be read, but lines can be identified as the same.) <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.618039] ata3: SATA link down (SStatus 0 SControl 300) <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.618285] ata1: SATA link down (SStatus 0 SControl 300) <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.618723] ata2: SATA link down (SStatus 0 SControl 300) <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.619198] ata4: SATA link down (SStatus 0 SControl 300) <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.632642] ata7: SATA link down (SStatus 0 SControl 300) <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.772051] ata8: SATA link up 1.5 Gbps (SStatus 113 SControl 300) <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.791125] ata8.00: ACPI cmd ef/03:45:00:00:00:a0 (SET FEATURES) filtered out <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.791327] ata8.00: ACPI cmd ef/03:0c:00:00:00:a0 (SET FEATURES) filtered out <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.791769] ata8.00: ACPI cmd f5/00:00:00:00:00:00 (SECURITY FREEZE LOCK) filtered out <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.798143] ata8.00: configured for UDMA/100 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.801022] usb 3-1: reset low speed USB device using uhci_hcd and address 2 <0.5> 2012-07-06 19:54:07 Telcontar kernel - - - [ 790.867036] firewire_core: rediscovered device fw0 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.076084] ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl 300) <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.076307] ata5.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.079122] ata5.01: ACPI cmd ef/03:45:00:00:00:b0 (SET FEATURES) filtered out <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.079329] ata5.01: ACPI cmd ef/03:0c:00:00:00:b0 (SET FEATURES) filtered out <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.079951] ata5.01: ACPI cmd c6/00:10:00:00:00:b0 (SET MULTIPLE MODE) succeeded <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.080237] ata5.01: ACPI cmd f5/00:00:00:00:00:00 (SECURITY FREEZE LOCK) filtered out <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.086111] ata6.00: SATA link up 3.0 Gbps (SStatus 123 SControl 300) <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.086326] ata6.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.086742] ata5.00: ACPI cmd ef/03:45:00:00:00:a0 (SET FEATURES) filtered out <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.087071] ata5.00: ACPI cmd ef/03:0c:00:00:00:a0 (SET FEATURES) filtered out <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.087605] ata5.00: ACPI cmd c6/00:10:00:00:00:a0 (SET MULTIPLE MODE) succeeded <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.087804] ata5.00: ACPI cmd f5/00:00:00:00:00:00 (SECURITY FREEZE LOCK) filtered out <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.089123] ata6.01: ACPI cmd ef/03:45:00:00:00:b0 (SET FEATURES) filtered out <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.089313] ata6.01: ACPI cmd ef/03:0c:00:00:00:b0 (SET FEATURES) filtered out <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.089765] ata6.01: ACPI cmd c6/00:10:00:00:00:b0 (SET MULTIPLE MODE) succeeded <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.089950] ata6.01: ACPI cmd f5/00:00:00:00:00:00 (SECURITY FREEZE LOCK) filtered out <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.096128] ata6.00: ACPI cmd ef/03:45:00:00:00:a0 (SET FEATURES) filtered out <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.096316] ata6.00: ACPI cmd ef/03:0c:00:00:00:a0 (SET FEATURES) filtered out <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.096782] ata6.00: ACPI cmd c6/00:10:00:00:00:a0 (SET MULTIPLE MODE) succeeded <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.096971] ata6.00: ACPI cmd f5/00:00:00:00:00:00 (SECURITY FREEZE LOCK) filtered out <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.097582] ata5.00: configured for UDMA/133 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.103314] ata5.01: configured for UDMA/133 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.106304] ata6.00: configured for UDMA/133 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.112341] ata6.01: configured for UDMA/133 (this is the last but one line in the bad photo of crashed session; next two are missing) <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.521080] usb 8-2: reset low speed USB device using uhci_hcd and address 2 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 791.902051] usb 2-5: reset high speed USB device using ehci_hcd and address 2 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 792.002714] r8169 0000:06:00.0: eth0: link up (and that ^ is the line in the crashed session, the point of failure) <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 792.291119] usb 2-5.4: reset high speed USB device using ehci_hcd and address 4 <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 792.953016] snd-usb-audio 2-5.4:1.2: no reset_resume for driver snd-usb-audio? <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 792.953214] snd-usb-audio 2-5.4:1.3: no reset_resume for driver snd-usb-audio? <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 792.955419] PM: restore of devices complete after 2646.655 msecs <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 793.139858] ALSA sound/usb/clock.c:233: current rate 16877 is different from the runtime rate 8000 <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 793.318604] ALSA sound/usb/clock.c:233: current rate 16777215 is different from the runtime rate 11025 <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 793.497350] ALSA sound/usb/clock.c:233: current rate 3750848 is different from the runtime rate 16000 <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 793.676092] ALSA sound/usb/clock.c:233: current rate 0 is different from the runtime rate 22050 <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 793.854963] ALSA sound/usb/clock.c:233: current rate 10748160 is different from the runtime rate 24000 <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 794.033708] ALSA sound/usb/clock.c:233: current rate 13 is different from the runtime rate 32000 <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 794.212455] ALSA sound/usb/clock.c:233: current rate 11469056 is different from the runtime rate 44100 <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 794.391200] ALSA sound/usb/clock.c:233: current rate 11469056 is different from the runtime rate 48000 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 794.577733] I was here: 2.8 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 794.577937] I was here: 2.9 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 794.578371] I was here: 1.3 <0.6> 2012-07-06 19:54:07 Telcontar kernel - - - [ 794.578797] I was here: 1.4 here the photo shows ", 2, 4" and step 1.3, 1.4 of s2disk, and the image is saved to disk. The next is from the thawing section. <0.4> 2012-07-06 19:54:07 Telcontar kernel - - - [ 794.601890] Restarting tasks ... done. <0.7> 2012-07-06 19:54:07 Telcontar kernel - - - [ 794.667017] PM: Basic memory bitmaps freed <5.4> 2012-07-06 19:54:07 Telcontar pm-utils - - - Thawing (95)... <5.4> 2012-07-06 19:54:07 Telcontar pm-utils - - - Thawing (1)... Another interesting "feature" seen in the photos is that in the second one is missing a section of the left side. This happened since it switched to the nouveau driver (it is noticiably slower, I see artifacts in the xterm as I type this). I think, seeing the log, that I need more printks inside dpm_suspend(). Or maybe not... I'm about lost. /** * dpm_suspend - Execute "suspend" callbacks for all non-sysdev devices. * @state: PM transition of the system being carried out. */ static int dpm_suspend(pm_message_t state) { struct list_head list; ktime_t starttime = ktime_get(); int error = 0; INIT_LIST_HEAD(&list); mutex_lock(&dpm_list_mtx); pm_transition = state; async_error = 0; while (!list_empty(&dpm_list)) { struct device *dev = to_device(dpm_list.prev); get_device(dev); mutex_unlock(&dpm_list_mtx); error = device_suspend(dev); mutex_lock(&dpm_list_mtx); if (error) { pm_dev_err(dev, state, "", error); put_device(dev); break; } if (!list_empty(&dev->power.entry)) list_move(&dev->power.entry, &list); put_device(dev); if (async_error) break; } list_splice(&list, dpm_list.prev); mutex_unlock(&dpm_list_mtx); async_synchronize_full(); if (!error) error = async_error; if (!error) dpm_show_time(starttime, state, NULL); return error; } - -- Cheers, Carlos E. R. (from 11.4 x86_64 "Celadon" at Telcontar) -----BEGIN PGP SIGNATURE----- Version: GnuPG v2.0.16 (GNU/Linux) iEYEARECAAYFAk/3NhwACgkQtTMYHG2NR9VmvACfRce0tPUY+ZPquZBwvdIgSJ4R /skAn3Ob1R8/XpVpHY30HLN2Yute95GS =Adi6 -----END PGP SIGNATURE----- -- To unsubscribe, e-mail: opensuse+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse+owner@opensuse.org