Mailinglist Archive: opensuse (818 mails)

< Previous Next >
Re: [opensuse] Need help: I found out where s2disk crashes.
  • From: "Carlos E. R." <robin.listas@xxxxxxxxxxxxxx>
  • Date: Fri, 6 Jul 2012 21:01:42 +0200 (CEST)
  • Message-id: <alpine.LNX.2.00.1207062000260.5806@Telcontar.valinor>
-----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@xxxxxxxxxxxx
To contact the owner, e-mail: opensuse+owner@xxxxxxxxxxxx

< Previous Next >
List Navigation
Follow Ups