New issue
Advanced search Search tips
Note: Color blocks (like █ or █) mean that a user may not be available. Tooltip shows the reason.

Issue 705333 link

Starred by 1 user
Status: WontFix
Owner: ----
Closed: Jul 2017
Cc:
cros-perf-detectives@google.com
bleung@chromium.org
drinkcat@chromium.org
snanda@chromium.org
chromeos-performance-bugs@google.com
█ djkurtz@chromium.org
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 3
Type: Bug-Regression



Sign in to add a comment

Elm: resume time variance increased since 58.9332.0.0

Project Member Reported by littlecvr@chromium.org, Mar 27 2017 
Crosbolt dashboard (https://cros-goldeneye.corp.google.com/console/listCrosbolt) shows that Elm's resume time variance increased a lot since 58.9332.0.0.
Screenshot from 2017-03-27 12:04:24.png
84.1 KB View Download

Comment 1 by littlecvr@chromium.org, Mar 27 2017

Cc: chromeos-performance-bugs@google.com cros-perf-detectives@google.com

Comment 2 by littlecvr@chromium.org, Mar 27 2017

Cc: drinkcat@chromium.org djkurtz@chromium.org

Comment 3 by littlecvr@chromium.org, Mar 27 2017

Labels: -Type-Bug OS-Chrome Type-Bug-Regression

Comment 4 by littlecvr@chromium.org, Mar 27 2017 

I guess this is probably not a time critical issue for now since 0.15 secs and 0.55 secs are both fast enough for resuming. But we may still want to know the reason because there may actually be a big issue under the surface.

Comment 5 by littlecvr@chromium.org, Mar 27 2017 

Thanks Nicolas' help, seems that all bad results (~0.55) were coming from one device: chromeos2-row7-rack10-host11. All other devices gave good results (~0.15).

Comment 6 by littlecvr@chromium.org, Mar 27 2017

Cc: snanda@chromium.org
Comparing the system log between good and bad devices:

GOOD
2017-03-10T20:48:19.144292+00:00 INFO kernel: [  437.121666] calling  rfkill1+ @ 5893, parent: phy0
2017-03-10T20:48:19.144299+00:00 INFO kernel: [  437.121684] call rfkill1+ returned 0 after 2 usecs
2017-03-10T20:48:19.144306+00:00 INFO kernel: [  437.121717] PM: resume of devices complete after 123.161 msecs

BAD
2017-03-02T23:51:45.548039+00:00 INFO kernel: [  145.414668] calling  rfkill1+ @ 3922, parent: phy0
2017-03-02T23:51:45.548046+00:00 INFO kernel: [  145.414687] call rfkill1+ returned 0 after 2 usecs
2017-03-02T23:51:45.548049+00:00 INFO kernel: [  145.436919] call 2-1.2+ returned 0 after 58250 usecs
2017-03-02T23:51:45.548052+00:00 INFO kernel: [  145.499524] usb 1-2.2.4: reset high-speed USB device number 6 using xhci-mtk
2017-03-02T23:51:45.548055+00:00 INFO kernel: [  145.826860] call 1-2.2.4+ returned 0 after 485186 usecs
2017-03-02T23:51:45.548058+00:00 INFO kernel: [  145.826884] calling  1-2.2.4.1+ @ 3950, parent: 1-2.2.4
2017-03-02T23:51:45.548061+00:00 INFO kernel: [  145.826891] call 1-2.2.4.1+ returned 0 after 0 usecs
2017-03-02T23:51:45.548064+00:00 INFO kernel: [  145.827057] PM: resume of devices complete after 536.756 msecs

Note the differences starting from line 3, the bad device tried to reset the USB device and spent about 400 msecs (which is exact the time difference).

Comment 7 by drinkcat@chromium.org, Mar 27 2017 

2017-03-02T23:51:45.548052+00:00 INFO kernel: [  145.499524] usb 1-2.2.4: reset high-speed USB device number 6 using xhci-mtk

Which device is this? Maybe start by comparing lsusb on both "GOOD" and "BAD" devices?

Comment 8 by deanliao@chromium.org, Mar 28 2017 

Resume is hard because different USB tree brings different result.

Though this is not performance critical, it worths investigation. Perhaps someday a failed resume would be root-caused by a bad USB tree.

Comment 9 by littlecvr@chromium.org, Mar 28 2017 

The "1-2.2.4" USB device exists on both GOOD and BAD DUTs. But they are connected to different hubs.

GOOD
usb1     Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
1-2      Bus 001 Device 003: ID 0bda:5416 Realtek Semiconductor Corp.
1-2.1    Bus 001 Device 004: ID 1a40:0101 Terminus Technology Inc. Hub
1-2.1.3  Bus 001 Device 006: ID 0424:9514 Standard Microsystems Corp. SMC9514 Hub

BAD
usb1     Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
1-2      Bus 001 Device 003: ID 0bda:5416 Realtek Semiconductor Corp.
1-2.2    Bus 001 Device 005: ID 2109:2813
1-2.2.4  Bus 001 Device 006: ID 0424:9514 Standard Microsystems Corp. SMC9514 Hub

1-2.2 on BAD DUT has no name in `lsusb`, but `lsusb -v` says it's a VIA USB 2.0 hub.

Checking into messages, the kernel tries to wake up the parent and then the children. The kernel thinks that SMC9514 device takes 400 msecs to reset, but probably it's because of the parents?

BTW, I tried on my local DUT: if it is connected to an Apple network dongle it would take 400 msecs more to resume, too.
elm-lsusb-BAD.txt
53.7 KB View Download
elm-lsusb-GOOD.txt
49.7 KB View Download
messages-BAD.txt
106 KB View Download
messages-GOOD.txt
104 KB View Download

Comment 10 by littlecvr@chromium.org, Mar 28 2017

Labels: Performance-Sheriff

Comment 11 by vpalatin@google.com, Mar 31 2017

Cc: bleung@chromium.org
I thought we tried to do the USB ones asynchronously (as in device_enable_async_suspend())
Per se, I think all USB devices are asynchronous since device_enable_async_suspend() is called in usb_new_device(), but they might have children which are not ? preventing them ?

Adding Benson who might know the details.

Comment 12 by vpalatin@google.com, Mar 31 2017 

On chromeos2-row7-rack10-host11, I'm currently seeing:

# lsusb
Bus 001 Device 007: ID 0424:ec00 Standard Microsystems Corp. SMSC9512/9514 Fast Ethernet Adapter
Bus 001 Device 006: ID 0424:9514 Standard Microsystems Corp. SMC9514 Hub
Bus 002 Device 003: ID 2109:0813  
Bus 001 Device 005: ID 2109:2813  
Bus 001 Device 004: ID 0b95:1780 ASIX Electronics Corp. AX88178
Bus 002 Device 002: ID 0bda:0416 Realtek Semiconductor Corp. 
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 003: ID 0bda:5416 Realtek Semiconductor Corp. 
Bus 001 Device 002: ID 04f2:b567 Chicony Electronics Co., Ltd 
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

# lsusb -t
/:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=xhci-mtk/1p, 5000M
    |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/2p, 5000M
        |__ Port 2: Dev 3, If 0, Class=Hub, Driver=hub/4p, 5000M
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=xhci-mtk/2p, 480M
    |__ Port 1: Dev 2, If 0, Class=Video, Driver=uvcvideo, 480M
    |__ Port 1: Dev 2, If 1, Class=Video, Driver=uvcvideo, 480M
    |__ Port 2: Dev 3, If 0, Class=Hub, Driver=hub/2p, 480M
        |__ Port 1: Dev 4, If 0, Class=Vendor Specific Class, Driver=asix, 480M
        |__ Port 2: Dev 5, If 0, Class=Hub, Driver=hub/4p, 480M
            |__ Port 4: Dev 6, If 0, Class=Hub, Driver=hub/5p, 480M
                |__ Port 1: Dev 7, If 0, Class=Vendor Specific Class, Driver=smsc95xx, 480M

usb1/1-1/ep_00/power/async >> enabled
usb1/1-1/power/async >> enabled
usb1/1-1/1-1:1.0/ep_87/power/async >> enabled
usb1/1-1/1-1:1.0/power/async >> enabled
usb1/1-1/1-1:1.0/video4linux/video4/power/async >> disabled
usb1/1-1/1-1:1.1/power/async >> enabled
usb1/1-2/1-2.1/ep_00/power/async >> enabled
usb1/1-2/1-2.1/power/async >> enabled
usb1/1-2/1-2.1/1-2.1:1.0/net/eth0/power/async >> disabled
usb1/1-2/1-2.1/1-2.1:1.0/ep_03/power/async >> enabled
usb1/1-2/1-2.1/1-2.1:1.0/ep_81/power/async >> enabled
usb1/1-2/1-2.1/1-2.1:1.0/ep_82/power/async >> enabled
usb1/1-2/1-2.1/1-2.1:1.0/power/async >> enabled
usb1/1-2/1-2.2/ep_00/power/async >> enabled
usb1/1-2/1-2.2/power/async >> enabled
usb1/1-2/1-2.2/1-2.2:1.0/ep_81/power/async >> enabled
usb1/1-2/1-2.2/1-2.2:1.0/power/async >> enabled
usb1/1-2/1-2.2/1-2.2:1.0/1-2.2-port1/power/async >> enabled
usb1/1-2/1-2.2/1-2.2:1.0/1-2.2-port2/power/async >> enabled
usb1/1-2/1-2.2/1-2.2:1.0/1-2.2-port3/power/async >> enabled
usb1/1-2/1-2.2/1-2.2:1.0/1-2.2-port4/power/async >> enabled
usb1/1-2/1-2.2/1-2.2.4/ep_00/power/async >> enabled
usb1/1-2/1-2.2/1-2.2.4/power/async >> enabled
usb1/1-2/1-2.2/1-2.2.4/1-2.2.4.1/ep_00/power/async >> enabled
usb1/1-2/1-2.2/1-2.2.4/1-2.2.4.1/power/async >> enabled
usb1/1-2/1-2.2/1-2.2.4/1-2.2.4.1/1-2.2.4.1:1.0/net/eth1/power/async >> disabled
usb1/1-2/1-2.2/1-2.2.4/1-2.2.4.1/1-2.2.4.1:1.0/ep_02/power/async >> enabled
usb1/1-2/1-2.2/1-2.2.4/1-2.2.4.1/1-2.2.4.1:1.0/ep_81/power/async >> enabled
usb1/1-2/1-2.2/1-2.2.4/1-2.2.4.1/1-2.2.4.1:1.0/ep_83/power/async >> enabled
usb1/1-2/1-2.2/1-2.2.4/1-2.2.4.1/1-2.2.4.1:1.0/power/async >> enabled
usb1/1-2/1-2.2/1-2.2.4/1-2.2.4:1.0/ep_81/power/async >> enabled
usb1/1-2/1-2.2/1-2.2.4/1-2.2.4:1.0/power/async >> enabled
usb1/1-2/1-2.2/1-2.2.4/1-2.2.4:1.0/1-2.2.4-port1/power/async >> enabled
usb1/1-2/1-2.2/1-2.2.4/1-2.2.4:1.0/1-2.2.4-port2/power/async >> enabled
usb1/1-2/1-2.2/1-2.2.4/1-2.2.4:1.0/1-2.2.4-port3/power/async >> enabled
usb1/1-2/1-2.2/1-2.2.4/1-2.2.4:1.0/1-2.2.4-port4/power/async >> enabled
usb1/1-2/1-2.2/1-2.2.4/1-2.2.4:1.0/1-2.2.4-port5/power/async >> enabled
usb1/1-2/ep_00/power/async >> enabled
usb1/1-2/power/async >> enabled
usb1/1-2/1-2:1.0/ep_81/power/async >> enabled
usb1/1-2/1-2:1.0/power/async >> enabled
usb1/1-2/1-2:1.0/1-2-port1/power/async >> enabled
usb1/1-2/1-2:1.0/1-2-port2/power/async >> enabled
usb1/ep_00/power/async >> enabled
usb1/power/async >> enabled
usb1/1-0:1.0/ep_81/power/async >> enabled
usb1/1-0:1.0/power/async >> enabled
usb1/1-0:1.0/usb1-port1/power/async >> enabled
usb1/1-0:1.0/usb1-port2/power/async >> enabled
usb2/2-1/2-1.2/ep_00/power/async >> enabled
usb2/2-1/2-1.2/power/async >> enabled
usb2/2-1/2-1.2/2-1.2:1.0/ep_81/power/async >> enabled
usb2/2-1/2-1.2/2-1.2:1.0/power/async >> enabled
usb2/2-1/2-1.2/2-1.2:1.0/2-1.2-port1/power/async >> enabled
usb2/2-1/2-1.2/2-1.2:1.0/2-1.2-port2/power/async >> enabled
usb2/2-1/2-1.2/2-1.2:1.0/2-1.2-port3/power/async >> enabled
usb2/2-1/2-1.2/2-1.2:1.0/2-1.2-port4/power/async >> enabled
usb2/2-1/ep_00/power/async >> enabled
usb2/2-1/power/async >> enabled
usb2/2-1/2-1:1.0/ep_81/power/async >> enabled
usb2/2-1/2-1:1.0/power/async >> enabled
usb2/2-1/2-1:1.0/2-1-port1/power/async >> enabled
usb2/2-1/2-1:1.0/2-1-port2/power/async >> enabled
usb2/ep_00/power/async >> enabled
usb2/power/async >> enabled
usb2/2-0:1.0/ep_81/power/async >> enabled
usb2/2-0:1.0/power/async >> enabled
usb2/2-0:1.0/usb2-port1/power/async >> enabled

this shows that only the ethernet device of the smsc9514 behind the hub has the 'async_suspend' disabled:
"usb1/1-2/1-2.2/1-2.2.4/1-2.2.4.1/1-2.2.4.1:1.0/net/eth1/power/async >> disabled"
(along with the other ethernet dongle and the V4L2 camera device)
Might worth try to turn them on.

Comment 13 by benhenry@chromium.org, Jul 27 2017

Status: WontFix (was: Untriaged)
This alert was found before M-60 branched. Closing as WontFix as this is believed to either be invalid or non-reproducible.
►

Sign in to add a comment