Re: port-i386/53894: "ehci_sync_hc: timed out" with ACPI/SMP enabled on eBox 3352DX3-AP

To: gnats-bugs%netbsd.org@localhost
Subject: Re: port-i386/53894: "ehci_sync_hc: timed out" with ACPI/SMP enabled on eBox 3352DX3-AP
From: Andrius V <vezhlys%gmail.com@localhost>
Date: Sun, 20 Jan 2019 22:56:58 +0200

Hi,

Thank you for the prompt reply. I can provide this output but it is a
bit tricky since USB ports are the only available besides Ethernet and
VGA (and integrated vte ethernet controller doesn't work properly as
well unfortunately, so ssh is out of option). Does it matter when to
do this output? I guess non ACPI/SMP boot won't provide the required
data as well? Currently I did a cron job which outputs the vmstat -u
usbhist result to file on boot. Please see an attached report for
results. Theoretically, I can modify cronjob to post report a bit
later if needed.

Regards,
Andrius V

On Sun, Jan 20, 2019 at 3:10 AM David H. Gutteridge <david%gutteridge.ca@localhost> wrote:
>
> The following reply was made to PR port-i386/53894; it has been noted by GNATS.
>
> From: "David H. Gutteridge" <david%gutteridge.ca@localhost>
> To: gnats-bugs%netbsd.org@localhost
> Cc:
> Subject: Re: port-i386/53894: "ehci_sync_hc: timed out" with ACPI/SMP
>  enabled on eBox 3352DX3-AP
> Date: Sat, 19 Jan 2019 20:09:06 -0500
>
>  It would probably be helpful to provide USB_DEBUG output. To do so,
>  please see http://www.netbsd.org/docs/kernel/#usb-debugging,
>  specifically the part following "USB debugging code has been changed in
>  NetBSD 7.99 and later."
>
>  Dave
>
>

50000 entries, next is 155
000000.000000 ohci_init#1@0: called!
000000.000000 ohci_alloc_sed#1@0: called!
000000.000000 ohci_alloc_sed#1@0: allocating chunk
000000.000000 ohci_alloc_sed#2@0: called!
000000.000000 ohci_alloc_sed#3@0: called!
000000.000000 ohci_alloc_sed#4@0: called!
000000.000000 ohci_alloc_sed#5@0: called!
000000.000000 ohci_alloc_sed#6@0: called!
000000.000000 ohci_alloc_sed#7@0: called!
000000.000000 ohci_alloc_sed#8@0: called!
000000.000000 ohci_alloc_sed#9@0: called!
000000.000000 ohci_alloc_sed#10@0: called!
000000.000000 ohci_alloc_sed#11@0: called!
000000.000000 ohci_alloc_sed#12@0: called!
000000.000000 ohci_alloc_sed#13@0: called!
000000.000000 ohci_alloc_sed#14@0: called!
000000.000000 ohci_alloc_sed#15@0: called!
000000.000000 ohci_alloc_sed#16@0: called!
000000.000000 ohci_alloc_sed#17@0: called!
000000.000000 ohci_alloc_sed#18@0: called!
000000.000000 ohci_alloc_sed#19@0: called!
000000.000000 ohci_alloc_sed#20@0: called!
000000.000000 ohci_alloc_sed#21@0: called!
000000.000000 ohci_alloc_sed#22@0: called!
000000.000000 ohci_alloc_sed#23@0: called!
000000.000000 ohci_alloc_sed#24@0: called!
000000.000000 ohci_alloc_sed#25@0: called!
000000.000000 ohci_alloc_sed#26@0: called!
000000.000000 ohci_alloc_sed#27@0: called!
000000.000000 ohci_alloc_sed#28@0: called!
000000.000000 ohci_alloc_sed#29@0: called!
000000.000000 ohci_alloc_sed#30@0: called!
000000.000000 ohci_alloc_sed#31@0: called!
000000.000000 ohci_alloc_sed#32@0: called!
000000.000000 ohci_alloc_sed#33@0: called!
000000.000000 ohci_alloc_sed#34@0: called!
000000.000000 ohci_alloc_sed#35@0: called!
000000.000000 ohci_alloc_sed#36@0: called!
000000.000000 ohci_alloc_sed#37@0: called!
000000.000000 ohci_alloc_sed#38@0: called!
000000.000000 ohci_alloc_sed#39@0: called!
000000.000000 ohci_alloc_sed#40@0: called!
000000.000000 ohci_alloc_sed#41@0: called!
000000.000000 ohci_alloc_sed#42@0: called!
000000.000000 ohci_alloc_sed#43@0: called!
000000.000000 ohci_alloc_sed#44@0: called!
000000.000000 ohci_alloc_sed#45@0: called!
000000.000000 ohci_alloc_sed#46@0: called!
000000.000000 ohci_alloc_sed#47@0: called!
000000.000000 ohci_alloc_sed#48@0: called!
000000.000000 ohci_alloc_sed#49@0: called!
000000.000000 ohci_alloc_sed#50@0: called!
000000.000000 ohci_alloc_sed#51@0: called!
000000.000000 ohci_alloc_sed#52@0: called!
000000.000000 ohci_alloc_sed#53@0: called!
000000.000000 ohci_alloc_sed#54@0: called!
000000.000000 ohci_alloc_sed#55@0: called!
000000.000000 ohci_alloc_sed#56@0: called!
000000.000000 ohci_alloc_sed#57@0: called!
000000.000000 ohci_alloc_sed#58@0: called!
000000.000000 ohci_alloc_sed#59@0: called!
000000.000000 ohci_alloc_sed#60@0: called!
000000.000000 ohci_alloc_sed#61@0: called!
000000.000000 ohci_alloc_sed#62@0: called!
000000.000000 ohci_alloc_sed#63@0: called!
000000.000000 ohci_alloc_sed#64@0: called!
000000.000000 ohci_alloc_sed#65@0: called!
000000.000000 ohci_alloc_sed#66@0: called!
000000.000000 ohci_init#1@0: cold started
000000.000000 ohci_init#1@0: sc 0xc3f73008: resetting
000000.000000 ohci_dumpregs#1@0: called!
000000.000000 ohci_dumpregs#1@0: rev=0x00000110 control=0x000000bf command=0x00000000
000000.000000 ohci_dumpregs#1@0:                intrstat=0x00000004 intre=0x00000000 intrd=0x00000000
000000.000000 ohci_dumpregs#1@0:                hcca=0x42005000 percur=0x00000000 ctrlhd=0x420077d0
000000.000000 ohci_dumpregs#1@0:                ctrlcur=0x00000000 bulkhd=0x420077a0 bulkcur=0x00000000
000000.000000 ohci_dumpregs#1@0:                done=0x00000000 fmival=0xa7782edf fmrem=0x80002e14
000000.000000 ohci_dumpregs#1@0:                fmnum=0x0000000c perst=0x00002a2f lsthrs=0x00000628
000000.000000 ohci_dumpregs#1@0:                desca=0x0f000904 descb=0x001e0000 stat=0x00000000
000000.000000 ohci_dumpregs#1@0:                port1=0x00000000 port2=0x00000000
000000.000000 ohci_dumpregs#1@0:          HCCA: frame_number=0x000c done_head=0x00000000
000000.000000 ohci_init#1@0: enabling 0x8000005b
000001.977987 ohci_open#1@0: called!
000001.977993 ohci_open#1@0: pipe=0xc3aab938, addr=0, endpt=0 (0)
000001.978045 ohci_roothub_ctrl#1@0: called!
000001.978050 ohci_roothub_ctrl#1@0: type=0x80 request=06
000001.978057 ohci_roothub_ctrl#1@0: wValue=0x0100
000001.978075 ohci_open#2@0: called!
000001.978080 ohci_open#2@0: pipe=0xc3aab938, addr=0, endpt=0 (0)
000001.978089 ohci_roothub_ctrl#2@0: called!
000001.978094 ohci_roothub_ctrl#2@0: type=0x00 request=05
000001.992529 ohci_open#3@0: called!
000001.992533 ohci_open#3@0: pipe=0xc3aab938, addr=1, endpt=0 (1)
000001.992545 ohci_roothub_ctrl#3@0: called!
000001.992551 ohci_roothub_ctrl#3@0: type=0x80 request=06
000001.992556 ohci_roothub_ctrl#3@0: wValue=0x0100
000001.992572 ohci_roothub_ctrl#4@0: called!
000001.992576 ohci_roothub_ctrl#4@0: type=0x80 request=06
000001.992581 ohci_roothub_ctrl#4@0: wValue=0x0300
000001.992589 ohci_roothub_ctrl#5@0: called!
000001.992593 ohci_roothub_ctrl#5@0: type=0x80 request=06
000001.992600 ohci_roothub_ctrl#5@0: wValue=0x0300
000001.992609 ohci_roothub_ctrl#6@0: called!
000001.992614 ohci_roothub_ctrl#6@0: type=0x80 request=06
000001.992619 ohci_roothub_ctrl#6@0: wValue=0x0301
000001.992627 ohci_roothub_ctrl#7@0: called!
000001.992631 ohci_roothub_ctrl#7@0: type=0x80 request=06
000001.992636 ohci_roothub_ctrl#7@0: wValue=0x0301
000001.992648 ohci_roothub_ctrl#8@0: called!
000001.992653 ohci_roothub_ctrl#8@0: type=0x80 request=06
000001.992658 ohci_roothub_ctrl#8@0: wValue=0x0302
000001.992666 ohci_roothub_ctrl#9@0: called!
000001.992671 ohci_roothub_ctrl#9@0: type=0x80 request=06
000001.992676 ohci_roothub_ctrl#9@0: wValue=0x0302
000001.993237 ohci_roothub_ctrl#10@0: called!
000001.993242 ohci_roothub_ctrl#10@0: type=0x80 request=06
000001.993249 ohci_roothub_ctrl#10@0: wValue=0x0200
000001.993261 ohci_roothub_ctrl#11@0: called!
000001.993266 ohci_roothub_ctrl#11@0: type=0x80 request=06
000001.993270 ohci_roothub_ctrl#11@0: wValue=0x0200
000001.993280 ohci_roothub_ctrl#12@0: called!
000001.993284 ohci_roothub_ctrl#12@0: type=0x00 request=09
000001.993297 ohci_roothub_ctrl#13@0: called!
000001.993302 ohci_roothub_ctrl#13@0: type=0xa0 request=06
000001.993338 ohci_open#4@0: called!
000001.993343 ohci_open#4@0: pipe=0xc3aab858, addr=1, endpt=129 (1)
000002.202657 ohci_roothub_ctrl#14@0: called!
000002.202662 ohci_roothub_ctrl#14@0: type=0x23 request=03
000002.202668 ohci_roothub_ctrl#14@0: set port power 1
000002.202680 ohci_roothub_ctrl#15@0: called!
000002.202685 ohci_roothub_ctrl#15@0: type=0x23 request=03
000002.202689 ohci_roothub_ctrl#15@0: set port power 2
000002.202697 ohci_roothub_ctrl#16@0: called!
000002.202702 ohci_roothub_ctrl#16@0: type=0x23 request=03
000002.202708 ohci_roothub_ctrl#16@0: set port power 3
000002.202715 ohci_roothub_ctrl#17@0: called!
000002.202720 ohci_roothub_ctrl#17@0: type=0x23 request=03
000002.202726 ohci_roothub_ctrl#17@0: set port power 4
000002.712837 ohci_roothub_ctrl#18@0: called!
000002.712841 ohci_roothub_ctrl#18@0: type=0xa0 request=00
000002.712851 ohci_roothub_ctrl#19@0: called!
000002.712856 ohci_roothub_ctrl#19@0: type=0xa3 request=00
000002.712861 ohci_roothub_ctrl#19@0: get port status i=1
000002.712868 ohci_roothub_ctrl#19@0: port status=0x0100
000002.712876 ohci_roothub_ctrl#20@0: called!
000002.712882 ohci_roothub_ctrl#20@0: type=0xa3 request=00
000002.712886 ohci_roothub_ctrl#20@0: get port status i=2
000002.712891 ohci_roothub_ctrl#20@0: port status=0x0100
000002.712900 ohci_roothub_ctrl#21@0: called!
000002.712904 ohci_roothub_ctrl#21@0: type=0xa3 request=00
000002.712910 ohci_roothub_ctrl#21@0: get port status i=3
000002.712916 ohci_roothub_ctrl#21@0: port status=0x0100
000002.712924 ohci_roothub_ctrl#22@0: called!
000002.712929 ohci_roothub_ctrl#22@0: type=0xa3 request=00
000002.712934 ohci_roothub_ctrl#22@0: get port status i=4
000002.712939 ohci_roothub_ctrl#22@0: port status=0x0100

Follow-Ups:
- Re: port-i386/53894: "ehci_sync_hc: timed out" with ACPI/SMP enabled on eBox 3352DX3-AP
  - From: Andrius V

References:
- Re: port-i386/53894: "ehci_sync_hc: timed out" with ACPI/SMP enabled on eBox 3352DX3-AP
  - From: David H. Gutteridge

Prev by Date: Re: port-sun3/48432 (System hangs under light load)
Next by Date: Re: port-i386/53894: "ehci_sync_hc: timed out" with ACPI/SMP enabled on eBox 3352DX3-AP
Previous by Thread: Re: port-i386/53894: "ehci_sync_hc: timed out" with ACPI/SMP enabled on eBox 3352DX3-AP
Next by Thread: Re: port-i386/53894: "ehci_sync_hc: timed out" with ACPI/SMP enabled on eBox 3352DX3-AP
Indexes:

Home | Main Index | Thread Index | Old Index