port-amd64/54392: "pause" at boot w/o timecounters ticking

[martin%NetBSD.org@localhost]

>Number:         54392
>Category:       port-amd64
>Synopsis:       "pause" at boot w/o timecounters ticking
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    port-amd64-maintainer
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Sun Jul 21 05:45:00 +0000 2019
>Originator:     Martin Husemann
>Release:        NetBSD 8.99.51
>Organization:
The NetBSD Foundation, Inc.
>Environment:
System: NetBSD seven-days-to-the-wolves.aprisoft.de 8.99.51 NetBSD 8.99.51 (GENERIC) #288: Wed Jul 17 15:58:58 CEST 2019 martin%seven-days-to-the-wolves.aprisoft.de@localhost:/work/src/sys/arch/amd64/compile/GENERIC amd64
Architecture: x86_64
Machine: amd64
>Description:

Since a month (or so) I see one of my machines boot very "slowly" sometimes.
This is not reproducable and happens not very often. When I first saw it
I thought it had paniced during boot, connected to the serial console
and hit enter (expecting a db prompt), but instead it continued booting.

I had not captured that session, so on later boots I connected the serial
earlier and captured output. 

The issue happens here:

[   1.1246297] ieee1394if0: bus manager 0
[   1.9138511] uhub0 at usb0: NetBSD (0000) xHCI root hub (0000), class 9/0, rev 3.00/1.00, addr 0
[   2.0162584] uhub1 at usb1: NetBSD (0000) xHCI root hub (0000), class 9/0, rev 2.00/1.00, addr 0

<---- very long delay here ---->

[   2.4451159] uhub2 at usb4: NetBSD (0000) OHCI root hub (0000), class 9/0, rev 1.00/1.00, addr 1

and the delay was not 0.4 seconds, but probably infinite, untill I caused
interrupts by hitting enter on the serial console.

Full boot message below.

[   1.0000000] Copyright (c) 1996, 1997, 1998, 1999, 2000, 2001, 2002, 2003, 2004, 2005,
[   1.0000000]     2006, 2007, 2008, 2009, 2010, 2011, 2012, 2013, 2014, 2015, 2016, 2017,
[   1.0000000]     2018, 2019 The NetBSD Foundation, Inc.  All rights reserved.
[   1.0000000] Copyright (c) 1982, 1986, 1989, 1991, 1993
[   1.0000000]     The Regents of the University of California.  All rights reserved.
[   1.0000000] NetBSD 8.99.51 (GENERIC) #288: Wed Jul 17 15:58:58 CEST 2019
[   1.0000000] 	martin%seven-days-to-the-wolves.aprisoft.de@localhost:/work/src/sys/arch/amd64/compile/GENERIC
[   1.0000000] total memory = 16382 MB
[   1.0000000] avail memory = 15882 MB
[   1.0000000] running cgd selftest aes-xts-256 aes-xts-512 done
[   1.0000030] mainbus0 (root)
[   1.0000030] ACPI: RSDP 0x00000000000FBAD0 000024 (v02 ACPIAM)
[   1.0000030] ACPI: XSDT 0x00000000CFE90100 00005C (v01 030811 XSDT1042 20110308 MSFT 00000097)
[   1.0000030] ACPI: FACP 0x00000000CFE90290 0000F4 (v03 030811 FACP1042 20110308 MSFT 00000097)
[   1.0000030] Firmware Warning (ACPI): 32/64X length mismatch in FADT/Gpe0Block: 64/32 (20190405/tbfadt-642)
[   1.0000030] ACPI: DSDT 0x00000000CFE90450 00E040 (v01 A1585  A1585000 00000000 INTL 20060113)
[   1.0000030] ACPI: FACS 0x00000000CFEA8000 000040
[   1.0000030] ACPI: APIC 0x00000000CFE90390 00007C (v01 030811 APIC1042 20110308 MSFT 00000097)
[   1.0000030] ACPI: MCFG 0x00000000CFE90410 00003C (v01 030811 OEMMCFG  20110308 MSFT 00000097)
[   1.0000030] ACPI: OEMB 0x00000000CFEA8040 000072 (v01 030811 OEMB1042 20110308 MSFT 00000097)
[   1.0000030] ACPI: SRAT 0x00000000CFE9F8A0 000108 (v01 AMD    FAM_F_10 00000002 AMD  00000001)
[   1.0000030] ACPI: HPET 0x00000000CFE9F9B0 000038 (v01 030811 OEMHPET  20110308 MSFT 00000097)
[   1.0000030] ACPI: SSDT 0x00000000CFE9F9F0 000DA4 (v01 A M I  POWERNOW 00000001 AMD  00000001)
[   1.0000030] ACPI: 2 ACPI AML tables successfully acquired and loaded
[   1.0000030] ioapic0 at mainbus0 apid 6
[   1.0000030] cpu0 at mainbus0 apid 0
[   1.0000030] cpu0: AMD Phenom(tm) II X6 1075T Processor, id 0x100fa0
[   1.0000030] cpu0: package 0, core 0, smt 0
[   1.0000030] cpu1 at mainbus0 apid 1
[   1.0000030] cpu1: AMD Phenom(tm) II X6 1075T Processor, id 0x100fa0
[   1.0000030] cpu1: package 0, core 1, smt 0
[   1.0000030] cpu2 at mainbus0 apid 2
[   1.0000030] cpu2: AMD Phenom(tm) II X6 1075T Processor, id 0x100fa0
[   1.0000030] cpu2: package 0, core 2, smt 0
[   1.0000030] cpu3 at mainbus0 apid 3
[   1.0000030] cpu3: AMD Phenom(tm) II X6 1075T Processor, id 0x100fa0
[   1.0000030] cpu3: package 0, core 3, smt 0
[   1.0000030] cpu4 at mainbus0 apid 4
[   1.0000030] cpu4: AMD Phenom(tm) II X6 1075T Processor, id 0x100fa0
[   1.0000030] cpu4: package 0, core 4, smt 0
[   1.0000030] cpu5 at mainbus0 apid 5
[   1.0000030] cpu5: AMD Phenom(tm) II X6 1075T Processor, id 0x100fa0
[   1.0000030] cpu5: package 0, core 5, smt 0
[   1.0000030] acpi0 at mainbus0: Intel ACPICA 20190405
[   1.0000030] acpi0: fixed power button present
[   1.0351544] hpet0 at acpi0: high precision event timer (mem 0xfed00000-0xfed00400)
[   1.1246297] acpiec0 at acpi0 (EC0, PNP0C09): io 0x62,0x66
[   1.1246297] attimer1 at acpi0 (TMR, PNP0100): io 0x40-0x43 irq 0
[   1.1246297] pcppi1 at acpi0 (SPKR, PNP0800): io 0x61
[   1.1246297] spkr0 at pcppi1: PC Speaker
[   1.1246297] wsbell at spkr0 not configured
[   1.1246297] midi0 at pcppi1: PC speaker
[   1.1246297] sysbeep0 at pcppi1
[   1.1246297] UAR1 (PNP0501) at acpi0 not configured
[   1.1246297] aibs0 at acpi0 (ASOC, ATK0110-16843024): ASUSTeK AI Booster
[   1.1246297] OMSC (PNP0C02) at acpi0 not configured
[   1.1246297] RMSC (PNP0C02) at acpi0 not configured
[   1.1246297] SIOR (PNP0C02) at acpi0 not configured
[   1.1246297] PCIE (PNP0C02) at acpi0 not configured
[   1.1246297] RMEM (PNP0C01) at acpi0 not configured
[   1.1246297] acpibut0 at acpi0 (PWRB, PNP0C0C-170): ACPI Power Button
[   1.1246297] acpiwmi0 at acpi0 (AOD, PNP0C14-0): ACPI WMI Interface
[   1.1246297] acpiwmibus at acpiwmi0 not configured
[   1.1246297] attimer1: attached to pcppi1
[   1.1246297] pci0 at mainbus0 bus 0: configuration mode 1
[   1.1246297] pchb0 at pci0 dev 0 function 0: vendor 1002 product 5957 (rev. 0x00)
[   1.1246297] ppb0 at pci0 dev 2 function 0: vendor 1002 product 5978 (rev. 0x00)
[   1.1246297] ppb0: PCI Express capability version 2 <Root Port of PCI-E Root Complex> x16 @ 5.0GT/s
[   1.1246297] ppb0: link is x16 @ 2.5GT/s
[   1.1246297] pci1 at ppb0 bus 6
[   1.1246297] nouveau0 at pci1 dev 0 function 0: vendor 10de product 0e22 (rev. 0xa1)
[   1.1246297] hdaudio0 at pci1 dev 0 function 1: HD Audio Controller
[   1.1246297] hdaudio0: interrupting at ioapic0 pin 19
[   1.1246297] hdafg0 at hdaudio0: vendor 10de product 0012
[   1.1246297] hdafg0: DP00 8ch: Digital Out [Jack]
[   1.1246297] hdafg0: 8ch/0ch 48000Hz PCM16*
[   1.1246297] hdafg1 at hdaudio0: vendor 10de product 0012
[   1.1246297] hdafg1: DP00 8ch: Digital Out [Jack]
[   1.1246297] hdafg1: 8ch/0ch 48000Hz PCM16*
[   1.1246297] hdafg2 at hdaudio0: vendor 10de product 0012
[   1.1246297] hdafg2: DP00 8ch: Digital Out [Jack]
[   1.1246297] hdafg2: 8ch/0ch 48000Hz PCM16*
[   1.1246297] hdafg3 at hdaudio0: vendor 10de product 0012
[   1.1246297] hdafg3: DP00 8ch: Digital Out [Jack]
[   1.1246297] hdafg3: 8ch/0ch 48000Hz PCM16*
[   1.1246297] ppb1 at pci0 dev 4 function 0: vendor 1002 product 597a (rev. 0x00)
[   1.1246297] ppb1: PCI Express capability version 2 <Root Port of PCI-E Root Complex> x4 @ 5.0GT/s
[   1.1246297] pci2 at ppb1 bus 5
[   1.1246297] nvme0 at pci2 dev 0 function 0: vendor 144d product a802 (rev. 0x01)
[   1.1246297] nvme0: NVMe 1.1
[   1.1246297] nvme0: interrupting at ioapic0 pin 16
[   1.1246297] nvme0: SAMSUNG MZVPV256HDGL-00000, firmware BXW7300Q, serial S1XWNYAH408386
[   1.1246297] ld0 at nvme0 nsid 1
[   1.1246297] ld0: 238 GB, 31130 cyl, 255 head, 63 sec, 512 bytes/sect x 500118192 sectors
[   1.1246297] ppb2 at pci0 dev 9 function 0: vendor 1002 product 597e (rev. 0x00)
[   1.1246297] ppb2: PCI Express capability version 2 <Root Port of PCI-E Root Complex> x2 @ 5.0GT/s
[   1.1246297] ppb2: link is x1 @ 2.5GT/s
[   1.1246297] pci3 at ppb2 bus 4
[   1.1246297] jmide0 at pci3 dev 0 function 0: vendor 197b product 2361 (rev. 0x10)
[   1.1246297] jmide0: 1 PATA port, 1 SATA port
[   1.1246297] jmide0: interrupting at ioapic0 pin 17
[   1.1246297] ahcisata0 at jmide0
[   1.1246297] ahcisata0: AHCI revision 1.10, 1 port, 32 slots, CAP 0xc722ff00<PSC,SSC,PMD,SPM,ISS=0x2=Gen2,SCLO,SAL,SALP,SNCQ,S64A>
[   1.1246297] atabus0 at ahcisata0 channel 0
[   1.1246297] jmide0: PCI IDE interface used
[   1.1246297] jmide0: primary channel is unused
[   1.1246297] jmide0: secondary channel is PATA
[   1.1246297] atabus1 at jmide0 channel 1
[   1.1246297] ppb3 at pci0 dev 10 function 0: vendor 1002 product 597f (rev. 0x00)
[   1.1246297] ppb3: PCI Express capability version 2 <Root Port of PCI-E Root Complex> x2 @ 5.0GT/s
[   1.1246297] ppb3: link is x1 @ 5.0GT/s
[   1.1246297] pci4 at ppb3 bus 3
[   1.1246297] xhci0 at pci4 dev 0 function 0: vendor 1033 product 0194 (rev. 0x03)
[   1.1246297] xhci0: interrupting at ioapic0 pin 18
[   1.1246297] usb0 at xhci0: USB revision 3.0
[   1.1246297] usb1 at xhci0: USB revision 2.0
[   1.1246297] ahcisata1 at pci0 dev 17 function 0: vendor 1002 product 4391 (rev. 0x40)
[   1.1246297] ahcisata1: AHCI revision 1.20, 6 ports, 32 slots, CAP 0xf730ff05<PSC,SSC,PMD,ISS=0x3=Gen3,SCLO,SAL,SALP,SMPS,SSNTF,SNCQ,S64A>
[   1.1246297] ahcisata1: interrupting at ioapic0 pin 19
[   1.1246297] atabus2 at ahcisata1 channel 0
[   1.1246297] atabus3 at ahcisata1 channel 1
[   1.1246297] atabus4 at ahcisata1 channel 2
[   1.1246297] atabus5 at ahcisata1 channel 3
[   1.1246297] atabus6 at ahcisata1 channel 4
[   1.1246297] atabus7 at ahcisata1 channel 5
[   1.1246297] ohci0 at pci0 dev 18 function 0: vendor 1002 product 4397 (rev. 0x00)
[   1.1246297] ohci0: interrupting at ioapic0 pin 18
[   1.1246297] ohci0: OHCI version 1.0, legacy support
[   1.1246297] usb2 at ohci0: USB revision 1.0
[   1.1246297] ehci0 at pci0 dev 18 function 2: vendor 1002 product 4396 (rev. 0x00)
[   1.1246297] ehci0: interrupting at ioapic0 pin 17
[   1.1246297] ehci0: dropped intr workaround enabled
[   1.1246297] ehci0: 1 companion controller, 5 ports: ohci0
[   1.1246297] usb3 at ehci0: USB revision 2.0
[   1.1246297] ohci1 at pci0 dev 19 function 0: vendor 1002 product 4397 (rev. 0x00)
[   1.1246297] ohci1: interrupting at ioapic0 pin 18
[   1.1246297] ohci1: OHCI version 1.0, legacy support
[   1.1246297] usb4 at ohci1: USB revision 1.0
[   1.1246297] ehci1 at pci0 dev 19 function 2: vendor 1002 product 4396 (rev. 0x00)
[   1.1246297] ehci1: interrupting at ioapic0 pin 17
[   1.1246297] ehci1: dropped intr workaround enabled
[   1.1246297] ehci1: 1 companion controller, 5 ports: ohci1
[   1.1246297] usb5 at ehci1: USB revision 2.0
[   1.1246297] piixpm0 at pci0 dev 20 function 0: vendor 1002 product 4385 (rev. 0x42)
[   1.1246297] piixpm0: polling
[   1.1246297] iic0 at piixpm0 port 0: I2C bus
[   1.1246297] iic1 at piixpm0 port 1: I2C bus
[   1.1246297] iic2 at piixpm0 port 2: I2C bus
[   1.1246297] iic3 at piixpm0 port 3: I2C bus
[   1.1246297] hdaudio1 at pci0 dev 20 function 2: HD Audio Controller
[   1.1246297] hdaudio1: interrupting at ioapic0 pin 16
[   1.1246297] hdafg4 at hdaudio1: vendor 1106 product 0440
[   1.1246297] hdafg4: DAC00 8ch: Speaker [Jack], HP Out [Jack]
[   1.1246297] hdafg4: ADC01 2ch: Line In [Jack], Mic In [Jack]
[   1.1246297] hdafg4: HDMI02 2ch: Digital Out [Jack]
[   1.1246297] hdafg4: DIG03 2ch: SPDIF Out [Jack]
[   1.1246297] hdafg4: 8ch/2ch 48000Hz PCM16*
[   1.1246297] audio0 at hdafg4: playback, capture, full duplex, independent
[   1.1246297] audio0: slinear_le:16 8ch 48000Hz, blk 40ms for playback
[   1.1246297] audio0: slinear_le:16 2ch 48000Hz, blk 40ms for recording
[   1.1246297] spkr1 at audio0: PC Speaker (synthesized)
[   1.1246297] wsbell at spkr1 not configured
[   1.1246297] pcib0 at pci0 dev 20 function 3: vendor 1002 product 439d (rev. 0x40)
[   1.1246297] ppb4 at pci0 dev 20 function 4: vendor 1002 product 4384 (rev. 0x40)
[   1.1246297] pci5 at ppb4 bus 2
[   1.1246297] fwohci0 at pci5 dev 8 function 0: vendor 1106 product 3044 (rev. 0xc0)
[   1.1246297] fwohci0: interrupting at ioapic0 pin 20
[   1.1246297] fwohci0: OHCI version 1.10 (ROM=1)
[   1.1246297] fwohci0: No. of Isochronous channels is 4.
[   1.1246297] fwohci0: EUI64 00:1f:c6:00:00:0a:ca:1a
[   1.1246297] fwohci0: Phy 1394a available S400, 2 ports.
[   1.1246297] fwohci0: Link S400, max_rec 2048 bytes.
[   1.1246297] ieee1394if0 at fwohci0: IEEE1394 bus
[   1.1246297] fwip0 at ieee1394if0: IP over IEEE1394
[   1.1246297] fwohci0: Initiate bus reset
[   1.1246297] ohci2 at pci0 dev 20 function 5: vendor 1002 product 4399 (rev. 0x00)
[   1.1246297] ohci2: interrupting at ioapic0 pin 18
[   1.1246297] ohci2: OHCI version 1.0, legacy support
[   1.1246297] usb6 at ohci2: USB revision 1.0
[   1.1246297] ppb5 at pci0 dev 21 function 0: vendor 1002 product 43a0 (rev. 0x00)
[   1.1246297] ppb5: PCI Express capability version 2 <Root Port of PCI-E Root Complex> x1 @ 5.0GT/s
[   1.1246297] ppb5: link is x1 @ 2.5GT/s
[   1.1246297] pci6 at ppb5 bus 1
[   1.1246297] re0 at pci6 dev 0 function 0: RealTek 8168/8111 PCIe Gigabit Ethernet (rev. 0x06)
[   1.1246297] re0: interrupting at ioapic0 pin 16
[   1.1246297] re0: Ethernet address bc:ae:c5:46:16:58
[   1.1246297] rgephy0 at re0 phy 7: RTL8211D 1000BASE-T media interface
[   1.1246297] rgephy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-FDX, auto
[   1.1246297] ohci3 at pci0 dev 22 function 0: vendor 1002 product 4397 (rev. 0x00)
[   1.1246297] ohci3: interrupting at ioapic0 pin 18
[   1.1246297] ohci3: OHCI version 1.0, legacy support
[   1.1246297] usb7 at ohci3: USB revision 1.0
[   1.1246297] ehci2 at pci0 dev 22 function 2: vendor 1002 product 4396 (rev. 0x00)
[   1.1246297] ehci2: interrupting at ioapic0 pin 17
[   1.1246297] ehci2: dropped intr workaround enabled
[   1.1246297] ehci2: 1 companion controller, 4 ports: ohci3
[   1.1246297] usb8 at ehci2: USB revision 2.0
[   1.1246297] pchb1 at pci0 dev 24 function 0: vendor 1022 product 1200 (rev. 0x00)
[   1.1246297] pchb2 at pci0 dev 24 function 1: vendor 1022 product 1201 (rev. 0x00)
[   1.1246297] pchb3 at pci0 dev 24 function 2: vendor 1022 product 1202 (rev. 0x00)
[   1.1246297] amdnb_misc0 at pci0 dev 24 function 3: AMD NB Misc Configuration
[   1.1246297] amdtemp0 at amdnb_misc0: AMD CPU Temperature Sensors (Family10h)
[   1.1246297] pchb4 at pci0 dev 24 function 4: vendor 1022 product 1204 (rev. 0x00)
[   1.1246297] isa0 at pcib0
[   1.1246297] com0 at isa0 port 0x3f8-0x3ff irq 4: ns16550a, working fifo
[   1.1246297] com0: console
[   1.1246297] pckbc0 at isa0 port 0x60-0x64
[   1.1246297] acpicpu0 at cpu0: ACPI CPU
[   1.1246297] acpicpu1 at cpu1: ACPI CPU
[   1.1246297] acpicpu2 at cpu2: ACPI CPU
[   1.1246297] acpicpu3 at cpu3: ACPI CPU
[   1.1246297] acpicpu4 at cpu4: ACPI CPU
[   1.1246297] acpicpu5 at cpu5: ACPI CPU
[   1.1246297] fwohci0: BUS reset
[   1.1246297] fwohci0: node_id=0xc800ffc0, gen=1, CYCLEMASTER mode
[   1.1246297] ieee1394if0: 1 nodes, maxhop <= 0 cable IRM irm(0) (me)
[   1.1246297] ieee1394if0: bus manager 0
[   1.9138511] uhub0 at usb0: NetBSD (0000) xHCI root hub (0000), class 9/0, rev 3.00/1.00, addr 0
[   2.0162584] uhub1 at usb1: NetBSD (0000) xHCI root hub (0000), class 9/0, rev 2.00/1.00, addr 0

<---- very long delay here ---->

[   2.4451159] uhub2 at usb4: NetBSD (0000) OHCI root hub (0000), class 9/0, rev 1.00/1.00, addr 1
[   2.5408481] uhub3 at usb6: NetBSD (0000) OHCI root hub (0000), class 9/0, rev 1.00/1.00, addr 1
[   2.6508792] uhub4 at usb3: NetBSD (0000) EHCI root hub (0000), class 9/0, rev 2.00/1.00, addr 1
[   2.7509074] ahcisata1 port 2: device present, speed: 1.5Gb/s
[   2.8209274] uhub5 at usb7: NetBSD (0000) OHCI root hub (0000), class 9/0, rev 1.00/1.00, addr 1
[   2.9209555] uhub6 at usb2: NetBSD (0000) OHCI root hub (0000), class 9/0, rev 1.00/1.00, addr 1
[   3.0209838] uhub7 at usb5: NetBSD (0000) EHCI root hub (0000), class 9/0, rev 2.00/1.00, addr 1
[   3.1347801] ahcisata1 port 0: device present, speed: 6.0Gb/s
[   3.2010346] uhub8 at usb8: NetBSD (0000) EHCI root hub (0000), class 9/0, rev 2.00/1.00, addr 1
[   4.2913429] delaying ask root by 5 seconds due to USB owner change.ehci0: handing over full speed device on port 1 to ohci0
[   4.8314951] wd0 at atabus2 drive 0
[   4.8715064] wd0: <ST2000DL003-9VT166>
[   4.9115178] wd0: 1863 GB, 3876021 cyl, 16 head, 63 sec, 512 bytes/sect x 3907029168 sectors
[   5.0715691] atapibus0 at atabus4: 1 targets
[   5.1315860] cd0 at atapibus0 drive 0: <HL-DT-ST BD-RE  BH10LS38, K89C2CJ1805, 1.03> cdrom removable
[   5.9618142] uplcom0 at uhub6 port 1
[   6.0018256] uplcom0: Prolific Technology Inc. (0x67b) USB-Serial Controller (0x2303), rev 1.10/3.00, addr 2
[   6.1318624] ucom0 at uplcom0
[   9.4027918] boot device: wd0
[   9.4328044] root on wd0e dumps on wd0b


>How-To-Repeat:
see above

>Fix:
n/a