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

From: Lu, Baolu
Date: Tue Nov 10 2015 - 21:42:21 EST




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.

Problem seems to exist at the place where host and target sync with
each other.


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.

This is the first phase of code. I could do this in the next phase.
The problems exist in the interferer between DbC and the host
controller. They share the same power well so host reset, or
suspend/resume will cause DbC not work.

(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.

I will send you a new version for test later. By the way, which hardware
are you using for test?


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

Thanks,
Baolu


--
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/