[opensuse] Machine failing to hibernate if a certain java application is running.
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 Hi, When a certain java application (see later) is running, I have a machine that fails to hibernate. I see this in the pm-suspend.log (trimmed for simplicity): +++····························· Initial commandline parameters: Mon Apr 28 12:56:11 CEST 2014: Running hooks for hibernate. Running hook /usr/lib/pm-utils/sleep.d/00logging hibernate hibernate: hibernate initiated: Mon Apr 28 12:56:11 CEST 2014 ... ... hibernate: success everywhere till ... /usr/lib/pm-utils/sleep.d/99info hibernate hibernate: success. Running hook /usr/lib/pm-utils/sleep.d/99video hibernate hibernate: /usr/lib/pm-utils/sleep.d/99video hibernate hibernate: success. Mon Apr 28 12:56:13 CEST 2014: performing hibernate INFO: using built-in quirks database from HAL. INFO: S2RAM_OPTS from HAL quirks: ' '. Mon Apr 28 12:56:19 CEST 2014: Awake. Mon Apr 28 12:56:20 CEST 2014: Running hooks for thaw Running hook /usr/lib/pm-utils/sleep.d/99video thaw hibernate: /usr/lib/pm-utils/sleep.d/99video thaw hibernate: success. Running hook /usr/lib/pm-utils/sleep.d/99info thaw hibernate: ·····························++- It is thawing immediately, no error given. Let's see the messages log: +++····························· 2014-04-28T12:56:11.880848+02:00 AmonLanc pm-utils: Hibernating (01)... 2014-04-28T12:56:12.353763+02:00 AmonLanc kernel: [137474.737127] pcmcia_socket pcmcia_socket0: pccard: card ejected from slot 0 2014-04-28T12:56:12.510594+02:00 AmonLanc systemd[1]: network@eth0.service: main process exited, code=killed, status=9/KILL 2014-04-28T12:56:12.518248+02:00 AmonLanc network[23906]: redirecting to "systemctl --signal=9 kill network.service" 2014-04-28T12:56:12.564912+02:00 AmonLanc pm-utils: Hibernating (95)... 2014-04-28T12:56:13.981750+02:00 AmonLanc kernel: [137476.366469] PM: Marking nosave pages: [mem 0x0009f000-0x000fffff] 2014-04-28T12:56:13.981778+02:00 AmonLanc kernel: [137476.366477] PM: Basic memory bitmaps created 2014-04-28T12:56:16.040658+02:00 AmonLanc kernel: [137477.194160] Syncing filesystems ... done. 2014-04-28T12:56:16.051944+02:00 AmonLanc kernel: [137477.258892] Freezing user space processes ... (elapsed 0.002 seconds) done. 2014-04-28T12:56:16.051953+02:00 AmonLanc kernel: [137477.261594] PM: Preallocating image memory... 2014-04-28T12:56:16.051956+02:00 AmonLanc kernel: [137478.096784] Restarting tasks ... done. 2014-04-28T12:56:16.051959+02:00 AmonLanc kernel: [137478.104366] PM: Basic memory bitmaps freed 2014-04-28T12:56:31.561440+02:00 AmonLanc dbus[1490]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper) 2014-04-28T12:56:32.060387+02:00 AmonLanc pm-utils: Thawing (95)... 2014-04-28T12:56:32.060867+02:00 AmonLanc dbus[1490]: [system] Activated service 'org.freedesktop.PackageKit' failed: Cannot launch daemon, file not found or permissions invalid 2014-04-28T12:56:32.061501+02:00 AmonLanc network[24081]: redirecting to "systemctl restart network.service" 2014-04-28T12:56:32.062659+02:00 AmonLanc systemd[1]: Stopping ifup managed network interface eth0... 2014-04-28T12:56:32.098013+02:00 AmonLanc systemd[1]: Stopping LSB: Configure network interfaces and set up routing... 2014-04-28T12:56:32.098846+02:00 AmonLanc systemd[1]: Starting LSB: Configure network interfaces and set up routing... ·····························++- dmesg doesn't say different: +++····························· [137476.366469] PM: Marking nosave pages: [mem 0x0009f000-0x000fffff] [137476.366477] PM: Basic memory bitmaps created [137477.194160] Syncing filesystems ... done. [137477.258892] Freezing user space processes ... (elapsed 0.002 seconds) done. [137477.261594] PM: Preallocating image memory... [137478.096784] Restarting tasks ... done. [137478.104366] PM: Basic memory bitmaps freed ·····························++- So no messages at about why it aborts. Now a normal pm-suspend.log, with the suspect java application stopped: +++····························· Initial commandline parameters: Mon Apr 28 12:49:48 CEST 2014: Running hooks for hibernate. Running hook /usr/lib/pm-utils/sleep.d/00logging hibernate hibernate: hibernate initiated: Mon Apr 28 12:49:48 CEST 2014 ... ... /usr/lib/pm-utils/sleep.d/99info hibernate hibernate: success. Running hook /usr/lib/pm-utils/sleep.d/99video hibernate hibernate: /usr/lib/pm-utils/sleep.d/99video hibernate hibernate: success. Mon Apr 28 12:49:49 CEST 2014: performing hibernate INFO: using built-in quirks database from HAL. INFO: S2RAM_OPTS from HAL quirks: ' '. Mon Apr 28 12:51:57 CEST 2014: Awake. Mon Apr 28 12:51:57 CEST 2014: Running hooks for thaw Running hook /usr/lib/pm-utils/sleep.d/99video thaw hibernate: /usr/lib/pm-utils/sleep.d/99video thaw hibernate: success. Running hook /usr/lib/pm-utils/sleep.d/99info thaw hibernate: ·····························++- The log is the same, but the machine actually powered off. The timestamps get written to file after the fact, I guess. And lets see /var/log/messages - - this time it is different, the machine did go to hibernation and it shows: +++····························· 2014-04-28T12:49:48.268310+02:00 AmonLanc pm-utils: Hibernating (01)... 2014-04-28T12:49:48.488613+02:00 AmonLanc kernel: [137215.095786] pcmcia_socket pcmcia_socket0: pccard: card ejected from slot 0 2014-04-28T12:49:48.570074+02:00 AmonLanc systemd[1]: network@eth0.service: main process exited, code=killed, status=9/KILL 2014-04-28T12:49:48.577795+02:00 AmonLanc network[21730]: redirecting to "systemctl --signal=9 kill network.service" 2014-04-28T12:49:48.622385+02:00 AmonLanc pm-utils: Hibernating (95)... 2014-04-28T12:49:49.744408+02:00 AmonLanc kernel: [137216.351823] PM: Marking nosave pages: [mem 0x0009f000-0x000fffff] 2014-04-28T12:49:49.744439+02:00 AmonLanc kernel: [137216.351831] PM: Basic memory bitmaps created 2014-04-28T12:51:57.342868+02:00 AmonLanc kernel: [137217.131446] Syncing filesystems ... done. 2014-04-28T12:51:57.120800+02:00 AmonLanc systemd[6024]: Time has been changed 2014-04-28T12:51:57.121541+02:00 AmonLanc systemd[1]: Time has been changed 2014-04-28T12:51:57.122260+02:00 AmonLanc systemd[30852]: Time has been changed 2014-04-28T12:51:58.354793+02:00 AmonLanc kernel: [137217.155722] Freezing user space processes ... (elapsed 0.004 seconds) done. 2014-04-28T12:51:58.354815+02:00 AmonLanc kernel: [137217.160555] PM: Preallocating image memory... done (allocated 71061 pages) 2014-04-28T12:51:58.354817+02:00 AmonLanc kernel: [137217.303618] PM: Allocated 284244 kbytes in 0.14 seconds (2030.31 MB/s) 2014-04-28T12:51:58.354821+02:00 AmonLanc kernel: [137217.303624] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done. 2014-04-28T12:51:58.354824+02:00 AmonLanc kernel: [137217.305344] Suspending console(s) (use no_console_suspend to debug) 2014-04-28T12:51:58.354826+02:00 AmonLanc kernel: [137217.305664] parport_pc 00:08: disabled 2014-04-28T12:51:58.354829+02:00 AmonLanc kernel: [137217.305677] i8042 aux 00:07: System wakeup disabled by ACPI 2014-04-28T12:51:58.354831+02:00 AmonLanc kernel: [137217.305685] i8042 kbd 00:06: System wakeup enabled by ACPI 2014-04-28T12:51:58.354834+02:00 AmonLanc kernel: [137217.385024] PM: freeze of devices complete after 79.668 msecs 2014-04-28T12:51:58.354837+02:00 AmonLanc kernel: [137217.385196] PM: late freeze of devices complete after 0.169 msecs 2014-04-28T12:51:58.354840+02:00 AmonLanc kernel: [137217.385506] PM: noirq freeze of devices complete after 0.306 msecs 2014-04-28T12:51:58.354848+02:00 AmonLanc kernel: [137217.385616] ACPI: Preparing to enter system sleep state S4 2014-04-28T12:51:58.354851+02:00 AmonLanc kernel: [137217.386034] PM: Saving platform NVS memory 2014-04-28T12:51:58.354854+02:00 AmonLanc kernel: [137217.386287] Disabling non-boot CPUs ... 2014-04-28T12:51:58.354856+02:00 AmonLanc kernel: [137217.386386] PM: Creating hibernation image: 2014-04-28T12:51:58.354858+02:00 AmonLanc kernel: [137217.388002] PM: Need to copy 56036 pages 2014-04-28T12:51:58.354861+02:00 AmonLanc kernel: [137217.388002] PM: Normal pages needed: 56036 + 1024, available pages: 72826 2014-04-28T12:51:58.354863+02:00 AmonLanc kernel: [137217.388002] PM: Restoring platform NVS memory 2014-04-28T12:51:58.354866+02:00 AmonLanc kernel: [137217.388002] microcode: CPU0 sig=0xf29, pf=0x4, revision=0x2e 2014-04-28T12:51:58.354868+02:00 AmonLanc kernel: [137217.388002] ACPI: Waking up from system sleep state S4 2014-04-28T12:51:58.354874+02:00 AmonLanc kernel: [137217.404087] yenta_cardbus 0000:01:03.0: O2: enabling read prefetch/write burst. If you experience problems or performance issues, use the yenta_socket parameter 'o2_speedup=off' 2014-04-28T12:51:58.354877+02:00 AmonLanc kernel: [137217.420544] PM: noirq restore of devices complete after 30.077 msecs 2014-04-28T12:51:58.354880+02:00 AmonLanc kernel: [137217.420664] PM: early restore of devices complete after 0.083 msecs 2014-04-28T12:51:58.354882+02:00 AmonLanc kernel: [137217.439541] i915 0000:00:02.0: setting latency timer to 64 2014-04-28T12:51:58.354885+02:00 AmonLanc kernel: [137217.456333] uhci_hcd 0000:00:1d.0: setting latency timer to 64 2014-04-28T12:51:58.354887+02:00 AmonLanc kernel: [137217.456355] usb usb2: root hub lost power or was reset 2014-04-28T12:51:58.354889+02:00 AmonLanc kernel: [137217.456367] uhci_hcd 0000:00:1d.1: setting latency timer to 64 2014-04-28T12:51:58.354892+02:00 AmonLanc kernel: [137217.456384] usb usb3: root hub lost power or was reset 2014-04-28T12:51:58.399884+02:00 AmonLanc kernel: [137217.456394] uhci_hcd 0000:00:1d.2: setting latency timer to 64 2014-04-28T12:51:58.399899+02:00 AmonLanc kernel: [137217.456412] usb usb4: root hub lost power or was reset 2014-04-28T12:51:58.399902+02:00 AmonLanc kernel: [137217.456423] ehci-pci 0000:00:1d.7: setting latency timer to 64 2014-04-28T12:51:58.399904+02:00 AmonLanc kernel: [137217.456435] usb usb1: root hub lost power or was reset 2014-04-28T12:51:58.399907+02:00 AmonLanc kernel: [137217.460310] ehci-pci 0000:00:1d.7: cache line size of 64 is not supported 2014-04-28T12:51:58.399909+02:00 AmonLanc kernel: [137217.460329] pci 0000:00:1e.0: setting latency timer to 64 2014-04-28T12:51:58.399911+02:00 AmonLanc kernel: [137217.460441] ata_piix 0000:00:1f.1: setting latency timer to 64 2014-04-28T12:51:58.399914+02:00 AmonLanc kernel: [137217.460502] snd_intel8x0 0000:00:1f.5: setting latency timer to 64 2014-04-28T12:51:58.399916+02:00 AmonLanc kernel: [137217.460581] snd_intel8x0m 0000:00:1f.6: setting latency timer to 64 2014-04-28T12:51:58.399922+02:00 AmonLanc kernel: [137217.460739] eth0: DSPCFG accepted after 0 usec. 2014-04-28T12:51:58.399926+02:00 AmonLanc kernel: [137217.460746] eth0: Setting full-duplex based on negotiated link capability. 2014-04-28T12:51:58.399929+02:00 AmonLanc kernel: [137217.488156] i8042 kbd 00:06: System wakeup disabled by ACPI 2014-04-28T12:51:58.399931+02:00 AmonLanc kernel: [137217.488820] parport_pc 00:08: activated 2014-04-28T12:51:58.399934+02:00 AmonLanc kernel: [137217.624329] ata1.00: ACPI cmd ef/03:45:00:00:00:a0 (SET FEATURES) filtered out 2014-04-28T12:51:58.399936+02:00 AmonLanc kernel: [137217.624332] ata1.00: ACPI cmd ef/03:0c:00:00:00:a0 (SET FEATURES) filtered out 2014-04-28T12:51:58.399939+02:00 AmonLanc kernel: [137217.624543] ata1.00: ACPI cmd c6/00:10:00:00:00:a0 (SET MULTIPLE MODE) succeeded 2014-04-28T12:51:58.399941+02:00 AmonLanc kernel: [137217.648375] ata1.00: configured for UDMA/100 2014-04-28T12:51:58.399943+02:00 AmonLanc kernel: [137217.648467] sd 0:0:0:0: [sda] Starting disk 2014-04-28T12:51:58.399949+02:00 AmonLanc kernel: [137217.912028] usb 1-4: reset high-speed USB device number 2 using ehci-pci 2014-04-28T12:51:58.399953+02:00 AmonLanc kernel: [137218.032044] firewire_core 0000:01:0a.0: rediscovered device fw0 2014-04-28T12:51:58.399955+02:00 AmonLanc kernel: [137218.156017] usb 4-2: reset full-speed USB device number 2 using uhci_hcd 2014-04-28T12:51:58.399957+02:00 AmonLanc kernel: [137218.473541] PM: restore of devices complete after 1034.498 msecs 2014-04-28T12:51:58.399960+02:00 AmonLanc kernel: [137218.862203] Restarting kernel threads ... done. 2014-04-28T12:51:58.399962+02:00 AmonLanc kernel: [137218.865089] Restarting tasks ... done. 2014-04-28T12:51:58.399965+02:00 AmonLanc kernel: [137218.871900] PM: Basic memory bitmaps freed 2014-04-28T12:52:01.173911+02:00 AmonLanc dbus[1490]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper) 2014-04-28T12:52:01.700733+02:00 AmonLanc pm-utils: Thawing (95)... 2014-04-28T12:52:01.928066+02:00 AmonLanc dbus[1490]: [system] Activated service 'org.freedesktop.PackageKit' failed: Cannot launch daemon, file not found or permissions invalid 2014-04-28T12:52:02.426069+02:00 AmonLanc network[21963]: redirecting to "systemctl restart network.service" 2014-04-28T12:52:02.433872+02:00 AmonLanc systemd[1]: Stopping ifup managed network interface eth0... 2014-04-28T12:52:02.436145+02:00 AmonLanc systemd[1]: Stopping LSB: Configure network interfaces and set up routing... 2014-04-28T12:52:02.565994+02:00 AmonLanc systemd[1]: Starting LSB: Configure network interfaces and set up routing... 2014-04-28T12:52:03.105363+02:00 AmonLanc ifdown[21980]: eth0 device: National Semiconductor Corporation DP83815 (MacPhyter) Ethernet Controller 2014-04-28T12:52:03.112182+02:00 AmonLanc ifdown[21980]: eth0 device: National Semiconductor Corporation DP83815 (MacPhyter) Ethernet Controller 2014-04-28T12:52:03.368314+02:00 AmonLanc network[21991]: Setting up network interfaces: 2014-04-28T12:52:03.905985+02:00 AmonLanc network[21991]: lo ·····························++- Now, about the application itself. It is using java. Actually, the problem started about two days ago, when I installed oracle java to see if it solved a different issue. Before it was using java-1_7_0-openjdk-1.7.0.6-24.13.5.i586, which as far as I remember doesn't have this particular problem. The application itself is jdownloader (jdupdate.jar), an application to download things on its own (http://jdownloader.org). When it is running it impedes hibernation, probably intentionally, because it would abort a long download which would then have to be restarted (these sites often do not allow retaking partials downloads). But that is of no consequence to me, as I time the hibernation to happen after the download completed while I sleep (via 'at'). My guess is then that the functionality to impede hibernation fails with java-1_7_0-openjdk-1.7.0.6-24.13.5.i586, but not with jre-1.7.0_55-fcs.i586. But I'm surprised that there is no entry at all in the logs about why the hibernation was aborted. BUG somewhere? So, my problem now is to force hibernation to happen, perhaps by suspending the application itself or directly killing it. I know about "fg". But "bg" doesn't seem to be for "suspending" a process, just sends a process to background. Or I can revert to openjdk. - -- Cheers Carlos E. R. (from 13.1 x86_64 "Bottle" at Telcontar) -----BEGIN PGP SIGNATURE----- Version: GnuPG v2.0.22 (GNU/Linux) iEYEARECAAYFAlNeRCsACgkQtTMYHG2NR9UIMgCfY+FJkGzJd0gHMvMSAaBRo5TN mKoAoJBUe+XZsEJvUYD9eRNG7N/rqcQ1 =Zx5P -----END PGP SIGNATURE-----
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On 4/28/2014 5:06 AM, Carlos E. R. wrote:
2014-04-28T12:56:31.561440+02:00 AmonLanc dbus[1490]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper)
That seems to be the first thing activated after the un-wanted thaw, but I don't know if that is significant or not. There were 15 seconds unlogged just after wake, and before Pmutils indicates it is thawing. When you manually select a hibernate does it behave the same? If so, can you unplug the cat5 cable before suspending? In hibernation, I believe (correct me if I'm wrong) that your nic is still powered, and if so, it might be seeing something that tells it to wake. - -- _____________________________________ - ---This space for rent--- -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.9 (MingW32) iEYEARECAAYFAlNejE4ACgkQv7M3G5+2DLLwEwCfUFnoVCRru1a0qk/o3FQhWFjn IlEAoKpiv8gviTUi7bgtMzjKxC3GMRr9 =SEk6 -----END PGP SIGNATURE----- -- To unsubscribe, e-mail: opensuse+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse+owner@opensuse.org
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA256 El 2014-04-28 a las 10:13 -0700, John Andersen escribió:
On 4/28/2014 5:06 AM, Carlos E. R. wrote:
2014-04-28T12:56:31.561440+02:00 AmonLanc dbus[1490]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper)
That seems to be the first thing activated after the un-wanted thaw, but I don't know if that is significant or not. There were 15 seconds unlogged just after wake, and before Pmutils indicates it is thawing.
When you manually select a hibernate does it behave the same?
That was actually a manual hibernate, by calling "pm-hibernate" as root. I wanted to see it by myself, before that I thought that it might not like if being called from "at".
If so, can you unplug the cat5 cable before suspending?
I'm not at home now, but I can try that when I get back.
In hibernation, I believe (correct me if I'm wrong) that your nic is still powered, and if so, it might be seeing something that tells it to wake.
No, one of the pm-utils scripts disconnects networking before telling the kernel to hibernate. And anyway, that's not a problem: hibernating succeeds if that particular application is closed first. And I have hibernated with nfs and ssh connections active, sometimes during actual file transfers... (which crashed). I can handle that, I think: killall applicationname sleep 30 killall applicationname sleep 5 pm-hibernate. But how can an application inhibit hibernate, and do so AFTER all pm-utils scripts run, in a way that NOTHING is logged about that inhibition? I can understand *that* application not wanting to hibernate, yes, but not that this is not logged. Something else. In /etc/apparmor.d/usr.lib.dovecot.imap there is this entry: deny capability block_suspend, So dovecot may want at some time to inhibit hibernation, and the current apparmor forbids that. Yet I'm profiling this java application with apparmour, and i have not seen that request. I might add that prohibition explicitly in my custom profile and see... - -- Cheers Carlos E. R. (from 13.1 x86_64 "Bottle" (Minas Tirith)) -----BEGIN PGP SIGNATURE----- Version: GnuPG v2.0.22 (GNU/Linux) iF4EAREIAAYFAlNfCHUACgkQja8UbcUWM1yU/QD/ZoMTOt9YeSa7t0CZl7WDG23c 0G9OrLJJEk0yxIVTLkIA/RZfdkxbz2wL5pMh3caVV81vYpFMWUdWf6OZbFcbczAY =16qB -----END PGP SIGNATURE-----
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On Tuesday, 2014-04-29 at 04:03 +0200, Carlos E. R. wrote:
On 4/28/2014 5:06 AM, Carlos E. R. wrote:
If so, can you unplug the cat5 cable before suspending?
I'm not at home now, but I can try that when I get back.
Ok, back here. Yesterday automatic hibernation failed. So in the morning (yesterday), IIRC, I did: · try manual himbernation (pm-hibernate), which failed. · pull the cable, try again: success. So I think: you were right! I write a little script to stop network (rcnetwork stop), and hibernate. I called this from "at" this night. Failed. I had made a little mistake in the script and it failed to run. So this morning: · corrected the script · call it: network is stopped, hibernation called, failure (when the kernel attempts to hibernate, with no error message: it just aborts). · Edit the script: add "killall java". · Call it a second time: success. So at this point I don't know if I have to kill both java and network, or I have to call hibernation twice! I'll find that out tonight, that is, tomorrow morning. I suppose. - -- Cheers, Carlos E. R. (from 13.1 x86_64 "Bottle" at Telcontar) -----BEGIN PGP SIGNATURE----- Version: GnuPG v2.0.22 (GNU/Linux) iEYEARECAAYFAlNjegoACgkQtTMYHG2NR9VjmwCgj1kvTX/GFcwvYiIWhTf2yLhj wLAAniNfP4oPyWGnrvaJiV7wbpN2y/Ky =vprK -----END PGP SIGNATURE-----
participants (3)
-
Carlos E. R. -
Carlos E. R. -
John Andersen