Message-ID: <20171229155714.GA30656@amd>
Date:   Fri, 29 Dec 2017 16:57:14 +0100
From:   Pavel Machek <pavel@....cz>
To:     kernel list <linux-kernel@...r.kernel.org>,
        "Rafael J. Wysocki" <rjw@...ysocki.net>,
        Linux-pm mailing list <linux-pm@...r.kernel.org>
Cc:     gregkh@...uxfoundation.org, linux-usb@...r.kernel.org
Subject: v4.15-rc5: resume took way too long, warning in syslog

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

Download attachment "delme.gz" of type "application/gzip" (27340 bytes)

Download attachment "delme.gz" of type "application/gzip" (27340 bytes)

Download attachment "signature.asc" of type "application/pgp-signature" (182 bytes)

Powered by blists - more mailing lists