Re: [PATCH v3 00/12] usb: early: add support for early printk through USB3 debug port

From: Lu, Baolu
Date: Wed Nov 11 2015 - 21:46:17 EST


Hi Dave,

Which device are you testing with? This implementation was developed
and tested on Intel Skylake devices.

It doesn't surprise me if it doesn't work with other silicons. But it do
remind me to create a verified-list and put those known-to-work devices
in it.

Thanks,
Baolu

On 11/11/2015 10:25 AM, Dave Young wrote:
Hi,

On 11/11/15 at 09:32am, Lu, Baolu wrote:

On 11/10/2015 05:39 PM, Dave Young wrote:
Hi,

On 11/09/15 at 03:38pm, Lu Baolu wrote:
This patch series adds support for early printk through USB3 debug port.
USB3 debug port is described in xHCI specification as an optional extended
capability.

I did a test with your previous patchset with the manually wired cable.
debug host detected the remote device, but later the devie automaticlly
disconnected and earlyprintk hangs.
Hi Dave,

What I have done is:
Retested it, seems it is not stable. I got a sucessful boot with earlyprintk
But only once and there was no "Press Y to continue", I just blindly pressed Y.

The other tests failed.

Since it is not convinience to test, do you have way to enable the dbc
after kernel boot? like echo 1 to a sysfs file to enable it.
(1) Build a new kernel for debug target with this patch series applied.
(2) Add "earlyprintk=xdbc" to the kernel option of debug target. The
"keep" option for early printk doesn't support yet. (That's my next
target.)

(3) Boot the debug host, and disable USB runtime suspend:

# echo on > /sys/bus/pci/devices/<xhci_pci_bus_name>/power/control
# echo on | tee /sys/bus/usb/devices/*/power/control

(4) Boot the debug target. Check the dmesg message on debug host.

# tail -f /var/log/kern.log

Nov 12 01:27:50 allen-ult kernel: [ 1815.983374] usb 4-3: new SuperSpeed USB
device number 4 using xhci_hcd
Nov 12 01:27:50 allen-ult kernel: [ 1815.999595] usb 4-3: LPM exit latency
is zeroed, disabling LPM.
Nov 12 01:27:50 allen-ult kernel: [ 1815.999899] usb 4-3: New USB device
found, idVendor=1d6b, idProduct=0004
Nov 12 01:27:50 allen-ult kernel: [ 1815.999902] usb 4-3: New USB device
strings: Mfr=1, Product=2, SerialNumber=3
Nov 12 01:27:50 allen-ult kernel: [ 1815.999903] usb 4-3: Product: Remote
GDB
Nov 12 01:27:50 allen-ult kernel: [ 1815.999904] usb 4-3: Manufacturer:
Linux
Nov 12 01:27:50 allen-ult kernel: [ 1815.999905] usb 4-3: SerialNumber: 0001
Nov 12 01:27:50 allen-ult kernel: [ 1816.000240] usb_debug 4-3:1.0: xhci_dbc
converter detected
Nov 12 01:27:50 allen-ult kernel: [ 1816.000360] usb 4-3: xhci_dbc converter
now attached to ttyUSB0

(5) Host has completed enumeration of debug device. Start "minicom" on debug
host.

Most times I have no chance to run minicom before the usb disconnection here.

Welcome to minicom 2.7

OPTIONS: I18n
Compiled on Jan 1 2014, 17:13:19.
Port /dev/ttyUSB0, 01:28:02

Press CTRL-A Z for help on special keys

Press Y to continue...

(6) You should be able to see "Press Y to continue..." (if not, try pressing
Enter key)
Press Y key, debug target should go ahead with boot and early boot messages
should show in mincom.

Press Y to continue...
[ 0.000000] Initializing cgroup subsys cpuset
[ 0.000000] Initializing cgroup subsys cpu
[ 0.000000] Initializing cgroup subsys cpuacct
[ 0.000000] Linux version 4.3.0-rc7+ (allen@blu-skl) (gcc version 4.8.4
(Ubuntu 4.8.4-2ubuntu1~14.04) 5
[ 0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-4.3.0-rc7+
root=UUID=5a2fb856-0238-4b6e-aa45-beeccb7
[ 0.000000] KERNEL supported cpus:

[...skipped...]

[ 0.000000] Offload RCU callbacks from CPUs: 0-7.
[ 0.000000] Console: colour dummy device 80x25
[ 0.000000] console [tty0] enabled
[ 0.000000] bootconsole [earlyxdbc0] disabled


So "the devie automaticlly disconnected and earlyprintk hangs" happens in
which step?

Here is some log on host side.

[ 1568.052135] usb 2-2: new SuperSpeed USB device number 5 using xhci_hcd
[ 1568.063416] usb 2-2: LPM exit latency is zeroed, disabling LPM.
[ 1568.063750] usb 2-2: New USB device found, idVendor=1d6b, idProduct=0004
[ 1568.063751] usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1568.063752] usb 2-2: Product: Remote GDB
[ 1568.063753] usb 2-2: Manufacturer: Linux
[ 1568.063754] usb 2-2: SerialNumber: 0001
[ 1568.065580] usb_debug 2-2:1.0: xhci_dbc converter detected
[ 1568.066309] usb 2-2: xhci_dbc converter now attached to ttyUSB0
[ 1580.464706] usb 2-2: USB disconnect, device number 5
[ 1580.464996] xhci_dbc ttyUSB0: xhci_dbc converter now disconnected from ttyUSB0
[ 1580.465062] usb_debug 2-2:1.0: device disconnected
[ 1580.670743] usb 2-2: new SuperSpeed USB device number 6 using xhci_hcd
[ 1580.682068] usb 2-2: LPM exit latency is zeroed, disabling LPM.
[ 1580.682667] usb 2-2: New USB device found, idVendor=1d6b, idProduct=0004
[ 1580.682672] usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1580.682675] usb 2-2: Product: Remote GDB
[ 1580.682678] usb 2-2: Manufacturer: Linux
[ 1580.682681] usb 2-2: SerialNumber: 0001
[ 1580.685190] usb_debug 2-2:1.0: xhci_dbc converter detected
[ 1580.687106] usb 2-2: xhci_dbc converter now attached to ttyUSB0
[ 1586.751477] usb 2-2: USB disconnect, device number 6
[ 1586.754248] xhci_dbc ttyUSB0: xhci_dbc converter now disconnected from ttyUSB0
[ 1586.754287] usb_debug 2-2:1.0: device disconnected
[ 1586.960399] usb 2-2: new SuperSpeed USB device number 7 using xhci_hcd
[ 1586.971562] usb 2-2: LPM exit latency is zeroed, disabling LPM.
[ 1586.971916] usb 2-2: New USB device found, idVendor=1d6b, idProduct=0004
[ 1586.971918] usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1586.971919] usb 2-2: Product: Remote GDB
[ 1586.971921] usb 2-2: Manufacturer: Linux
[ 1586.971922] usb 2-2: SerialNumber: 0001
[ 1586.973140] usb_debug 2-2:1.0: xhci_dbc converter detected
[ 1586.973939] usb 2-2: xhci_dbc converter now attached to ttyUSB0
[ 1616.615418] usb 2-2: USB disconnect, device number 7
[ 1616.617865] xhci_dbc ttyUSB0: xhci_dbc converter now disconnected from ttyUSB0
[ 1616.617918] usb_debug 2-2:1.0: device disconnected
[ 1616.823351] usb 2-2: new SuperSpeed USB device number 8 using xhci_hcd
[ 1616.834520] usb 2-2: LPM exit latency is zeroed, disabling LPM.
[ 1616.834856] usb 2-2: New USB device found, idVendor=1d6b, idProduct=0004
[ 1616.834858] usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1616.834859] usb 2-2: Product: Remote GDB
[ 1616.834860] usb 2-2: Manufacturer: Linux
[ 1616.834860] usb 2-2: SerialNumber: 0001
[ 1616.836715] usb_debug 2-2:1.0: xhci_dbc converter detected
[ 1616.837327] usb 2-2: xhci_dbc converter now attached to ttyUSB0
[ 1622.719311] usb 2-2: USB disconnect, device number 8
[ 1622.721962] xhci_dbc ttyUSB0: xhci_dbc converter now disconnected from ttyUSB0
[ 1622.721995] usb_debug 2-2:1.0: device disconnected
[ 1622.928226] usb 2-2: new SuperSpeed USB device number 9 using xhci_hcd
[ 1622.939383] usb 2-2: LPM exit latency is zeroed, disabling LPM.
[ 1622.939714] usb 2-2: New USB device found, idVendor=1d6b, idProduct=0004
[ 1622.939715] usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1622.939716] usb 2-2: Product: Remote GDB
[ 1622.939717] usb 2-2: Manufacturer: Linux
[ 1622.939718] usb 2-2: SerialNumber: 0001
[ 1622.941593] usb_debug 2-2:1.0: xhci_dbc converter detected
[ 1622.942187] usb 2-2: xhci_dbc converter now attached to ttyUSB0
[ 1631.312112] usb 2-2: USB disconnect, device number 9
[ 1631.315427] xhci_dbc ttyUSB0: xhci_dbc converter now disconnected from ttyUSB0
[ 1631.315465] usb_debug 2-2:1.0: device disconnected
[ 1631.521007] usb 2-2: new SuperSpeed USB device number 10 using xhci_hcd
[ 1631.532212] usb 2-2: LPM exit latency is zeroed, disabling LPM.
[ 1631.532544] usb 2-2: New USB device found, idVendor=1d6b, idProduct=0004
[ 1631.532545] usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1631.532546] usb 2-2: Product: Remote GDB
[ 1631.532547] usb 2-2: Manufacturer: Linux
[ 1631.532548] usb 2-2: SerialNumber: 0001
[ 1631.534413] usb_debug 2-2:1.0: xhci_dbc converter detected
[ 1631.535117] usb 2-2: xhci_dbc converter now attached to ttyUSB0
[ 1633.252488] usb 2-2: USB disconnect, device number 10
[ 1633.255279] xhci_dbc ttyUSB0: xhci_dbc converter now disconnected from ttyUSB0
[ 1633.255314] usb_debug 2-2:1.0: device disconnected
[ 1633.461411] usb 2-2: new SuperSpeed USB device number 11 using xhci_hcd
[ 1633.472598] usb 2-2: LPM exit latency is zeroed, disabling LPM.
[ 1633.472932] usb 2-2: New USB device found, idVendor=1d6b, idProduct=0004
[ 1633.472933] usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1633.472934] usb 2-2: Product: Remote GDB
[ 1633.472935] usb 2-2: Manufacturer: Linux
[ 1633.472936] usb 2-2: SerialNumber: 0001
[ 1633.473987] usb_debug 2-2:1.0: xhci_dbc converter detected
[ 1633.474624] usb 2-2: xhci_dbc converter now attached to ttyUSB0
[ 1633.900927] usb 2-2: USB disconnect, device number 11
[ 1633.901176] xhci_dbc ttyUSB0: xhci_dbc converter now disconnected from ttyUSB0
[ 1633.901226] usb_debug 2-2:1.0: device disconnected
[ 1634.106831] usb 2-2: new SuperSpeed USB device number 12 using xhci_hcd
[ 1634.117987] usb 2-2: LPM exit latency is zeroed, disabling LPM.
[ 1634.118328] usb 2-2: New USB device found, idVendor=1d6b, idProduct=0004
[ 1634.118329] usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1634.118330] usb 2-2: Product: Remote GDB
[ 1634.118331] usb 2-2: Manufacturer: Linux
[ 1634.118332] usb 2-2: SerialNumber: 0001
[ 1634.120194] usb_debug 2-2:1.0: xhci_dbc converter detected
[ 1634.120949] usb 2-2: xhci_dbc converter now attached to ttyUSB0

Thanks
Dave
--
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


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/