Attachment 204331 Details for Bug 249911 – Hibernate + resume logs; please see the 2x5 minutes time distance there.

Hibernate + resume logs; please see the 2x5 minutes time distance there.

hibernate-0 (text/plain), 14.76 KB, created by Jan Kratochvil on 2007-09-24 17:37:31 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Jan Kratochvil

Created: 2007-09-24 17:37:31 UTC

Size: 14.76 KB

patch

obsolete

>==> /var/log/messages <==
>Sep 24 18:10:03 host0 gnome-power-manager: (lace) Hibernating computer because clicked tray
>tail: /var/log/pm-suspend.log: file truncated
>
>==> /var/log/Xorg.0.log <==
>Synaptics DeviceOff called
>
>==> /var/log/messages <==
>Sep 24 18:10:04 host0 kernel: usb 5-1: USB disconnect, address 9
>Sep 24 18:10:04 host0 ntpd[7927]: ntpd exiting on signal 15
>
>==> /var/log/pm-suspend.log <==
>Mon Sep 24 18:10:04 CEST 2007: running hibernate hooks.
>===== Mon Sep 24 18:10:04 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/00clear =====
>===== Mon Sep 24 18:10:04 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/01grub =====
>===== Mon Sep 24 18:10:04 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/05led =====
>===== Mon Sep 24 18:10:04 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/10NetworkManager =====
>===== Mon Sep 24 18:10:04 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/20video =====
>===== Mon Sep 24 18:10:04 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/49bluetooth =====
>===== Mon Sep 24 18:10:04 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/50modules =====
>===== Mon Sep 24 18:10:04 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/55battery =====
>===== Mon Sep 24 18:10:04 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/60sysfont =====
>===== Mon Sep 24 18:10:04 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/65alsa =====
>===== Mon Sep 24 18:10:04 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/90clock =====
>Shutting down ntpd: [  OK  ]
>
>==> /var/log/audit/audit.log <==
>type=USYS_CONFIG msg=audit(1190650206.499:41): user pid=8169 uid=0 auid=4294967295 msg='changing system time: exe="/sbin/hwclock" (hostname=?, addr=?, terminal=? res=success)'
>
>==> /var/log/debug <==
>Sep 24 18:10:06 host0 kernel: PM: suspend-to-disk mode set to 'platform'
>
>==> /var/log/messages <==
>Sep 24 18:21:34 host0 kernel: swsusp: Marking nosave pages: 000000000009f000 - 0000000000100000
>
>==> /var/log/pm-suspend.log <==
>===== Mon Sep 24 18:10:06 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/94cpufreq =====
>===== Mon Sep 24 18:10:06 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/95led =====
>===== Mon Sep 24 18:10:06 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/99video =====
>Mon Sep 24 18:10:06 CEST 2007: done running hibernate hooks.
>
>==> /var/log/messages <==
>Sep 24 18:21:34 host0 kernel: swsusp: Basic memory bitmaps created
>Sep 24 18:21:34 host0 kernel: Stopping tasks ... done.
>Sep 24 18:21:34 host0 kernel: Shrinking memory...  #010-#010\#010|#010done (17568 pages freed)
>Sep 24 18:21:34 host0 kernel: Freed 70272 kbytes in 0.60 seconds (117.12 MB/s)
>Sep 24 18:21:34 host0 kernel: Suspending console(s)
>Sep 24 18:21:34 host0 kernel: snd-usb-audio 1-1.4:1.0: no suspend for driver snd-usb-audio?
>Sep 24 18:21:34 host0 kernel: snd-usb-audio 1-1.4:1.1: no suspend for driver snd-usb-audio?
>Sep 24 18:21:34 host0 kernel: snd-usb-audio 1-1.4:1.2: no suspend for driver snd-usb-audio?
>
>==> /var/log/debug <==
>Sep 24 18:21:34 host0 kernel: swsusp: Normal pages needed: 125109 + 1024 + 38, available pages: 398769
>Sep 24 18:21:34 host0 kernel: PCI: Setting latency timer of device 0000:00:01.0 to 64
>Sep 24 18:21:34 host0 kernel: PCI: Setting latency timer of device 0000:00:1b.0 to 64
>Sep 24 18:21:34 host0 kernel: PCI: Setting latency timer of device 0000:00:1c.0 to 64
>Sep 24 18:21:34 host0 kernel: PCI: Setting latency timer of device 0000:00:1c.1 to 64
>Sep 24 18:21:34 host0 kernel: PCI: Setting latency timer of device 0000:00:1c.2 to 64
>Sep 24 18:21:34 host0 kernel: PCI: Setting latency timer of device 0000:00:1c.3 to 64
>Sep 24 18:21:34 host0 kernel: PCI: Setting latency timer of device 0000:00:1d.0 to 64
>Sep 24 18:21:34 host0 kernel: PCI: Setting latency timer of device 0000:00:1d.1 to 64
>Sep 24 18:21:34 host0 kernel: PCI: Setting latency timer of device 0000:00:1d.2 to 64
>Sep 24 18:21:34 host0 kernel: PCI: Setting latency timer of device 0000:00:1d.3 to 64
>Sep 24 18:21:34 host0 kernel: PCI: Setting latency timer of device 0000:00:1d.7 to 64
>Sep 24 18:21:34 host0 kernel: PCI: cache line size of 32 is not supported by device 0000:00:1d.7
>Sep 24 18:21:34 host0 kernel: PCI: Setting latency timer of device 0000:00:1e.0 to 64
>Sep 24 18:21:34 host0 kernel: PCI: Setting latency timer of device 0000:00:1f.1 to 64
>Sep 24 18:21:34 host0 kernel: ata6: port disabled. ignoring.
>Sep 24 18:21:34 host0 kernel: PCI: Setting latency timer of device 0000:00:1f.2 to 64
>Sep 24 18:21:34 host0 kernel: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
>Sep 24 18:21:34 host0 kernel: PM: Image restored successfully.
>
>==> /var/log/messages <==
>Sep 24 18:21:34 host0 kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
>Sep 24 18:21:34 host0 kernel: ACPI: PCI interrupt for device 0000:00:1f.1 disabled
>Sep 24 18:21:34 host0 kernel: ACPI: PCI interrupt for device 0000:00:1d.7 disabled
>Sep 24 18:21:34 host0 kernel: ACPI: PCI interrupt for device 0000:00:1d.3 disabled
>Sep 24 18:21:34 host0 kernel: ACPI: PCI interrupt for device 0000:00:1d.2 disabled
>Sep 24 18:21:34 host0 kernel: ACPI: PCI interrupt for device 0000:00:1d.1 disabled
>Sep 24 18:21:34 host0 kernel: ACPI: PCI interrupt for device 0000:00:1d.0 disabled
>Sep 24 18:21:34 host0 kernel: ACPI: PCI interrupt for device 0000:00:1b.0 disabled
>Sep 24 18:21:34 host0 kernel: Disabling non-boot CPUs ...
>Sep 24 18:21:34 host0 kernel: kvm: disabling virtualization on CPU1
>Sep 24 18:21:34 host0 kernel: CPU 1 is now offline
>Sep 24 18:21:34 host0 kernel: lockdep: not fixing up alternatives.
>Sep 24 18:21:34 host0 kernel: CPU1 is down
>Sep 24 18:21:34 host0 kernel: Extended CMOS year: 2000
>Sep 24 18:21:34 host0 kernel: swsusp: critical section: 
>Sep 24 18:21:34 host0 kernel: swsusp: Need to copy 125109 pages
>Sep 24 18:21:34 host0 kernel: Extended CMOS year: 2000
>Sep 24 18:21:34 host0 kernel: Enabling non-boot CPUs ...
>Sep 24 18:21:34 host0 kernel: lockdep: not fixing up alternatives.
>Sep 24 18:21:34 host0 kernel: Booting processor 1/2 APIC 0x1
>Sep 24 18:21:34 host0 kernel: Initializing CPU#1
>Sep 24 18:21:34 host0 kernel: Calibrating delay using timer specific routine.. 3988.84 BogoMIPS (lpj=1994421)
>Sep 24 18:21:34 host0 kernel: CPU: L1 I cache: 32K, L1 D cache: 32K
>Sep 24 18:21:34 host0 kernel: CPU: L2 cache: 4096K
>Sep 24 18:21:34 host0 kernel: CPU 1/1 -> Node 0
>Sep 24 18:21:34 host0 kernel: CPU: Physical Processor ID: 0
>Sep 24 18:21:34 host0 kernel: CPU: Processor Core ID: 1
>Sep 24 18:21:34 host0 kernel: Intel(R) Core(TM)2 CPU         T7200  @ 2.00GHz stepping 06
>Sep 24 18:21:34 host0 kernel: kvm: enabling virtualization on CPU1
>Sep 24 18:21:34 host0 kernel: Switched to high resolution mode on CPU 1
>Sep 24 18:21:34 host0 kernel: CPU1 is up
>Sep 24 18:21:34 host0 kernel: ACPI: PCI Interrupt 0000:00:1b.0[B] -> GSI 17 (level, low) -> IRQ 17
>Sep 24 18:21:34 host0 kernel: ACPI: PCI Interrupt 0000:00:1d.0[A] -> GSI 16 (level, low) -> IRQ 16
>Sep 24 18:21:34 host0 kernel: usb usb2: root hub lost power or was reset
>Sep 24 18:21:34 host0 kernel: ACPI: PCI Interrupt 0000:00:1d.1[B] -> GSI 17 (level, low) -> IRQ 17
>Sep 24 18:21:34 host0 kernel: usb usb3: root hub lost power or was reset
>Sep 24 18:21:34 host0 kernel: ACPI: PCI Interrupt 0000:00:1d.2[C] -> GSI 18 (level, low) -> IRQ 18
>Sep 24 18:21:34 host0 kernel: usb usb4: root hub lost power or was reset
>Sep 24 18:21:34 host0 kernel: ACPI: PCI Interrupt 0000:00:1d.3[D] -> GSI 19 (level, low) -> IRQ 19
>Sep 24 18:21:34 host0 kernel: usb usb5: root hub lost power or was reset
>Sep 24 18:21:34 host0 kernel: ACPI: PCI Interrupt 0000:00:1d.7[D] -> GSI 19 (level, low) -> IRQ 19
>Sep 24 18:21:34 host0 kernel: usb usb1: root hub lost power or was reset
>Sep 24 18:21:34 host0 kernel: ehci_hcd 0000:00:1d.7: debug port 1
>Sep 24 18:21:34 host0 kernel: ACPI: PCI Interrupt 0000:00:1f.1[C] -> GSI 16 (level, low) -> IRQ 16
>Sep 24 18:21:34 host0 kernel: ACPI: PCI Interrupt 0000:01:00.0[A] -> GSI 16 (level, low) -> IRQ 16
>Sep 24 18:21:34 host0 kernel: Coming out of suspend...
>Sep 24 18:21:34 host0 kernel: ata3: SATA link down (SStatus 0 SControl 0)
>Sep 24 18:21:34 host0 kernel: ata2: SATA link down (SStatus 0 SControl 0)
>Sep 24 18:21:34 host0 kernel: ata4: SATA link down (SStatus 0 SControl 0)
>Sep 24 18:21:34 host0 kernel: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
>Sep 24 18:21:34 host0 kernel: ata1.00: configured for UDMA/100
>Sep 24 18:21:34 host0 kernel: sd 0:0:0:0: [sda] 195371568 512-byte hardware sectors (100030 MB)
>Sep 24 18:21:34 host0 kernel: sd 0:0:0:0: [sda] Write Protect is off
>Sep 24 18:21:34 host0 kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
>Sep 24 18:21:34 host0 kernel: ata5.00: configured for UDMA/33
>Sep 24 18:21:34 host0 kernel: sd 0:0:0:0: [sda] Starting disk
>Sep 24 18:21:34 host0 kernel: Restarting tasks ... <6>usb 1-1: USB disconnect, address 20
>Sep 24 18:21:34 host0 kernel: usb 1-1.1: USB disconnect, address 22
>Sep 24 18:21:34 host0 kernel: usb 1-1.2: USB disconnect, address 23
>Sep 24 18:21:34 host0 kernel: usb 1-1.4: USB disconnect, address 24
>Sep 24 18:21:34 host0 kernel: done.
>Sep 24 18:21:34 host0 kernel: swsusp: Basic memory bitmaps freed
>Sep 24 18:21:34 host0 kernel: usb 1-1: new high speed USB device using ehci_hcd and address 26
>Sep 24 18:21:34 host0 kernel: usb 1-1: configuration #1 chosen from 1 choice
>Sep 24 18:21:34 host0 kernel: hub 1-1:1.0: USB hub found
>Sep 24 18:21:34 host0 kernel: hub 1-1:1.0: 4 ports detected
>Sep 24 18:21:34 host0 kernel: usb 5-2: USB disconnect, address 8
>Sep 24 18:21:35 host0 kernel: usb 5-2: new full speed USB device using uhci_hcd and address 10
>Sep 24 18:21:35 host0 kernel: usb 5-2: configuration #1 chosen from 1 choice
>Sep 24 18:21:34 host0 acpid: received event "processor CPU0 00000081 00000000"
>Sep 24 18:21:35 host0 acpid: notifying client 3865[68:68]
>Sep 24 18:21:35 host0 acpid: notifying client 4680[0:0]
>Sep 24 18:21:35 host0 acpid: client has disconnected
>Sep 24 18:21:35 host0 acpid: completed event "processor CPU0 00000081 00000000"
>Sep 24 18:21:35 host0 acpid: received event "processor CPU1 00000081 00000000"
>Sep 24 18:21:35 host0 acpid: notifying client 3865[68:68]
>Sep 24 18:21:35 host0 acpid: completed event "processor CPU1 00000081 00000000"
>Sep 24 18:21:35 host0 acpid: received event "thermal_zone THM0 00000081 00000000"
>Sep 24 18:21:35 host0 acpid: notifying client 3865[68:68]
>Sep 24 18:21:35 host0 acpid: completed event "thermal_zone THM0 00000081 00000000"
>Sep 24 18:21:35 host0 kernel: usb 1-1.1: new low speed USB device using ehci_hcd and address 28
>Sep 24 18:21:34 host0 gnome-power-manager: (lace) Resuming computer
>Sep 24 18:21:35 host0 gnome-power-manager: (lace) hibernate failed
>Sep 24 18:21:35 host0 kernel: usb 1-1.1: configuration #1 chosen from 1 choice
>Sep 24 18:21:35 host0 kernel: input: Logitech USB-PS/2 Optical Mouse as /class/input/input18
>Sep 24 18:21:35 host0 kernel: input: USB HID v1.10 Mouse [Logitech USB-PS/2 Optical Mouse] on usb-0000:00:1d.7-1.1
>Sep 24 18:21:35 host0 kernel: usb 1-1.2: new low speed USB device using ehci_hcd and address 29
>Sep 24 18:21:35 host0 kernel: usb 1-1.2: configuration #1 chosen from 1 choice
>Sep 24 18:21:35 host0 kernel: input: CHICONY USB Keyboard as /class/input/input19
>Sep 24 18:21:35 host0 kernel: input: USB HID v1.10 Keyboard [CHICONY USB Keyboard] on usb-0000:00:1d.7-1.2
>Sep 24 18:21:36 host0 kernel: usb 1-1.4: new full speed USB device using ehci_hcd and address 30
>Sep 24 18:21:36 host0 kernel: usb 1-1.4: configuration #1 chosen from 1 choice
>
>==> /var/log/pm-suspend.log <==
>Mon Sep 24 18:21:36 CEST 2007: running thaw hooks.
>
>==> /var/log/audit/audit.log <==
>type=USYS_CONFIG msg=audit(1190650897.215:42): user pid=8402 uid=0 auid=4294967295 msg='changing system time: exe="/sbin/hwclock" (hostname=?, addr=?, terminal=? res=success)'
>
>==> /var/log/pm-suspend.log <==
>===== Mon Sep 24 18:21:36 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/99video =====
>===== Mon Sep 24 18:21:36 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/95led =====
>===== Mon Sep 24 18:21:36 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/94cpufreq =====
>===== Mon Sep 24 18:21:36 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/90clock =====
>===== Mon Sep 24 18:21:37 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/65alsa =====
>
>==> /var/log/Xorg.0.log <==
>(II) Open ACPI successful (/var/run/acpid.socket)
>
>==> /var/log/messages <==
>Sep 24 18:21:37 host0 acpid: client connected from 4680[0:0]
>Sep 24 18:21:37 host0 acpid: 1 client rule loaded
>
>==> /var/log/pm-suspend.log <==
>===== Mon Sep 24 18:21:37 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/60sysfont =====
>===== Mon Sep 24 18:21:37 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/55battery =====
>method return sender=:1.2 -> dest=:1.70 reply_serial=2
>   boolean true
>===== Mon Sep 24 18:21:37 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/50modules =====
>===== Mon Sep 24 18:21:37 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/49bluetooth =====
>===== Mon Sep 24 18:21:37 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/20video =====
>===== Mon Sep 24 18:21:37 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/10NetworkManager =====
>===== Mon Sep 24 18:21:37 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/05led =====
>===== Mon Sep 24 18:21:37 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/01grub =====
>===== Mon Sep 24 18:21:37 CEST 2007: running hook: /usr/lib/pm-utils/sleep.d/00clear =====
>Mon Sep 24 18:21:37 CEST 2007: done running thaw hooks.
>
>==> /var/log/messages <==
>Sep 24 18:21:38 host0 kernel: usb 5-1: new full speed USB device using uhci_hcd and address 11
>Sep 24 18:21:38 host0 kernel: usb 5-1: configuration #1 chosen from 1 choice
>
>==> /var/log/Xorg.0.log <==
>(II) Mouse0: ps2EnableDataReporting: succeeded
>Synaptics DeviceOn called
>(--) Synaptics auto-dev sets device to /dev/input/event2
>(**) Option "Device" "/dev/input/event2"
>(--) Synaptics touchpad found
>
>==> /var/log/pm-suspend.log <==
>ntpd: Synchronizing with time server: 
>==> /var/log/debug <==
>Sep 24 18:21:58 host0 ntpd[8584]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
>
>==> /var/log/messages <==
>Sep 24 18:21:58 host0 ntpdate[8581]: step time server 212.96.160.147 offset 0.013359 sec
>Sep 24 18:21:58 host0 ntpd[8583]: ntpd 4.2.4p2@1.1495-o Tue Aug 21 13:51:58 UTC 2007 (1)
>Sep 24 18:21:58 host0 ntpd[8584]: precision = 1.000 usec
>Sep 24 18:21:58 host0 ntpd[8584]: Listening on interface #0 wildcard, 0.0.0.0#123 Disabled
>Sep 24 18:21:58 host0 ntpd[8584]: Listening on interface #1 wildcard, ::#123 Disabled
>Sep 24 18:21:58 host0 ntpd[8584]: Listening on interface #2 lo, ::1#123 Enabled
>Sep 24 18:21:58 host0 ntpd[8584]: Listening on interface #3 wlan0, fe80::219:d2ff:fe29:8f1b#123 Enabled
>Sep 24 18:21:58 host0 ntpd[8584]: Listening on interface #4 lo, 127.0.0.1#123 Enabled
>Sep 24 18:21:58 host0 ntpd[8584]: Listening on interface #5 wlan0, 192.168.66.2#123 Enabled
>Sep 24 18:21:58 host0 ntpd[8584]: kernel time sync status 0040
>Sep 24 18:21:58 host0 ntpd[8584]: frequency initialized 145.173 PPM from /var/lib/ntp/drift
>
>==> /var/log/pm-suspend.log <==
>[  OK  ]
>Starting ntpd: [  OK  ]

Actions: View

Attachments on bug 249911: 204331