Hi! v4.15-rc5.. resume took _way_ too long, and I have warn_on in dmesg as a bonus. It looks like USB problem...? I never seen this before. Pavel [42266.070103] PM: Syncing filesystems ... done. [42266.948883] Freezing user space processes ... (elapsed 0.003 seconds) done. [42266.952336] OOM killer disabled. [42266.952338] Freezing remaining freezable tasks ... (elapsed 0.003 seconds) done. [42266.956273] Suspending console(s) (use no_console_suspend to debug) [42267.148227] sd 0:0:0:0: [sda] Synchronizing SCSI cache [42267.148629] sd 0:0:0:0: [sda] Stopping disk [42267.225212] e1000e: EEE TX LPI TIMER: 00000011 [42267.723975] PM: suspend devices took 0.764 seconds [42267.796905] ACPI: Preparing to enter system sleep state S3 [42268.140237] ACPI: EC: event blocked [42268.140242] ACPI: EC: EC stopped [42268.140247] PM: Saving platform NVS memory [42268.140275] Disabling non-boot CPUs ... [42268.159546] smpboot: CPU 1 is now offline [42268.183574] smpboot: CPU 2 is now offline [42268.213618] IRQ 19: no longer affine to CPU3 [42268.214663] smpboot: CPU 3 is now offline [42268.217690] ACPI: Low-level resume complete [42268.217757] ACPI: EC: EC started [42268.217758] PM: Restoring platform NVS memory [42268.218070] Enabling non-boot CPUs ... [42268.219625] x86: Booting SMP configuration: [42268.219629] smpboot: Booting Node 0 Processor 1 APIC 0x1 [42268.220144] Disabled fast string operations [42268.317954] cache: parent cpu1 should not be sleeping [42268.318395] CPU1 is up [42268.320852] smpboot: Booting Node 0 Processor 2 APIC 0x2 [42268.321562] Disabled fast string operations [42268.421952] cache: parent cpu2 should not be sleeping [42268.422447] CPU2 is up [42268.424900] smpboot: Booting Node 0 Processor 3 APIC 0x3 [42268.425607] Disabled fast string operations [42268.521949] cache: parent cpu3 should not be sleeping [42268.522594] CPU3 is up [42268.527660] ACPI: Waking up from system sleep state S3 [42269.202432] sdhci-pci 0000:0d:00.0: MMC controller base frequency changed to 50Mhz. [42269.239534] iwlwifi 0000:03:00.0: RF_KILL bit toggled to disable radio. [42269.240825] ACPI: EC: event unblocked [42269.244977] sd 0:0:0:0: [sda] Starting disk [42269.489765] usb 1-1.3: reset full-speed USB device number 3 using ehci-pci [42269.577806] ata2: SATA link down (SStatus 0 SControl 300) [42269.577851] ata5: SATA link down (SStatus 0 SControl 300) [42269.677809] usb 1-1.6: reset high-speed USB device number 4 using ehci-pci [42270.167923] psmouse serio1: synaptics: queried max coordinates: x [..5472], y [..4448] [42270.361825] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300) [42270.363396] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded [42270.363404] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out [42270.363409] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out [42270.366202] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded [42270.366209] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out [42270.366215] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out [42270.367116] ata1.00: configured for UDMA/133 [42273.571626] e1000e: eth2 NIC Link is Up 100 Mbps Full Duplex, Flow Control: Rx/Tx [42273.571638] e1000e 0000:00:19.0 eth2: 10/100 speed: disabling TSO [42274.421868] usb 2-1.1.4: reset high-speed USB device number 55 using ehci-pci [42279.541849] usb 2-1.1.4: device descriptor read/64, error -110 [42295.157864] usb 2-1.1.4: device descriptor read/64, error -110 [42295.345865] usb 2-1.1.4: reset high-speed USB device number 55 using ehci-pci [42300.533867] usb 2-1.1.4: device descriptor read/64, error -110 [42316.149843] usb 2-1.1.4: device descriptor read/64, error -110 [42316.337864] usb 2-1.1.4: reset high-speed USB device number 55 using ehci-pci [42327.029859] usb 2-1.1.4: device not accepting address 55, error -110 [42327.113863] usb 2-1.1.4: reset high-speed USB device number 55 using ehci-pci [42337.781888] usb 2-1.1.4: device not accepting address 55, error -110 [42337.785431] PM: resume devices took 68.544 seconds [42337.785436] ------------[ cut here ]------------ [42337.785441] Component: resume devices, time: 68544 [42337.785467] WARNING: CPU: 1 PID: 30277 at kernel/power/suspend_test.c:55 suspend_test_finish+0x73/0x80 [42337.785471] Modules linked in: [42337.785483] CPU: 1 PID: 30277 Comm: systemd-sleep Not tainted 4.15.0-rc5 #146 [42337.785487] Hardware name: LENOVO 42872WU/42872WU, BIOS 8DET73WW (1.43 ) 10/12/2016 [42337.785495] RIP: 0010:suspend_test_finish+0x73/0x80 [42337.785500] RSP: 0000:ffffc9000f617cf8 EFLAGS: 00010292 [42337.785509] RAX: 0000000000000026 RBX: ffffffff84f9320a RCX: 000000004566332b [42337.785514] RDX: 000000000b0ce99a RSI: ffff8801835a11f8 RDI: ffffffff85246380 [42337.785518] RBP: ffffc9000f617d08 R08: ffff8801835a11d0 R09: 0000000000000000 [42337.785523] R10: 00000000dc463ffc R11: 3a656d6974202c01 R12: 0000000000010bc0 [42337.785527] R13: 0000000000000000 R14: ffffc9000f617f00 R15: fffffffffffffff2 [42337.785533] FS: 0000000000000000(0000) GS:ffff88019e240000(0063) knlGS:00000000f7d1b700 [42337.785538] CS: 0010 DS: 002b ES: 002b CR0: 0000000080050033 [42337.785542] CR2: 0000000000000000 CR3: 000000017182e002 CR4: 00000000000606a0 [42337.785547] Call Trace: [42337.785558] suspend_devices_and_enter+0x166/0x5e0 [42337.785566] pm_suspend+0x279/0x2f0 [42337.785573] state_store+0x62/0xa0 [42337.785583] kobj_attr_store+0xf/0x20 [42337.785594] sysfs_kf_write+0x40/0x50 [42337.785602] kernfs_fop_write+0x11a/0x1a0 [42337.785611] __vfs_write+0x23/0x130 [42337.785617] ? vfs_write+0x15c/0x180 [42337.785625] ? __sb_start_write+0xed/0x180 [42337.785631] ? vfs_write+0x15c/0x180 [42337.785638] vfs_write+0xaf/0x180 [42337.785646] ? up_read+0x1a/0x40 [42337.785653] SyS_write+0x44/0xb0 [42337.785664] do_int80_syscall_32+0x5b/0x120 [42337.785674] entry_INT80_compat+0x2c/0x40 [42337.785680] RIP: 0023:0xf7f0dc42 [42337.785685] RSP: 002b:00000000ffa274e4 EFLAGS: 00000246 ORIG_RAX: 0000000000000004 [42337.785694] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00000000f7f0a000 [42337.785698] RDX: 0000000000000004 RSI: 0000000000000004 RDI: 00000000f7f0a000 [42337.785702] RBP: 00000000565ab050 R08: 0000000000000000 R09: 0000000000000000 [42337.785707] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000 [42337.785711] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000 [42337.785718] Code: 29 c1 31 c0 e8 ca a7 00 00 41 81 fc 10 27 00 00 77 05 5b 41 5c 5d c3 44 89 e2 48 89 de 48 c7 c7 01 34 f9 84 31 c0 e8 7d 01 fb ff <0f> ff 5b 41 5c 5d c3 90 90 90 90 90 90 55 0f b6 05 4c 0d c9 01 [42337.785966] ---[ end trace a926c3e188989851 ]--- [42337.786889] OOM killer enabled. [42337.786898] Restarting tasks ... [42337.795617] systemd[1]: Starting Journal Service... [42337.796629] usb 2-1.1.4: USB disconnect, device number 55 [42337.796819] cdc_ether 2-1.1.4:1.0 usb0: unregister 'cdc_ether' usb-0000:00:1d.0-1.1.4, CDC Ethernet Device [42337.800341] done. [42337.813790] PM: suspend exit [42337.816608] systemd[1]: Started Suspend. [42337.816671] systemd[1]: Requested transaction contradicts existing jobs: File exists [42337.816682] systemd[1]: Service sleep.target is not needed anymore. Stopping. [42337.817078] systemd[1]: Stopping Sleep. [42337.817095] systemd[1]: Stopped target Sleep. [42337.817125] systemd[1]: Reached target Suspend. [42337.818135] systemd[1]: Starting Run anacron jobs at resume... [42337.819217] systemd[1]: Started Run anacron jobs at resume. [42337.913753] usb 2-1.1.4: new high-speed USB device number 56 using ehci-pci [42338.395078] e1000e: eth2 NIC Link is Down [42338.732172] systemd-journald[2470]: Received SIGTERM from PID 1 (systemd). [42339.679602] systemd[1]: Unit systemd-journald.service entered failed state. [42340.426957] systemd-journald[30462]: Received request to flush runtime journal from PID 1 [42343.029871] usb 2-1.1.4: device descriptor read/64, error -110 [42344.483918] e1000e: eth2 NIC Link is Up 100 Mbps Full Duplex, Flow Control: Rx/Tx [42344.483927] e1000e 0000:00:19.0 eth2: 10/100 speed: disabling TSO [42358.645164] usb 2-1.1.4: device descriptor read/64, error -110 [42358.833023] usb 2-1.1.4: new high-speed USB device number 57 using ehci-pci [42364.018463] usb 2-1.1.4: device descriptor read/64, error -110 [42379.626669] usb 2-1.1.4: device descriptor read/64, error -110 [42379.735177] usb 2-1.1-port4: attempt power cycle [42380.338299] usb 2-1.1.4: new high-speed USB device number 58 using ehci-pci -- (english) http://www.livejournal.com/~pavelmachek (cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html
Attachment:
delme.gz
Description: application/gzip
Attachment:
delme.gz
Description: application/gzip
Attachment:
signature.asc
Description: Digital signature
