Re: v4.15-rc5: resume took way too long, warning in syslog
On Fri 2017-12-29 11:23:36, Alan Stern wrote: > On Fri, 29 Dec 2017, Pavel Machek wrote: > > > 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. > > Is this problem very repeatable? Is there any possibility of bisecting > to find the cause? It is first time this happened.. Let me see if it reappears. But I start to get feeling, that something like this is simply going to happen from time to time... USB hubs are not exactly high-quality parts, EMI, ... Pavel > > [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 :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.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 :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 > > It sure looks like that USB device (or maybe the hub it was connected > to) decided to stop working during the suspend. > > Alan Stern -- (english) http://www.livejournal.com/~pavelmachek (cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html signature.asc Description: Digital signature
Re: v4.15-rc5: resume took way too long, warning in syslog
On Fri, 29 Dec 2017, Pavel Machek wrote: > 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. Is this problem very repeatable? Is there any possibility of bisecting to find the cause? > [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 :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.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 :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 It sure looks like that USB device (or maybe the hub it was connected to) decided to stop working during the suspend. Alan Stern -- To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
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: 0011 [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 :0d:00.0: MMC controller base frequency changed to 50Mhz. [42269.239534] iwlwifi :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 :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: :c9000f617cf8 EFLAGS: 00010292 [42337.785509] RAX: 0026 RBX: 84f9320a RCX: 4566332b [42337.785514] RDX: 0b0ce99a RSI: 8801835a11f8 RDI: 85246380 [42337.785518] RBP: c9000f617d08 R08: 8801835a11d0 R09: [42337.785523] R10:
