You are not logged in.

#1 2012-01-18 12:46:17

marvn
Member
From: Prague
Registered: 2010-01-05
Posts: 84

[SOLVED] yet another resume issue

hello,

I've wierd issues with resuming after suspend, I have it since 3.1 kernel, but maybe it's not related. It's wierd, because the computer (according to logs) resume normally, my screen lit up, but remains black (while there should be my ascii aquarium there)

here are the logs (3:20 suspend, 10:07 resume, 11:09 reboot - it should be 10:09, but my clock is confused due to dualboot)

Jan 18 03:20:28 localhost kernel: [ 7492.851636] ADDRCONF(NETDEV_UP): eth0: link is not ready
Jan 18 03:20:30 localhost ntpd[789]: Deleting interface #5 wlan0, 192.168.1.3#123, interface stats: received=289, sent=290, dropped=0, active_time=7432 secs
Jan 18 03:20:30 localhost ntpd[789]: 83.167.232.159 interface 192.168.1.3 -> (none)
Jan 18 03:20:30 localhost ntpd[789]: 195.113.159.1 interface 192.168.1.3 -> (none)
Jan 18 03:20:30 localhost ntpd[789]: 147.231.100.5 interface 192.168.1.3 -> (none)
Jan 18 03:20:30 localhost ntpd[789]: 89.31.8.3 interface 192.168.1.3 -> (none)
Jan 18 03:20:30 localhost ntpd[789]: Deleting interface #4 wlan0, fe80::f27b:cbff:fe44:579d#123, interface stats: received=0, sent=0, dropped=0, active_time=7440 secs
Jan 18 03:20:30 localhost ntpd[789]: peers refreshed
Jan 18 10:07:02 localhost kernel: [ 7496.919995] PM: Syncing filesystems ... done.
Jan 18 10:07:02 localhost kernel: [ 7496.922525] PM: Preparing system for mem sleep
Jan 18 10:07:02 localhost kernel: [ 7496.922543] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 18 10:07:02 localhost kernel: [ 7496.934095] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 18 10:07:02 localhost kernel: [ 7496.947423] PM: Entering mem sleep
Jan 18 10:07:02 localhost kernel: [ 7496.947508] Suspending console(s) (use no_console_suspend to debug)
Jan 18 10:07:02 localhost kernel: [ 7496.971929] sd 0:0:0:0: [sda] Synchronizing SCSI cache
Jan 18 10:07:02 localhost kernel: [ 7496.972232] sd 0:0:0:0: [sda] Stopping disk
Jan 18 10:07:02 localhost kernel: [ 7497.067366] ehci_hcd 0000:00:1a.0: PCI INT A disabled
Jan 18 10:07:02 localhost kernel: [ 7497.070660] ehci_hcd 0000:00:1d.0: PCI INT A disabled
Jan 18 10:07:02 localhost kernel: [ 7497.130807] snd_hda_intel 0000:00:1b.0: PCI INT A disabled
Jan 18 10:07:02 localhost kernel: [ 7497.466945] snd_hda_intel 0000:01:00.1: PCI INT A disabled
Jan 18 10:07:02 localhost kernel: [ 7497.467011] ACPI handle has no context!
Jan 18 10:07:02 localhost kernel: [ 7497.577002] PM: suspend of devices complete after 629.868 msecs
Jan 18 10:07:02 localhost kernel: [ 7497.643584] PM: late suspend of devices complete after 66.641 msecs
Jan 18 10:07:02 localhost kernel: [ 7497.643845] ACPI: Preparing to enter system sleep state S3
Jan 18 10:07:02 localhost kernel: [ 7497.843430] PM: Saving platform NVS memory
Jan 18 10:07:02 localhost kernel: [ 7497.845513] Disabling non-boot CPUs ...
Jan 18 10:07:02 localhost kernel: [ 7497.846958] Broke affinity for irq 41
Jan 18 10:07:02 localhost kernel: [ 7497.949720] CPU 1 is now offline
Jan 18 10:07:02 localhost kernel: [ 7497.951014] Broke affinity for irq 42
Jan 18 10:07:02 localhost kernel: [ 7498.053183] CPU 2 is now offline
Jan 18 10:07:02 localhost kernel: [ 7498.054835] Broke affinity for irq 43
Jan 18 10:07:02 localhost kernel: [ 7498.156272] CPU 3 is now offline
Jan 18 10:07:02 localhost kernel: [ 7498.157592] Broke affinity for irq 44
Jan 18 10:07:02 localhost kernel: [ 7498.259548] CPU 4 is now offline
Jan 18 10:07:02 localhost kernel: [ 7498.362733] CPU 5 is now offline
Jan 18 10:07:02 localhost kernel: [ 7498.465933] CPU 6 is now offline
Jan 18 10:07:02 localhost kernel: [ 7498.569194] CPU 7 is now offline
Jan 18 10:07:02 localhost kernel: [ 7498.569592] Extended CMOS year: 2000
Jan 18 10:07:02 localhost kernel: [ 7498.569881] ACPI: Low-level resume complete
Jan 18 10:07:02 localhost kernel: [ 7498.569935] PM: Restoring platform NVS memory
Jan 18 10:07:02 localhost kernel: [ 7498.570376] Extended CMOS year: 2000
Jan 18 10:07:02 localhost kernel: [ 7498.570454] Enabling non-boot CPUs ...
Jan 18 10:07:02 localhost kernel: [ 7498.570538] Booting Node 0 Processor 1 APIC 0x2
Jan 18 10:07:02 localhost kernel: [ 7498.570540] smpboot cpu 1: start_ip = 98000
Jan 18 10:07:02 localhost kernel: [ 7498.581648] Calibrating delay loop (skipped) already calibrated this CPU
Jan 18 10:07:02 localhost kernel: [ 7498.602033] NMI watchdog enabled, takes one hw-pmu counter.
Jan 18 10:07:02 localhost kernel: [ 7498.603164] Switched to NOHz mode on CPU #1
Jan 18 10:07:02 localhost kernel: [ 7498.606581] hpet: hpet3 irq 41 for MSI
Jan 18 10:07:02 localhost kernel: [ 7498.606609] CPU1 is up
Jan 18 10:07:02 localhost kernel: [ 7498.606745] Booting Node 0 Processor 2 APIC 0x4
Jan 18 10:07:02 localhost kernel: [ 7498.606749] smpboot cpu 2: start_ip = 98000
Jan 18 10:07:02 localhost kernel: [ 7498.617854] Calibrating delay loop (skipped) already calibrated this CPU
Jan 18 10:07:02 localhost kernel: [ 7498.638232] NMI watchdog enabled, takes one hw-pmu counter.
Jan 18 10:07:02 localhost kernel: [ 7498.639797] Switched to NOHz mode on CPU #2
Jan 18 10:07:02 localhost kernel: [ 7498.639885] hpet: hpet4 irq 42 for MSI
Jan 18 10:07:02 localhost kernel: [ 7498.639909] CPU2 is up
Jan 18 10:07:02 localhost kernel: [ 7498.640034] Booting Node 0 Processor 3 APIC 0x6
Jan 18 10:07:02 localhost kernel: [ 7498.640038] smpboot cpu 3: start_ip = 98000
Jan 18 10:07:02 localhost kernel: [ 7498.683983] Calibrating delay loop (skipped) already calibrated this CPU
Jan 18 10:07:02 localhost kernel: [ 7498.710025] NMI watchdog enabled, takes one hw-pmu counter.
Jan 18 10:07:02 localhost kernel: [ 7498.713060] Switched to NOHz mode on CPU #3
Jan 18 10:07:02 localhost kernel: [ 7498.716446] hpet: hpet5 irq 43 for MSI
Jan 18 10:07:02 localhost kernel: [ 7498.716464] CPU3 is up
Jan 18 10:07:02 localhost kernel: [ 7498.716539] Booting Node 0 Processor 4 APIC 0x1
Jan 18 10:07:02 localhost kernel: [ 7498.716541] smpboot cpu 4: start_ip = 98000
Jan 18 10:07:02 localhost kernel: [ 7498.727646] Calibrating delay loop (skipped) already calibrated this CPU
Jan 18 10:07:02 localhost kernel: [ 7498.748152] NMI watchdog enabled, takes one hw-pmu counter.
Jan 18 10:07:02 localhost kernel: [ 7498.749684] Switched to NOHz mode on CPU #4
Jan 18 10:07:02 localhost kernel: [ 7498.749750] hpet: hpet6 irq 44 for MSI
Jan 18 10:07:02 localhost kernel: [ 7498.749769] CPU4 is up
Jan 18 10:07:02 localhost kernel: [ 7498.749871] Booting Node 0 Processor 5 APIC 0x3
Jan 18 10:07:02 localhost kernel: [ 7498.749873] smpboot cpu 5: start_ip = 98000
Jan 18 10:07:02 localhost kernel: [ 7498.760981] Calibrating delay loop (skipped) already calibrated this CPU
Jan 18 10:07:02 localhost kernel: [ 7498.781570] NMI watchdog enabled, takes one hw-pmu counter.
Jan 18 10:07:02 localhost kernel: [ 7498.783034] Switched to NOHz mode on CPU #5
Jan 18 10:07:02 localhost kernel: [ 7498.783112] CPU5 is up
Jan 18 10:07:02 localhost kernel: [ 7498.783220] Booting Node 0 Processor 6 APIC 0x5
Jan 18 10:07:02 localhost kernel: [ 7498.783223] smpboot cpu 6: start_ip = 98000
Jan 18 10:07:02 localhost kernel: [ 7498.794330] Calibrating delay loop (skipped) already calibrated this CPU
Jan 18 10:07:02 localhost kernel: [ 7498.815143] NMI watchdog enabled, takes one hw-pmu counter.
Jan 18 10:07:02 localhost kernel: [ 7498.816385] Switched to NOHz mode on CPU #6
Jan 18 10:07:02 localhost kernel: [ 7498.816488] CPU6 is up
Jan 18 10:07:02 localhost kernel: [ 7498.816730] Booting Node 0 Processor 7 APIC 0x7
Jan 18 10:07:02 localhost kernel: [ 7498.816732] smpboot cpu 7: start_ip = 98000
Jan 18 10:07:02 localhost kernel: [ 7498.827839] Calibrating delay loop (skipped) already calibrated this CPU
Jan 18 10:07:02 localhost kernel: [ 7498.848615] NMI watchdog enabled, takes one hw-pmu counter.
Jan 18 10:07:02 localhost kernel: [ 7498.849694] Switched to NOHz mode on CPU #7
Jan 18 10:07:02 localhost kernel: [ 7498.853100] CPU7 is up
Jan 18 10:07:02 localhost kernel: [ 7498.857541] ACPI: Waking up from system sleep state S3
Jan 18 10:07:02 localhost kernel: [ 7498.963477] ehci_hcd 0000:00:1a.0: restoring config space at offset 0x1 (was 0x2900006, writing 0x2900002)
Jan 18 10:07:02 localhost kernel: [ 7498.963511] snd_hda_intel 0000:00:1b.0: restoring config space at offset 0xf (was 0x10b, writing 0x100)
Jan 18 10:07:02 localhost kernel: [ 7498.963529] snd_hda_intel 0000:00:1b.0: restoring config space at offset 0x3 (was 0x10, writing 0x0)
Jan 18 10:07:02 localhost kernel: [ 7498.963538] snd_hda_intel 0000:00:1b.0: restoring config space at offset 0x1 (was 0x100006, writing 0x100002)
Jan 18 10:07:02 localhost kernel: [ 7498.963658] ehci_hcd 0000:00:1d.0: restoring config space at offset 0x1 (was 0x2900006, writing 0x2900002)
Jan 18 10:07:02 localhost kernel: [ 7498.963690] pci 0000:00:1e.0: restoring config space at offset 0xa (was 0xffffffff, writing 0x0)
Jan 18 10:07:02 localhost kernel: [ 7498.963772] ahci 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b00007, writing 0x2b00407)
Jan 18 10:07:02 localhost kernel: [ 7498.963840] nvidia 0000:01:00.0: restoring config space at offset 0xf (was 0x100, writing 0x107)
Jan 18 10:07:02 localhost kernel: [ 7498.963850] nvidia 0000:01:00.0: restoring config space at offset 0x9 (was 0x1, writing 0x3001)
Jan 18 10:07:02 localhost acpid: client 794[0:0] has disconnected
Jan 18 10:07:02 localhost kernel: [ 7498.963856] nvidia 0000:01:00.0: restoring config space at offset 0x7 (was 0xc, writing 0xd000000c)
Jan 18 10:07:02 localhost kernel: [ 7498.963862] nvidia 0000:01:00.0: restoring config space at offset 0x5 (was 0xc, writing 0xc000000c)
Jan 18 10:07:02 localhost kernel: [ 7498.963867] nvidia 0000:01:00.0: restoring config space at offset 0x4 (was 0x0, writing 0xd2000000)
Jan 18 10:07:02 localhost kernel: [ 7498.963874] nvidia 0000:01:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100007)
Jan 18 10:07:02 localhost kernel: [ 7498.963923] snd_hda_intel 0000:01:00.1: restoring config space at offset 0xf (was 0x100, writing 0x107)
Jan 18 10:07:02 localhost kernel: [ 7498.963940] snd_hda_intel 0000:01:00.1: restoring config space at offset 0x4 (was 0x0, writing 0xd3000000)
Jan 18 10:07:02 localhost kernel: [ 7498.963945] snd_hda_intel 0000:01:00.1: restoring config space at offset 0x3 (was 0x800000, writing 0x800010)
Jan 18 10:07:02 localhost kernel: [ 7498.963951] snd_hda_intel 0000:01:00.1: restoring config space at offset 0x1 (was 0x100000, writing 0x100002)
Jan 18 10:07:02 localhost kernel: [ 7498.963996] atl1c 0000:02:00.0: restoring config space at offset 0xf (was 0x100, writing 0x103)
Jan 18 10:07:02 localhost kernel: [ 7498.964022] atl1c 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x10)
Jan 18 10:07:02 localhost kernel: [ 7498.964032] atl1c 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100007)
Jan 18 10:07:02 localhost kernel: [ 7498.964078] ath9k 0000:03:00.0: restoring config space at offset 0xf (was 0x1ff, writing 0x105)
Jan 18 10:07:02 localhost kernel: [ 7498.964102] ath9k 0000:03:00.0: restoring config space at offset 0x4 (was 0x4, writing 0xd5100004)
Jan 18 10:07:02 localhost kernel: [ 7498.964110] ath9k 0000:03:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x10)
Jan 18 10:07:02 localhost kernel: [ 7498.964121] ath9k 0000:03:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100007)
Jan 18 10:07:02 localhost kernel: [ 7498.964348] PM: early resume of devices complete after 1.110 msecs
Jan 18 10:07:02 localhost kernel: [ 7498.964605] ehci_hcd 0000:00:1a.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
Jan 18 10:07:02 localhost kernel: [ 7498.964615] ehci_hcd 0000:00:1a.0: setting latency timer to 64
Jan 18 10:07:02 localhost kernel: [ 7498.964632] snd_hda_intel 0000:00:1b.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22
Jan 18 10:07:02 localhost kernel: [ 7498.964640] snd_hda_intel 0000:00:1b.0: setting latency timer to 64
Jan 18 10:07:02 localhost kernel: [ 7498.964692] ehci_hcd 0000:00:1d.0: PCI INT A -> GSI 23 (level, low) -> IRQ 23
Jan 18 10:07:02 localhost kernel: [ 7498.964698] pci 0000:00:1e.0: setting latency timer to 64
Jan 18 10:07:02 localhost kernel: [ 7498.964706] ehci_hcd 0000:00:1d.0: setting latency timer to 64
Jan 18 10:07:02 localhost kernel: [ 7498.964712] snd_hda_intel 0000:00:1b.0: irq 46 for MSI/MSI-X
Jan 18 10:07:02 localhost kernel: [ 7498.964728] ahci 0000:00:1f.2: setting latency timer to 64
Jan 18 10:07:02 localhost kernel: [ 7498.964791] snd_hda_intel 0000:01:00.1: PCI INT A -> GSI 16 (level, low) -> IRQ 16
Jan 18 10:07:02 localhost kernel: [ 7498.964803] snd_hda_intel 0000:01:00.1: setting latency timer to 64
Jan 18 10:07:02 localhost kernel: [ 7498.975034] sd 0:0:0:0: [sda] Starting disk
Jan 18 10:07:02 localhost kernel: [ 7499.066422] atl1c 0000:02:00.0: irq 47 for MSI/MSI-X
Jan 18 10:07:02 localhost kernel: [ 7499.209497] usb 1-1.1: reset high speed USB device number 3 using ehci_hcd
Jan 18 10:07:02 localhost kernel: [ 7499.295944] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Jan 18 10:07:02 localhost kernel: [ 7499.357379] ata2.00: configured for UDMA/100
Jan 18 10:07:02 localhost kernel: [ 7501.147613] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jan 18 10:07:02 localhost kernel: [ 7501.378598] ata1.00: configured for UDMA/133
Jan 18 10:07:02 localhost kernel: [ 7501.470003] PM: resume of devices complete after 2507.929 msecs
Jan 18 10:07:02 localhost kernel: [ 7501.470208] PM: Finishing wakeup.
Jan 18 10:07:02 localhost kernel: [ 7501.470209] Restarting tasks ... done.
Jan 18 10:07:02 localhost kernel: [ 7501.475503] video LNXVIDEO:01: Restoring backlight state
Jan 18 10:07:02 localhost logger: ACPI action undefined: ACPI0003:00
Jan 18 10:07:02 localhost logger: ACPI group/action undefined: processor / LNXCPU:00
Jan 18 10:07:02 localhost logger: ACPI group/action undefined: processor / LNXCPU:01
Jan 18 10:07:02 localhost logger: ACPI group/action undefined: processor / LNXCPU:02
Jan 18 10:07:02 localhost logger: ACPI group/action undefined: processor / LNXCPU:03
Jan 18 10:07:02 localhost logger: ACPI action undefined: PNP0C0A:00
Jan 18 10:07:02 localhost logger: ACPI action undefined: PNP0C0A:00
Jan 18 10:07:02 localhost logger: ACPI group/action undefined: processor / LNXCPU:04
Jan 18 10:07:02 localhost logger: ACPI group/action undefined: processor / LNXCPU:05
Jan 18 10:07:02 localhost logger: ACPI group/action undefined: processor / LNXCPU:06
Jan 18 10:07:02 localhost logger: ACPI group/action undefined: processor / LNXCPU:07
Jan 18 10:07:02 localhost acpid: client connected from 794[0:0]
Jan 18 10:07:02 localhost acpid: 1 client rule loaded
Jan 18 10:07:06 localhost kernel: [ 7505.835237] atl1c 0000:02:00.0: atl1c: eth0 NIC Link is Up<1000 Mbps Full Duplex>
Jan 18 10:07:06 localhost kernel: [ 7505.835842] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Jan 18 10:07:07 localhost kernel: [ 7506.174071] EXT4-fs (sda4): re-mounted. Opts: commit=600
Jan 18 10:07:07 localhost dhcpcd[5160]: dhcpcd not running
Jan 18 10:07:07 localhost kernel: [ 7506.820851] ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jan 18 10:07:07 localhost dhcpcd[5166]: dhcpcd not running
Jan 18 10:07:07 localhost kernel: [ 7506.857199] atl1c 0000:02:00.0: irq 47 for MSI/MSI-X
Jan 18 10:07:07 localhost kernel: [ 7506.857309] atl1c 0000:02:00.0: atl1c: eth0 NIC Link is Up<1000 Mbps Full Duplex>
Jan 18 10:07:08 localhost dhcpcd[5173]: dhcpcd not running
Jan 18 10:07:08 localhost kernel: [ 7507.142787] atl1c 0000:02:00.0: irq 47 for MSI/MSI-X
Jan 18 10:07:08 localhost kernel: [ 7507.142853] atl1c 0000:02:00.0: atl1c: eth0 NIC Link is Up<1000 Mbps Full Duplex>
Jan 18 11:09:17 localhost kernel: [    0.000000] Initializing cgroup subsys cpuset
Jan 18 11:09:17 localhost kernel: [    0.000000] Initializing cgroup subsys cpu
Jan 18 11:09:17 localhost kernel: [    0.000000] Linux version 3.1.9-2-ARCH (tobias@T-POWA-LX) (gcc version 4.6.2 20111223 (prerelease) (GCC) ) #1 SMP PREEMPT Sat Jan 14 

it's rather rare, like 1 in 10 cases, but it's annoying.  it might be KMS related, but it should be off as i'm using nvidia prop drivers. I've also removed "acpm force" from kernel boot params, but don't know yet if this will help.

so...anyone else is having these issues? any ideas what might help here?

thx in advance, M

UPDATE: no issues in last two weeks and no more "nvidia (EE)" in xorg log, no solution quite worked, so it was probably smt between kernel and nvidia drivers...

Last edited by marvn (2012-02-20 12:49:04)


core i5 4590, x86_64, nvidia 970

Offline

#2 2012-01-18 13:34:27

JamieKitson
Member
From: UK
Registered: 2010-10-18
Posts: 161
Website

Re: [SOLVED] yet another resume issue

What command are you using to suspend? There are some s2ram troubleshooting options here: http://tr.opensuse.org/S2ram

Offline

#3 2012-01-18 13:45:45

marvn
Member
From: Prague
Registered: 2010-01-05
Posts: 84

Re: [SOLVED] yet another resume issue

I'm mostly using Fn+F4 (it's acer notebook and these shortcuts works in linux by default). sometimes my ntb is suspend by KDE batery deamon (or how it's called). I'm pretty sure that both methods are using pm-utils.


core i5 4590, x86_64, nvidia 970

Offline

#4 2012-01-25 15:56:14

marvn
Member
From: Prague
Registered: 2010-01-05
Posts: 84

Re: [SOLVED] yet another resume issue

I've probably find what causing it. There is "(EE) NVIDIA(0): WAIT: (E, 0, 0x857d)" in xorg log. Goolge leads me to nvforum http://www.nvnews.net/vbulletin/showthread.php?t=150925

from there:

Last several weeks I've noticed my laptop screen sometimes not coming up out of suspend, though I was changing kernel versions a lot so I thought that was causing it. Just had the opportunity to ssh into the laptop during one of those moments, and I see the exact same error in Xorg.0.log.

I'm on 2.6.32 amd64 with driver 270.41.06. I'll give the suggested intel_iommu=off tip a try. If that doesn't work, I'm going to go back to one of the 190 series, that was the last time I was free of this other problem: http://www.nvnews.net/vbulletin/showthread.php?t=158091

Steve

so adding intel_iommu=off to boot params might be a working workaround (for those who don't use virtualization)


core i5 4590, x86_64, nvidia 970

Offline

Board footer

Powered by FluxBB