On 22.05.2017 21:24, Xavier . wrote:
Hello and thanks dmesg.4.12-rc1.with_dyndbg_pendrive_connected_at_boot_1r.txt (1r and 2n are very different on xhci) [ 0.000000] Linux version 4.12.0-041200rc1-generic (kernel@gomeisa) (gcc version 6.3.0 20170510 (Ubuntu 6.3.0-17ubuntu1) ) #201705131731 SMP Sat May 13 21:48:41 UTC 2017
...
[ 4.281409] xhci_hcd 0000:02:00.0: xHCI Host Controller [ 4.281431] xhci_hcd 0000:02:00.0: new USB bus registered, assigned bus number 2 [ 4.281466] xhci_hcd 0000:02:00.0: xHCI capability registers at f8452000: [ 4.281473] xhci_hcd 0000:02:00.0: CAPLENGTH AND HCIVERSION 0x1000020: [ 4.281477] xhci_hcd 0000:02:00.0: CAPLENGTH: 0x20 [ 4.281482] xhci_hcd 0000:02:00.0: HCIVERSION: 0x100 [ 4.281489] xhci_hcd 0000:02:00.0: HCSPARAMS 1: 0x4000820 [ 4.281493] xhci_hcd 0000:02:00.0: Max device slots: 32 [ 4.281498] xhci_hcd 0000:02:00.0: Max interrupters: 8 [ 4.281502] xhci_hcd 0000:02:00.0: Max ports: 4 [ 4.281509] xhci_hcd 0000:02:00.0: HCSPARAMS 2: 0x24000011 [ 4.281513] xhci_hcd 0000:02:00.0: Isoc scheduling threshold: 1 [ 4.281518] xhci_hcd 0000:02:00.0: Maximum allowed segments in event ring: 1 [ 4.281524] xhci_hcd 0000:02:00.0: HCSPARAMS 3 0x0: [ 4.281529] xhci_hcd 0000:02:00.0: Worst case U1 device exit latency: 0 [ 4.281533] xhci_hcd 0000:02:00.0: Worst case U2 device exit latency: 0 [ 4.281540] xhci_hcd 0000:02:00.0: HCC PARAMS 0x14051cf: [ 4.281545] xhci_hcd 0000:02:00.0: HC generates 64 bit addresses [ 4.281549] xhci_hcd 0000:02:00.0: HC hasn't Contiguous Frame ID Capability [ 4.281554] xhci_hcd 0000:02:00.0: HC can't generate Stopped - Short Package event [ 4.281558] xhci_hcd 0000:02:00.0: FIXME: more HCCPARAMS debugging [ 4.281565] xhci_hcd 0000:02:00.0: RTSOFF 0x600: [ 4.281570] xhci_hcd 0000:02:00.0: xHCI operational registers at f8452020: [ 4.281576] xhci_hcd 0000:02:00.0: USBCMD 0x0: [ 4.281581] xhci_hcd 0000:02:00.0: HC is being stopped [ 4.281585] xhci_hcd 0000:02:00.0: HC has finished hard reset [ 4.281589] xhci_hcd 0000:02:00.0: Event Interrupts disabled [ 4.281594] xhci_hcd 0000:02:00.0: Host System Error Interrupts disabled [ 4.281598] xhci_hcd 0000:02:00.0: HC has finished light reset [ 4.281605] xhci_hcd 0000:02:00.0: USBSTS 0x1: [ 4.281609] xhci_hcd 0000:02:00.0: Event ring is empty [ 4.281613] xhci_hcd 0000:02:00.0: No Host System Error [ 4.281617] xhci_hcd 0000:02:00.0: HC is halted [ 4.281625] xhci_hcd 0000:02:00.0: f8452420 port status reg = 0x80 [ 4.281632] xhci_hcd 0000:02:00.0: f8452424 port power reg = 0x0 [ 4.281640] xhci_hcd 0000:02:00.0: f8452428 port link reg = 0x0 [ 4.281647] xhci_hcd 0000:02:00.0: f845242c port reserved reg = 0x0 [ 4.281654] xhci_hcd 0000:02:00.0: f8452430 port status reg = 0x80 [ 4.281661] xhci_hcd 0000:02:00.0: f8452434 port power reg = 0x0 [ 4.281668] xhci_hcd 0000:02:00.0: f8452438 port link reg = 0x0 [ 4.281676] xhci_hcd 0000:02:00.0: f845243c port reserved reg = 0x0 [ 4.281683] xhci_hcd 0000:02:00.0: f8452440 port status reg = 0x80 [ 4.281690] xhci_hcd 0000:02:00.0: f8452444 port power reg = 0x0 [ 4.281697] xhci_hcd 0000:02:00.0: f8452448 port link reg = 0x0 [ 4.281704] xhci_hcd 0000:02:00.0: f845244c port reserved reg = 0x0 [ 4.281711] xhci_hcd 0000:02:00.0: f8452450 port status reg = 0x80 [ 4.281718] xhci_hcd 0000:02:00.0: f8452454 port power reg = 0x0 [ 4.281725] xhci_hcd 0000:02:00.0: f8452458 port link reg = 0x0 [ 4.281732] xhci_hcd 0000:02:00.0: f845245c port reserved reg = 0x0 [ 4.281738] xhci_hcd 0000:02:00.0: QUIRK: Resetting on resume [ 4.281743] xhci_hcd 0000:02:00.0: // Halt the HC [ 4.281755] xhci_hcd 0000:02:00.0: Resetting HCD [ 4.281762] xhci_hcd 0000:02:00.0: // Reset the HC [ 4.286927] xhci_hcd 0000:02:00.0: Wait for controller to be ready for doorbell rings [ 4.286934] xhci_hcd 0000:02:00.0: Reset complete [ 4.286940] xhci_hcd 0000:02:00.0: Enabling 64-bit DMA addresses. [ 4.286944] xhci_hcd 0000:02:00.0: Calling HCD init [ 4.286949] xhci_hcd 0000:02:00.0: xhci_init [ 4.286953] xhci_hcd 0000:02:00.0: xHCI doesn't need link TRB QUIRK [ 4.286960] xhci_hcd 0000:02:00.0: Supported page size register = 0x1 [ 4.286965] xhci_hcd 0000:02:00.0: Supported page size of 4K [ 4.286969] xhci_hcd 0000:02:00.0: HCD page size set to 4K [ 4.286976] xhci_hcd 0000:02:00.0: // xHC can handle at most 32 device slots. [ 4.286982] xhci_hcd 0000:02:00.0: // Setting Max device slots reg = 0x20. [ 4.287128] ata2: port disabled--ignoring [ 4.287171] xhci_hcd 0000:02:00.0: // Device context base array address = 0x35617000 (DMA), f5617000 (virt) [ 4.287194] xhci_hcd 0000:02:00.0: Allocated command ring at f5615840 [ 4.287198] xhci_hcd 0000:02:00.0: First segment DMA is 0x35620000 [ 4.287207] xhci_hcd 0000:02:00.0: // Setting command ring address to 0x0000000035620001 [ 4.287216] xhci_hcd 0000:02:00.0: // xHC command ring deq ptr low bits + flags = @00000000 [ 4.287221] xhci_hcd 0000:02:00.0: // xHC command ring deq ptr high bits = @00000000 [ 4.287239] xhci_hcd 0000:02:00.0: // Doorbell array is located at offset 0x800 from cap regs base addr [ 4.287244] xhci_hcd 0000:02:00.0: // xHCI capability registers at f8452000: [ 4.287251] xhci_hcd 0000:02:00.0: // @f8452000 = 0x1000020 (CAPLENGTH AND HCIVERSION) [ 4.287255] xhci_hcd 0000:02:00.0: // CAPLENGTH: 0x20 [ 4.287260] xhci_hcd 0000:02:00.0: // HCIVERSION: 0x100 [ 4.287265] xhci_hcd 0000:02:00.0: // xHCI operational registers at f8452020: [ 4.287271] xhci_hcd 0000:02:00.0: // @f8452018 = 0x600 RTSOFF [ 4.287276] xhci_hcd 0000:02:00.0: // xHCI runtime registers at f8452600: [ 4.287282] xhci_hcd 0000:02:00.0: // @f8452014 = 0x800 DBOFF [ 4.287286] xhci_hcd 0000:02:00.0: // Doorbell array at f8452800: [ 4.287291] xhci_hcd 0000:02:00.0: xHCI runtime registers at f8452600: [ 4.287297] xhci_hcd 0000:02:00.0: f8452600: Microframe index = 0x0 [ 4.287313] xhci_hcd 0000:02:00.0: // Allocating event ring [ 4.287336] xhci_hcd 0000:02:00.0: TRB math tests passed. [ 4.287343] xhci_hcd 0000:02:00.0: // Allocated event ring segment table at 0x35623000 [ 4.287349] xhci_hcd 0000:02:00.0: Set ERST to 0; private num segs = 1, virt addr = f5623000, dma addr = 0x35623000 [ 4.287355] xhci_hcd 0000:02:00.0: // Write ERST size = 1 to ir_set 0 (some bits preserved) [ 4.287360] xhci_hcd 0000:02:00.0: // Set ERST entries to point to event ring. [ 4.287365] xhci_hcd 0000:02:00.0: // Set ERST base address for ir_set 0 = 0x35623000 [ 4.287377] xhci_hcd 0000:02:00.0: // Write event ring dequeue pointer, preserving EHB bit [ 4.287381] xhci_hcd 0000:02:00.0: Wrote ERST address to ir_set 0. [ 4.287389] xhci_hcd 0000:02:00.0: Allocating 4 scratchpad buffers [ 4.287452] xhci_hcd 0000:02:00.0: Ext Cap f8452510, port offset = 1, count = 2, revision = 0x3 [ 4.287466] xhci_hcd 0000:02:00.0: Ext Cap f8452524, port offset = 3, count = 2, revision = 0x2 [ 4.287470] xhci_hcd 0000:02:00.0: xHCI 1.0: support USB2 software lpm [ 4.287475] xhci_hcd 0000:02:00.0: Found 2 USB 2.0 ports and 2 USB 3.0 ports. [ 4.287481] xhci_hcd 0000:02:00.0: USB 2.0 port at index 2, addr = f8452440 [ 4.287486] xhci_hcd 0000:02:00.0: USB 2.0 port at index 3, addr = f8452450 [ 4.287491] xhci_hcd 0000:02:00.0: USB 3.0 port at index 0, addr = f8452420 [ 4.287496] xhci_hcd 0000:02:00.0: USB 3.0 port at index 1, addr = f8452430 [ 4.287502] xhci_hcd 0000:02:00.0: Finished xhci_init [ 4.287508] xhci_hcd 0000:02:00.0: Called HCD init [ 4.287514] xhci_hcd 0000:02:00.0: hcc params 0x014051cf hci version 0x100 quirks 0x00000090 [ 4.287528] xhci_hcd 0000:02:00.0: xhci_run [ 4.287743] xhci_hcd 0000:02:00.0: // xHC command ring deq ptr low bits + flags = @00000000 [ 4.287748] xhci_hcd 0000:02:00.0: // xHC command ring deq ptr high bits = @00000000 [ 4.287752] xhci_hcd 0000:02:00.0: ERST memory map follows: [ 4.287759] xhci_hcd 0000:02:00.0: @0000000035623000 35622000 00000000 00000100 00000000 [ 4.287767] xhci_hcd 0000:02:00.0: ERST deq = 64'h35622000 [ 4.287772] xhci_hcd 0000:02:00.0: // Set the interrupt modulation register [ 4.287780] xhci_hcd 0000:02:00.0: // Enable interrupts, cmd = 0x4. [ 4.287787] xhci_hcd 0000:02:00.0: // Enabling event ring interrupter f8452620 by writing 0x2 to irq_pending [ 4.287794] xhci_hcd 0000:02:00.0: f8452620: ir_set[0] [ 4.287799] xhci_hcd 0000:02:00.0: f8452620: ir_set.pending = 0x2 [ 4.287806] xhci_hcd 0000:02:00.0: f8452624: ir_set.control = 0xa0 [ 4.287812] xhci_hcd 0000:02:00.0: f8452628: ir_set.erst_size = 0x1 [ 4.287822] xhci_hcd 0000:02:00.0: f8452630: ir_set.erst_base = @35623000 [ 4.287831] xhci_hcd 0000:02:00.0: f8452638: ir_set.erst_dequeue = @35622000 [ 4.287835] xhci_hcd 0000:02:00.0: Finished xhci_run for USB2 roothub [ 4.287996] usb usb2: New USB device found, idVendor=1d6b, idProduct=0002 [ 4.288002] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [ 4.288007] usb usb2: Product: xHCI Host Controller [ 4.288011] usb usb2: Manufacturer: Linux 4.12.0-041200rc1-generic xhci-hcd [ 4.288015] usb usb2: SerialNumber: 0000:02:00.0 [ 4.288369] xHCI xhci_add_endpoint called for root hub [ 4.288374] xHCI xhci_check_bandwidth called for root hub [ 4.288383] xhci_hcd 0000:02:00.0: Endpoint 0x81 ep reset callback called [ 4.288493] hub 2-0:1.0: USB hub found [ 4.288526] hub 2-0:1.0: 2 ports detected [ 4.288703] xhci_hcd 0000:02:00.0: set port power, actual port 0 status = 0x2a0 [ 4.288731] xhci_hcd 0000:02:00.0: set port power, actual port 1 status = 0x2a0 [ 4.288899] xhci_hcd 0000:02:00.0: xHCI Host Controller [ 4.288915] xhci_hcd 0000:02:00.0: new USB bus registered, assigned bus number 3 [ 4.288931] xhci_hcd 0000:02:00.0: // Turn on HC, cmd = 0x5. [ 4.290521] xhci_hcd 0000:02:00.0: Finished xhci_run for USB3 roothub [ 4.290573] usb usb3: We don't know the algorithms for LPM for this host, disabling LPM. [ 4.290759] usb usb3: New USB device found, idVendor=1d6b, idProduct=0003 [ 4.290765] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [ 4.290769] usb usb3: Product: xHCI Host Controller [ 4.290774] usb usb3: Manufacturer: Linux 4.12.0-041200rc1-generic xhci-hcd [ 4.290778] usb usb3: SerialNumber: 0000:02:00.0 [ 4.291049] xHCI xhci_add_endpoint called for root hub [ 4.291053] xHCI xhci_check_bandwidth called for root hub [ 4.291060] xhci_hcd 0000:02:00.0: Endpoint 0x81 ep reset callback called [ 4.291176] hub 3-0:1.0: USB hub found [ 4.291204] hub 3-0:1.0: 2 ports detected [ 4.291401] xhci_hcd 0000:02:00.0: set port power, actual port 0 status = 0x2a0 [ 4.291430] xhci_hcd 0000:02:00.0: set port power, actual port 1 status = 0x2a0
...
[ 4.390793] xhci_hcd 0000:02:00.0: get port status, actual port 0 status = 0x2a0 [ 4.390800] xhci_hcd 0000:02:00.0: Get port status returned 0x100 [ 4.390838] xhci_hcd 0000:02:00.0: get port status, actual port 1 status = 0x202e1 [ 4.390843] xhci_hcd 0000:02:00.0: Get port status returned 0x10101 [ 4.390873] xhci_hcd 0000:02:00.0: clear port connect change, actual port 1 status = 0x2e1 [ 4.394856] xhci_hcd 0000:02:00.0: get port status, actual port 0 status = 0x2a0 [ 4.394865] xhci_hcd 0000:02:00.0: Get port status returned 0x2a0 [ 4.394932] xhci_hcd 0000:02:00.0: get port status, actual port 1 status = 0x2a0 [ 4.394937] xhci_hcd 0000:02:00.0: Get port status returned 0x2a0 [ 4.395004] xhci_hcd 0000:02:00.0: set port remote wake mask, actual port 0 status = 0xe0002a0 [ 4.395037] xhci_hcd 0000:02:00.0: set port remote wake mask, actual port 1 status = 0xe0002a0 [ 4.395090] xhci_hcd 0000:02:00.0: xhci_hub_status_data: stopping port polling.
[ 4.494950] xhci_hcd 0000:02:00.0: get port status, actual port 1 status = 0x2e1 [ 4.494959] xhci_hcd 0000:02:00.0: Get port status returned 0x101 [ 4.495012] xhci_hcd 0000:02:00.0: // Ding dong!
Queued the first enable slot command and wait for it to complete Everything looks good so far.
[ 9.698731] xhci_hcd 0000:02:00.0: Command timeout [ 9.698736] xhci_hcd 0000:02:00.0: Abort command ring [ 11.714714] xhci_hcd 0000:02:00.0: No stop event for abort, ring start fail? [ 11.714732] xhci_hcd 0000:02:00.0: Error while assigning device slot ID
5 seconds later driver times out on the command. To me this looks like we never get the command completiong interrupt Actually this looks like interupts are not working for xhci at all. Are there any interrupts for xhci? does /proc/interrupts show 0 interrupts for xhci for 4.12-rc1
[ 11.714923] xhci_hcd 0000:02:00.0: Max number of devices this xHCI host supports is 32. [ 11.715132] usb usb2-port2: couldn't allocate usb_device [ 11.715290] xhci_hcd 0000:02:00.0: disable port, actual port 1 status = 0x2e1 [ 11.715381] xhci_hcd 0000:02:00.0: xhci_hub_status_data: stopping port polling. ********************************************************************************************************************** dmesg.4.12-rc1.with_dyndbg_pendrive_connected_at_boot_2n [ 0.000000] Linux version 4.12.0-041200rc1-generic (kernel@gomeisa) (gcc version 6.3.0 20170510 (Ubuntu 6.3.0-17ubuntu1) ) #201705131731 SMP Sat May 13 21:48:41 UTC 2017
[ 4.097413] xhci_hcd 0000:02:00.0: xHCI Host Controller [ 4.097433] xhci_hcd 0000:02:00.0: new USB bus registered, assigned bus number 2 [ 4.178095] xhci_hcd 0000:02:00.0: xHCI capability registers at f8452000: [ 4.188170] xhci_hcd 0000:02:00.0: CAPLENGTH AND HCIVERSION 0xffffffff: [ 4.188175] xhci_hcd 0000:02:00.0: CAPLENGTH: 0xff [ 4.188180] xhci_hcd 0000:02:00.0: HCIVERSION: 0xffff [ 4.198256] xhci_hcd 0000:02:00.0: HCSPARAMS 1: 0xffffffff [ 4.198261] xhci_hcd 0000:02:00.0: Max device slots: 255 [ 4.198265] xhci_hcd 0000:02:00.0: Max interrupters: 2047 [ 4.198270] xhci_hcd 0000:02:00.0: Max ports: 127 [ 4.208346] xhci_hcd 0000:02:00.0: HCSPARAMS 2: 0xffffffff
Ok this second case we fail completely to read any xhci register, they all return 0xffffffff This is what it would look it xhci controller disappeared completely from PCI bus So first case looks like messed up PCI interrupts (MSI/MSI-X) and second one looks like reading registers fail completely for this PCI device. -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
