Hi Mathias,
thank you for your quick analysis. I tried to reproduce but only partially. I crashed the kernel in the end.
I placed the logs at http://195.113.57.32/~mmokrejs/Aukey_15port_hub.tar.bz2 (file size 799944)
Unpack and follow 'ls -latr' file ordering.
This will show I failed to reproduce the issue an the external drive was mounted:
diff -u -w dmesg-before.txt dmesg-after.txt
Therefore, the Aukey_15port_hub.success.mon.out should reveal proper behavior, not the 'Inactive' issue. Probably not much reason to study the file.
I tried again and again success, so another file Aukey_15port_hub.success_again.mon.out is probably useless. From the timestamp of this file you can infer which time period you can ignore (up to "now").
Then I hooked the external USB3 to SATA adapter with its drive to the Aukey HUB and powered on the HDD drive. That fooled Linux kernel, the port is dead and I would say this is same "behavior" as if the 'Inactive' issue caused Linux to kill USB ports and which cannot be cured by just unplugging the Aukey hub. Upon re-plug it would be still "dead".
I tried to collect runtime power-saving status values to show whether any of the ports is in sleeping state. None was.
# cat ~/bin/collect_runtime_status.sh
#!/bin/sh
grep . /sys/bus/pci/devices/*/power/runtime_status > runtime_status_"$1".txt
grep . /sys/bus/pci/devices/*/power/control > control_"$1".txt
grep . /sys/bus/pci/devices/*/power/runtime_status
grep . /sys/bus/pci/devices/*/power/control
cat /proc/interrupts > interrupts_"$1".txt
cat /proc/iomem > iomem_"$1".txt
lspci -vvv > lspci_vvv_"$1".txt
dmesg > dmesg_"$1".txt
#
At this stage I captured a new dmesg snapshot (dmesg_.txt).
Also captured bus traffic, file Aukey_15port_hub.dead_port.mon.out shows I cannot capture anything on the USB bus using "cat /sys/kernel/debug/usb/usbmon/0u > file" command.
Yet another dmesg snapshot is in port-is-still-dead.txt file showing a blocked kernel task being reported meanwhile:
diff -u -w dmesg_.txt port-is-still-dead.txt
+[ 864.036599] INFO: task kworker/0:1:609 blocked for more than 120 seconds.
+[ 864.036603] Not tainted 4.3.0-default-pciehp #2
+[ 864.036604] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
+[ 864.036606] kworker/0:1 D ffff88040bae7200 0 609 2 0x00000000
+[ 864.036613] Workqueue: usb_hub_wq hub_event
+[ 864.036615] ffff88040c93ba48 0000000000000086 0000000000000296 ffffffff820b3e40
+[ 864.036617] ffff8800d61cd300 ffff88040ccc94c0 ffff88040c93ba30 0000000000000296
+[ 864.036619] ffff88040c93c000 ffff880407ea1f10 ffff880409707948 0000000000000200
+[ 864.036621] Call Trace:
+[ 864.036625] [<ffffffff819cb14e>] schedule+0x2e/0x70
+[ 864.036628] [<ffffffff816555d6>] usb_kill_urb+0x56/0x90
+[ 864.036631] [<ffffffff811118a0>] ? wait_woken+0x80/0x80
+[ 864.036633] [<ffffffff8165458f>] usb_hcd_flush_endpoint+0x9f/0x160
+[ 864.036635] [<ffffffff81657223>] usb_disable_endpoint+0x93/0xa0
+[ 864.036638] [<ffffffff81657270>] usb_disable_interface+0x40/0x60
+[ 864.036640] [<ffffffff81659ade>] usb_unbind_interface+0x1ce/0x270
+[ 864.036643] [<ffffffff81599931>] __device_release_driver+0x91/0x130
+[ 864.036645] [<ffffffff815999f0>] device_release_driver+0x20/0x30
+[ 864.036646] [<ffffffff815987a3>] bus_remove_device+0x113/0x190
+[ 864.036649] [<ffffffff81594ed4>] device_del+0x134/0x250
+[ 864.036651] [<ffffffff81657314>] usb_disable_device+0x84/0x270
+[ 864.036652] [<ffffffff8164d211>] usb_disconnect+0x91/0x2b0
+[ 864.036654] [<ffffffff8164f387>] hub_event+0x677/0x1560
+[ 864.036657] [<ffffffff810edb7b>] process_one_work+0x1bb/0x4a0
+[ 864.036659] [<ffffffff810edb0f>] ? process_one_work+0x14f/0x4a0
+[ 864.036660] [<ffffffff810ee186>] worker_thread+0x46/0x440
+[ 864.036662] [<ffffffff810ee140>] ? rescuer_thread+0x2e0/0x2e0
+[ 864.036663] [<ffffffff810ee140>] ? rescuer_thread+0x2e0/0x2e0
+[ 864.036666] [<ffffffff810f360f>] kthread+0xdf/0x100
+[ 864.036668] [<ffffffff810f3530>] ? kthread_create_on_node+0x200/0x200
+[ 864.036670] [<ffffffff819d09ff>] ret_from_fork+0x3f/0x70
+[ 864.036672] [<ffffffff810f3530>] ? kthread_create_on_node+0x200/0x200
+[ 864.036674] 5 locks held by kworker/0:1/609:
+[ 864.036675] #0: ("usb_hub_wq"){.+.+.+}, at: [<ffffffff810edb0f>] process_one_work+0x14f/0x4a0
+[ 864.036679] #1: ((&hub->events)){+.+.+.}, at: [<ffffffff810edb0f>] process_one_work+0x14f/0x4a0
+[ 864.036682] #2: (&dev->mutex){......}, at: [<ffffffff8164ed74>] hub_event+0x64/0x1560
+[ 864.036685] #3: (&dev->mutex){......}, at: [<ffffffff8164d1d0>] usb_disconnect+0x50/0x2b0
+[ 864.036688] #4: (&dev->mutex){......}, at: [<ffffffff815999e8>] device_release_driver+0x18/0x30
An attempt to reboot resulted in a few more hung kernel tasks, no SysRq+O working, only SysRq+S and other SysRq commands which I do not know how to really use. So, I pressed the PWR button for 5 secs in the end. Sadly they are not in '/var/log/messages'.
I include also corresponding /var/log/messages contents which contain often
Nov 26 02:24:18 vostro kernel: xhci_hcd 0000:0b:00.0: get port status, actual port 0 status = 0x2a0
Nov 26 02:24:18 vostro kernel: xhci_hcd 0000:0b:00.0: Get port status returned 0x100
Nov 26 02:24:18 vostro kernel: xhci_hcd 0000:0b:00.0: get port status, actual port 1 status = 0xfe3
Nov 26 02:24:18 vostro kernel: xhci_hcd 0000:0b:00.0: Get port status returned 0x507
Nov 26 02:24:18 vostro kernel: usb usb1-port2: status 0507 change 0000
Nov 26 02:24:18 vostro kernel: hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000
Nov 26 02:24:18 vostro kernel: hub 1-0:1.0: hub_suspend
Nov 26 02:24:18 vostro kernel: usb usb1: bus auto-suspend, wakeup 1
Nov 26 02:24:18 vostro kernel: xhci_hcd 0000:0b:00.0: suspend failed because a port is resuming
Nov 26 02:24:18 vostro kernel: usb usb1: bus suspend fail, err -16
The contents are 3 boot-up sessions, you can thus find easily when I started up or rebooted the system:
# grep syslog-ng messages
Nov 26 01:34:34 vostro syslog-ng[3493]: syslog-ng shutting down; version='3.6.2'
Nov 26 01:38:10 vostro syslog-ng[3493]: syslog-ng starting up; version='3.6.2'
Nov 26 01:57:31 vostro syslog-ng[3493]: syslog-ng shutting down; version='3.6.2'
Nov 26 01:58:13 vostro syslog-ng[3493]: syslog-ng starting up; version='3.6.2'
Nov 26 02:21:23 vostro syslog-ng[3493]: syslog-ng shutting down; version='3.6.2'
Nov 26 02:22:06 vostro syslog-ng[3491]: syslog-ng starting up; version='3.6.2'
Nov 26 02:24:51 vostro syslog-ng[3491]: syslog-ng shutting down; version='3.6.2'
#
grep -i Prolific *
#
I am sorry there is that much data but I hope you can concentrate using timestamps easily on those parts which seem interesting enough.
Martin
Mathias Nyman wrote:
On 25.11.2015 00:09, Martin MOKREJŠ wrote:
Hi,
I have relatively new 13port USB 3.0 HUB based on VIAlabs 812 chipset with two power-only charging ports: 1x1.5A and 1x2.4A (AUKEY CB-H16, from Amazon). Sometimes, the hub (actually four 4-port hubs stitched together) chokes and all it's LEDs start blinking. I found it is caused by one device, which is a USB3 to SATA dongle:
PremiumCord KU3IDE3 Prolific PL2773 + JMD330 0x067b:0x2773 (1.00)
Now, I caught usbmon trace to show it is not recognized. Interestingly, the linux usb driver is unable to recognize any other device on that port. Even unplugging the fooled Aukey hub does not help, I have to reboot. Seems linux kernel is too much trying to enumerate some device on that port. But that seems a secondary issue to me. I can hook to the hub 12 other USB3 to SATA dongles (all based on ASMedia chip) and they all work fine.
If I connect the PremiumCord KU3IDE3 dongle via similar, VIA810 4-port hub with FW9.60 to the same laptop port it works fine. The laptop has TexasInstruments USB3 chip.
When I boot into Win7 the Aukey hub and PremiumCord KU3IDE3 play nicely together.
Thank you for you help,
Martin
An excerpt from the looping part of usbmon log show port link state seems to be Inactive.
This should be done on serious error condition to operate the link.
fff880408d47798 383464649 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
ffff880408d47798 383464681 C Ci:2:001:0 0 4 = c3027000
If I read the bits correctly the get port status request replies with status
connected, enabled, powered and link state is Inactive.
change bits were set for reset, bh reset and link state.
ffff880408d47798 383464717 S Co:2:001:0 s 23 01 0014 0001 0000 0
ffff880408d47798 383464731 C Co:2:001:0 0 0
ffff880408d47798 383464744 S Co:2:001:0 s 23 01 001d 0001 0000 0
ffff880408d47798 383464754 C Co:2:001:0 0 0
ffff880408d47798 383464766 S Co:2:001:0 s 23 01 0019 0001 0000 0
ffff880408d47798 383464776 C Co:2:001:0 0 0
ffff880408d47798 383464788 S Co:2:001:0 s 23 01 0010 0001 0000 0
ffff880408d47798 383464798 C Co:2:001:0 0 0
The previuis lines show hub cleared the changed port features
(reset change, bh reset change, link state change and port connect)
ffff880408d47798 383464810 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
ffff880408d47798 383464819 C Ci:2:001:0 0 4 = c3020000
the next get poer status still shows link is in inactive state
ffff880408d47798 383464831 S Co:2:001:0 s 23 03 001c 0001 0000 0
ffff880408d47798 383464843 C Co:2:001:0 0 0
Try to warm reset, Hub: Set port feature 1c = BH_PORT_RESET
Maybe enabling usb core and xhci debugging could show better what is going on
echo -n 'module xhci_hcd =p' > /sys/kernel/debug/dynamic_debug/control
echo 'module usbcore =p' >/sys/kernel/debug/dynamic_debug/control
-Mathias
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
