Date: Mon, 24 Apr 2017 21:06:11 -0700 From: Mark Millard <markmi@dsl-only.net> To: freebsd-arm <freebsd-arm@freebsd.org>, freebsd-hackers@freebsd.org Subject: Re: head -r317015 (and before) vs. Pine64+ 2GB (an aarch64) and spurious interrupts: Evidence of a source of irq 1023's (with last irq 27) Message-ID: <D128A050-9688-4BDB-9D16-50DFEF15D6A5@dsl-only.net> In-Reply-To: <B4FDA80F-1E72-4A2B-BE0C-E6F7BE6CDC5F@dsl-only.net> References: <B4FDA80F-1E72-4A2B-BE0C-E6F7BE6CDC5F@dsl-only.net>
next in thread | previous in thread | raw e-mail | index | archive | help
[I add more acquired information from generated
messages this time, spanning a full boot and some
later activity.]
On 2017-Apr-24, at 6:42 PM, Mark Millard <markmi at dsl-only.net> wrote:
> Note: The same kernel used below but installed
> on a rpi3 (aarch64) does not report such spurious
> interrupts. The issue is somehow specific
> to the Pine64+'s or at least not general
> to all aarch64's. (I've access to a Pine64+
> 2GB but Tom V. to a Pine64+ 1GB if I understand
> right. I do not know about other folks.)
>=20
>=20
> The initial pine64+ 2GB context had a powered hub with
> an SSD and had Ethernet plugged in. But unplugging
> everything but the serial console and applying power
> gets the same sort of thing, other than instead of
> 107 shown for the first "last irq" a 64 was shown
> instead.
>=20
>=20
> I made the following change in order to gather
> more evidence for the spurious interrupts that
> I and others have seen on Pine64+'s:
>=20
> FreeBSDx64# svnlite diff /usr/src/sys/arm/arm/gic.c
> Index: /usr/src/sys/arm/arm/gic.c
> =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
> --- /usr/src/sys/arm/arm/gic.c (revision 317015)
> +++ /usr/src/sys/arm/arm/gic.c (working copy)
> @@ -672,9 +672,15 @@
>=20
> if (irq >=3D sc->nirqs) {
> #ifdef GIC_DEBUG_SPURIOUS
> +//#define EXPECTED_SPURIOUS_IRQ 1023
> +// if (irq !=3D EXPECTED_SPURIOUS_IRQ) {
> device_printf(sc->gic_dev,
> - "Spurious interrupt detected: last irq: %d on =
CPU%d\n",
> - sc->last_irq[PCPU_GET(cpuid)], PCPU_GET(cpuid));
> + "Spurious interrupt %d detected of %d: last irq: %d =
on CPU%d\n"
> + "0,1,2,3: last irqs: %d,%d,%d,%d\n",
> + irq, sc->nirqs,
> + sc->last_irq[PCPU_GET(cpuid)], PCPU_GET(cpuid),
> + =
sc->last_irq[0],sc->last_irq[1],sc->last_irq[2],sc->last_irq[3]);
> +// }
> #endif
> return (FILTER_HANDLED);
> }
> @@ -720,6 +726,18 @@
> if (irq < sc->nirqs)
> goto dispatch_irq;
>=20
> +// if (irq !=3D EXPECTED_SPURIOUS_IRQ) {
> +//#undef EXPECTED_SPURIOUS_IRQ
> +#ifdef GIC_DEBUG_SPURIOUS
> + device_printf(sc->gic_dev,
> + "nextirq: Spurious interrupt %d detected of %d: last =
irq: %d on CPU%d\n"
> + "0,1,2,3: last irqs: %d,%d,%d,%d\n",
> + irq, sc->nirqs,
> + sc->last_irq[PCPU_GET(cpuid)], PCPU_GET(cpuid),
> + =
sc->last_irq[0],sc->last_irq[1],sc->last_irq[2],sc->last_irq[3]);
> +#endif
> +// }
> +
> return (FILTER_HANDLED);
> }
>=20
> The second block of code is in the "next_irq:"
> part of the code and has a "nextirq:" prefix
> text to make its messages unique.
>=20
> The console result from a boot attempt with this
> was as follows but first I will note one line from
> it showing the irq 27 binding:
>=20
> ehci0: <Allwinner Integrated USB 2.0 controller> mem =
0x1c1a000-0x1c1a0ff irq 27 on simplebus0
>=20
> That 27 is involved in what is shown below.
>=20
>>> FreeBSD EFI boot block
> Loader path: /boot/loader.efi
>=20
> Initializing modules: ZFS UFS
> Probing 3 block devices.....* done
> ZFS found no pools
> UFS found 1 partition
> Consoles: EFI console =20
> Command line arguments: loader.efi
> Image base: 0xb8dc4000
> EFI version: 2.05
> EFI Firmware: Das U-boot (rev 0.00)
>=20
> FreeBSD/arm64 EFI loader, Revision 1.1
> EFI boot environment
> Loading /boot/defaults/loader.conf
> /boot/kernel/kernel text=3D0x7ba128 data=3D0x9e6f8+0x39c3fe =
syms=3D[0x8+0x103b60+0x8+0xf8a79]
> /boot/entropy size=3D0x1000
>=20
> Hit [Enter] to boot immediately, or any other key for command prompt.
> Booting [/boot/kernel/kernel]... =20
> Using DTB provided by EFI at 0x49000000.
> KDB: debugger backends: ddb
> KDB: current backend: ddb
> Copyright (c) 1992-2017 The FreeBSD Project.
> Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, =
1994
> The Regents of the University of California. All rights =
reserved.
> FreeBSD is a registered trademark of The FreeBSD Foundation.
> FreeBSD 12.0-CURRENT r317015M arm64
> FreeBSD clang version 4.0.0 (tags/RELEASE_400/final 297347) (based on =
LLVM 4.0.0)
> VT: init without driver.
> Starting CPU 1 (1)
> Starting CPU 2 (2)
> Starting CPU 3 (3)
> FreeBSD/SMP: Multiprocessor System Detected: 4 CPUs
> random: unblocking device.
> random: entropy device external interface
> kbd0 at kbdmux0
> ofwbus0: <Open Firmware Device Tree>
> aw_ccu0: <Allwinner Clock Control Unit> on ofwbus0
> clk_fixed0: <Fixed clock> on aw_ccu0
> clk_fixed1: <Fixed clock> on aw_ccu0
> aw_pll0: <Allwinner PLL Clock> mem 0x1c20000-0x1c20003 on aw_ccu0
> aw_pll1: <Allwinner PLL Clock> mem 0x1c20028-0x1c2002b on aw_ccu0
> clk_fixed2: <Fixed factor clock> on aw_ccu0
> aw_pll2: <Allwinner PLL Clock> mem 0x1c2002c-0x1c2002f on aw_ccu0
> aw_cpuclk0: <Allwinner CPU Clock> mem 0x1c20050-0x1c20053 on aw_ccu0
> aw_axiclk0: <Allwinner AXI Clock> mem 0x1c20050-0x1c20053 on aw_ccu0
> aw_ahbclk0: <Allwinner AHB Clock> mem 0x1c20054-0x1c20057 on aw_ccu0
> aw_ahbclk1: <Allwinner AHB Clock> mem 0x1c2005c-0x1c2005f on aw_ccu0
> aw_apbclk0: <Allwinner APB Clock> mem 0x1c20054-0x1c20057 on aw_ccu0
> aw_apbclk1: <Allwinner APB Clock> mem 0x1c20058-0x1c2005b on aw_ccu0
> aw_gate0: <Allwinner Multi Bus Clock Gates> mem 0x1c20060-0x1c20073 on =
aw_ccu0
> aw_modclk0: <Allwinner Module Clock> mem 0x1c20088-0x1c2008b on =
aw_ccu0
> aw_modclk1: <Allwinner Module Clock> mem 0x1c2008c-0x1c2008f on =
aw_ccu0
> aw_modclk2: <Allwinner Module Clock> mem 0x1c20090-0x1c20093 on =
aw_ccu0
> aw_pll3: <Allwinner PLL Clock> mem 0x1c20044-0x1c20047 on aw_ccu0
> aw_usbclk0: <Allwinner USB Clocks> mem 0x1c200cc-0x1c200cf on aw_ccu0
> aw_thsclk0: <Allwinner THS Clock> mem 0x1c20074-0x1c20077 on aw_ccu0
> simplebus0: <Flattened device tree simple bus> on ofwbus0
> aw_reset0: <Allwinner Module Resets> mem 0x1c202c0-0x1c202cb on =
simplebus0
> aw_reset1: <Allwinner Module Resets> mem 0x1c202d0-0x1c202d3 on =
simplebus0
> aw_reset2: <Allwinner Module Resets> mem 0x1c202d8-0x1c202db on =
simplebus0
> regfix0: <Fixed Regulator> on simplebus0
> psci0: <ARM Power State Co-ordination Interface Driver> on ofwbus0
> aw_sid0: <Allwinner Secure ID Controller> mem 0x1c14000-0x1c143ff on =
simplebus0
> iichb0: <Allwinner RSB> mem 0x1f03400-0x1f037ff irq 24 on simplebus0
> iicbus0: <OFW I2C bus> on iichb0
> awusbphy0: <Allwinner USB PHY> mem =
0x1c19400-0x1c19423,0x1c1a800-0x1c1a803,0x1c1b800-0x1c1b803 on =
simplebus0
> gic0: <ARM Generic Interrupt Controller> mem =
0x1c81000-0x1c81fff,0x1c82000-0x1c83fff,0x1c84000-0x1c85fff,0x1c86000-0x1c=
87fff irq 0 on ofwbus0
> gic0: pn 0x2, arch 0x2, rev 0x1, implementer 0x43b irqs 224
> gpio0: <Allwinner GPIO/Pinmux controller> mem 0x1c20800-0x1c20bff irq =
8,9,10 on simplebus0
> gpiobus0: <OFW GPIO bus> on gpio0
> aw_nmi0: <Allwinner NMI Controller> mem 0x1f00c0c-0x1f00c43 irq 23 on =
simplebus0
> axp81x_pmu0: <X-Powers AXP81x Power Management Unit> at addr 0x746 irq =
30 on iicbus0
> gpiobus1: <OFW GPIO bus> on axp81x_pmu0
> generic_timer0: <ARMv8 Generic Timer> irq 1,2,3,4 on ofwbus0
> Timecounter "ARM MPCore Timecounter" frequency 24000000 Hz quality =
1000
> Event timer "ARM MPCore Eventtimer" frequency 24000000 Hz quality 1000
> rtc0: <Allwinner RTC> mem 0x1f00000-0x1f00053 irq 16,17 on simplebus0
> cpulist0: <Open Firmware CPU Group> on ofwbus0
> cpu0: <Open Firmware CPU> on cpulist0
> cpufreq_dt0: <Generic cpufreq driver> on cpu0
> cpu1: <Open Firmware CPU> on cpulist0
> cpu2: <Open Firmware CPU> on cpulist0
> cpu3: <Open Firmware CPU> on cpulist0
> a10_mmc0: <Allwinner Integrated MMC/SD controller> mem =
0x1c0f000-0x1c0ffff irq 5 on simplebus0
> mmc0: <MMC/SD bus> on a10_mmc0
> gpioc0: <GPIO controller> on gpio0
> uart0: <16750 or compatible> mem 0x1c28000-0x1c283ff irq 11 on =
simplebus0
> uart0: console (115384,n,8,1)
> awg0: <Allwinner Gigabit Ethernet> mem =
0x1c30000-0x1c300ff,0x1c00030-0x1c00033 irq 21 on simplebus0
> miibus0: <MII bus> on awg0
> rgephy0: <RTL8169S/8110S/8211 1000BASE-T media interface> PHY 0 on =
miibus0
> rgephy0: none, 10baseT, 10baseT-FDX, 10baseT-FDX-flow, 100baseTX, =
100baseTX-FDX, 100baseTX-FDX-flow, 1000baseT, 1000baseT-master, =
1000baseT-FDX, 1000baseT-FDX-master, 1000baseT-FDX-flow, =
1000baseT-FDX-flow-master, auto, auto-flow
> rgephy1: <RTL8169S/8110S/8211 1000BASE-T media interface> PHY 1 on =
miibus0
> rgephy1: none, 10baseT, 10baseT-FDX, 10baseT-FDX-flow, 100baseTX, =
100baseTX-FDX, 100baseTX-FDX-flow, 1000baseT, 1000baseT-master, =
1000baseT-FDX, 1000baseT-FDX-master, 1000baseT-FDX-flow, =
1000baseT-FDX-flow-master, auto, auto-flow
> awg0: Ethernet address: 02:ba:58:11:06:4e
> aw_wdog0: <Allwinner A31 Watchdog> mem 0x1c20ca0-0x1c20cbf irq 22 on =
simplebus0
> gpioc1: <GPIO controller> on axp81x_pmu0
> iic0: <I2C generic I/O> on iicbus0
> aw_thermal0: <Allwinner Thermal Sensor Controller> mem =
0x1c25000-0x1c253ff irq 25 on simplebus0
> ohci0: <Generic OHCI Controller> mem 0x1c1a400-0x1c1a4ff irq 26 on =
simplebus0
> usbus0 on ohci0
> ehci0: <Allwinner Integrated USB 2.0 controller> mem =
0x1c1a000-0x1c1a0ff irq 27 on simplebus0
> usbus1: EHCI version 1.0
> usbus1 on ehci0
> ohci1: <Generic OHCI Controller> mem 0x1c1b400-0x1c1b4ff irq 28 on =
simplebus0
> usbus2 on ohci1
> ehci1: <Allwinner Integrated USB 2.0 controller> mem =
0x1c1b000-0x1c1b0ff irq 29 on simplebus0
> usbus3: EHCI version 1.0
> usbus3 on ehci1
> cryptosoft0: <software crypto>
> gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 107 =
on CPU0
> 0,1,2,3: last irqs: 107,0,0,0
> Timecounters tick every 1.000 msec
> gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 27 =
on CPU0
> 0,1,2,3: last irqs: 27,0,0,0
> gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 27 =
on CPU0
> 0,1,2,3: last irqs: 27,0,0,0
> gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 27 =
on CPU0
> 0,1,2,3: last irqs: 27,0,0,0
> gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 27 =
on CPU0
> 0,1,2,3: last irqs: 27,0,0,0
> gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 27 =
on CPU0
> 0,1,2,3: last irqs: 27,0,0,0
> gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 27 =
on CPU0
> 0,1,2,3: last irqs: 27,0,0,0
> gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 27 =
on CPU0
> 0,1,2,3: last irqs: 27,0,0,0
> gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 27 =
on CPU0
> 0,1,2,3: last irqs: 27,0,0,0
> gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 27 =
on CPU0
> 0,1,2,3: last irqs: 27,0,0,0
> gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 27 =
on CPU0
> 0,1,2,3: last irqs: 27,0,0,0
> . . .
>=20
> The messages just seem to be continuously generated. I ended up =
unplugging
> the Pine64+ 2GB power.
>=20
> But they were all 27's expect for that first one being a 107 (or 64).
>=20
> So this starts before any of the other cores are started.
>=20
>=20
> I'll see if I can come up with a test showing later behavior.
I updated my change to avoid reporting the:
nextirq: . . . last irq: 27 on CPU 0
messages. This allows the boot to progress in
reasonable time and exposes more notices with
other content.
FreeBSDx64# svnlite diff /usr/src/sys/arm/arm/gic.c
Index: /usr/src/sys/arm/arm/gic.c
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
--- /usr/src/sys/arm/arm/gic.c (revision 317015)
+++ /usr/src/sys/arm/arm/gic.c (working copy)
@@ -672,9 +672,15 @@
=20
if (irq >=3D sc->nirqs) {
#ifdef GIC_DEBUG_SPURIOUS
+#define EXPECTED_SPURIOUS_IRQ 1023
+// if (irq !=3D EXPECTED_SPURIOUS_IRQ) {
device_printf(sc->gic_dev,
- "Spurious interrupt detected: last irq: %d on =
CPU%d\n",
- sc->last_irq[PCPU_GET(cpuid)], PCPU_GET(cpuid));
+ "Spurious interrupt %d detected of %d: last irq: %d =
on CPU%d\n"
+ "0,1,2,3: last irqs: %d,%d,%d,%d\n",
+ irq, sc->nirqs,
+ sc->last_irq[PCPU_GET(cpuid)], PCPU_GET(cpuid),
+ =
sc->last_irq[0],sc->last_irq[1],sc->last_irq[2],sc->last_irq[3]);
+// }
#endif
return (FILTER_HANDLED);
}
@@ -720,6 +726,22 @@
if (irq < sc->nirqs)
goto dispatch_irq;
=20
+ if ( irq !=3D EXPECTED_SPURIOUS_IRQ
+ || ( 0 =3D=3D PCPU_GET(cpuid)
+ && 27 !=3D sc->last_irq[0]
+ )
+ ) {
+#undef EXPECTED_SPURIOUS_IRQ
+#ifdef GIC_DEBUG_SPURIOUS
+ device_printf(sc->gic_dev,
+ "nextirq: Spurious interrupt %d detected of %d: last =
irq: %d on CPU%d\n"
+ "0,1,2,3: last irqs: %d,%d,%d,%d\n",
+ irq, sc->nirqs,
+ sc->last_irq[PCPU_GET(cpuid)], PCPU_GET(cpuid),
+ =
sc->last_irq[0],sc->last_irq[1],sc->last_irq[2],sc->last_irq[3]);
+#endif
+ }
+
return (FILTER_HANDLED);
In this section I mix in comments at points of the sequence
and I do not show every message but blocks of them.
This example has the Ethernet plugged in and the powered
USB HUB and its SSD in place. The SSD has the root file
system that is booted.
Initially for test test context:
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 107 on =
CPU0
0,1,2,3: last irqs: 107,0,0,0
Timecounters tick every 1.000 msec
usbus0: gic0: nextirq: Spurious interrupt 1023 detected of 224: last =
irq: 92 on CPU0
0,1,2,3: last irqs: 92,0,0,0
12Mbps Full Speed USB v1.0
usbus1: 480Mbps High Speed USB v2.0
usbus2: 12Mbps Full Speed USB v1.0
usbus3: 480Mbps High Speed USB v2.0
ugen0.1: <Generic OHCI root HUB> at usbus0
uhub0: <Generic OHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on =
usbus0
ugen1.1: <Allwinner EHCI root HUB> at usbus1
uhub1: <Allwinner EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on =
usbus1
ugen2.1: <Generic OHCI root HUB> at usbus2
uhub2: <Generic OHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on =
usbus2
ugen3.1: <Allwinner EHCI root HUB> at usbus3
uhub3: <Allwinner EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on =
usbus3
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,0,0,0
. . .
Then later "last irq: 106"s start being involved:
. . .
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU0
0,1,2,3: last irqs: 106,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU0
0,1,2,3: last irqs: 106,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU0
0,1,2,3: last irqs: 106,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU0
0,1,2,3: last irqs: 106,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU0
0,1,2,3: last irqs: 106,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU0
0,1,2,3: last irqs: 106,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU0
0,1,2,3: last irqs: 106,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU0
0,1,2,3: last irqs: 106,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU0
0,1,2,3: last irqs: 106,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU0
0,1,2,3: last irqs: 106,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU0
0,1,2,3: last irqs: 106,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU0
0,1,2,3: last irqs: 106,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU0
0,1,2,3: last irqs: 106,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU0
0,1,2,3: last irqs: 106,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU0
0,1,2,3: last irqs: 106,0,0,0
. . .
Once multiple cores are running the "nextirq:" messages stop and
transition to all being from the first message block in the updated
code. At which point "last irq: 27 on CPU 0" can be and is reported
again.
First I show up to the first non"nextirq:" message. . .
. . .
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU0
0,1,2,3: last irqs: 106,0,0,0
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU0
0,1,2,3: last irqs: 106,0,0,0
da0 at umass-sim0 bus 0 scbus0 target 0 lun 0
da0: <OWC Envoy Pro mini 0> Fixed Direct Access SPC-4 SCSI device
da0: Serial Number <REPLACED>
da0: 40.000MB/s transfers
da0: 228936MB (468862128 512 byte sectors)
da0: quirks=3D0x2<NO_6_BYTE>
Release APs
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU0
0,1,2,3: last irqs: 106,27,27,27
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU0
0,1,2,3: last irqs: 106,27,27,27
CPU 0: ARM Cortex-A53 r0p4 affinity: 0
Instruction Set Attributes 0 =3D <AES+PMULL,SHA1,SHA2,CRC32>
Instruction Set Attributes 1 =3D <0>
Processor Features 0 =3D <AdvSIMD,Float,EL3 32,EL2 32,EL1 =
32,EL0 32>
Processor Features 1 =3D <0>
Memory Model Features 0 =3D <4k Granule,64k =
Granule,MixedEndian,S/NS Mem,16bit ASID,1TB PA>
Memory Model Features 1 =3D <>
Debug Features 0 =3D <2 CTX Breakpoints,4 Watchpoints,6 =
Breakpoints,PMUv3,Debug v8>
Debug Features 1 =3D <0>
Auxiliary Features 0 =3D <0>
Auxiliary Features 1 =3D <0>
CPU 1: ARM Cortex-A53 r0p4 affinity: 1
CPU 2: ARM Cortex-A53 r0p4 affinity: 2
CPU 3: ARM Cortex-A53 r0p4 affinity: 3
Trying to mount root from ufs:/dev/ufs/PINE642Grootfs [rw,noatime]...
Setting hostuuid: a4f7fbeb-f668-11de-b280-ebb65474e619.
Setting hostid: 0xcd8e9e25.
Starting file system checks:
/dev/ufs/PINE642Grootfs: FILE SYSTEM CLEAN; SKIPPING CHECKS
/dev/ufs/PINE642Grootfs: clean, 40252336 free (325480 frags, 4990857 =
blocks, 0.7% fragmentation)
Mounting local filesystems:gic0: nextirq: Spurious interrupt 1023 =
detected of 224: last irq: 92 on CPU0
0,1,2,3: last irqs: 92,27,27,27
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,27,27,27
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,27,27,27
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,27,27,27
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,27,27,27
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,27,27,27
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,27,27,27
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,27,27,27
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,27,27,27
.
ELF ldconfig path: /lib /usr/lib /usr/lib/compat /usr/local/lib =
/usr/local/lib/gcc6 /usr/local/lib/perl5/5.24/mach/CORE =
/usr/local/llvm40/lib
Setting hostname: pine64.
Setting up harvesting: =
[UMA],[FS_ATIME],SWI,INTERRUPT,NET_NG,NET_ETHER,NET_TUN,MOUSE,KEYBOARD,ATT=
ACH,CACHED
Feeding entropy: .
awg0: link state changed to DOWN
Starting dhclient.
awg0: no link ......awg0: link state changed to UP
got link
Starting Network: lo0 awg0.
lo0: flags=3D8049<UP,LOOPBACK,RUNNING,MULTICAST> metric 0 mtu 16384
options=3D600003<RXCSUM,TXCSUM,RXCSUM_IPV6,TXCSUM_IPV6>
inet6 ::1 prefixlen 128=20
inet6 fe80::1%lo0 prefixlen 64 scopeid 0x2=20
inet 127.0.0.1 netmask 0xff000000=20
groups: lo=20
nd6 options=3D21<PERFORMNUD,AUTO_LINKLOCAL>
awg0: flags=3D8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu =
1500
options=3D8000b<RXCSUM,TXCSUM,VLAN_MTU,LINKSTATE>
ether 02:ba:58:11:06:4e
inet 192.168.1.103 netmask 0xffffff00 broadcast 192.168.1.255=20
media: Ethernet autoselect (1000baseT <full-duplex>)
status: active
nd6 options=3D29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
Starting devd.
add host 127.0.0.1: gateway lo0 fib 0: route already in table
add host ::1: gateway lo0 fib 0: route already in table
add net fe80::: gateway ::1
add net ff02::: gateway ::1
add net ::ffff:0.0.0.0: gateway ::1
add net ::0.0.0.0: gateway ::1
Creating and/or trimming log files.
Starting syslogd.
Starting rpcbind.
No core dumps found.
NFS access cache time=3D60
Clearing /tmp (X related).
NFSv4 is disabled
Starting mountd.
Starting nfsd.
Updating motd:.
Mounting late filesystems:.
Starting ntpd.
Starting powerd.
And from here on no more "nextirq:" messages occur during the
boot activity. . .
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU0
0,1,2,3: last irqs: 27,27,27,106
Performing sanity check on sshd configuration.
gic0: Spurious interrupt 1023 detected of 224: last irq: 106 on CPU3
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 106 on CPU3
gic0: 0,1,2,3: last irqs: 27,27,27,106
Spurious interrupt 1023 detected of 224: last irq: 27 on CPU0
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 106 on CPU3
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 106 on CPU3
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU0
0,1,2,3: last irqs: 27,27,27,106
Starting sshd.
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU1
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU1
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU1
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU1
0,1,2,3: last irqs: 27,27,27,27
gic0: Spurious interrupt 1023 detected of 224: last irq: 106 on CPU3
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU1
0,1,2,3: last irqs: 27,27,27,27
gic0: gic0: Spurious interrupt 1023 detected of 224: last irq: 106 on =
CPU3
Spurious interrupt 1023 detected of 224: last irq: 27 on CPU0
0,1,2,3: last irqs: 27,27,27,106
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU2
0,1,2,3: last irqs: 27,27,27,27
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU1
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU1
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU1
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU1
0,1,2,3: last irqs: 27,27,27,106
gic0: gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on =
CPU2
Spurious interrupt 1023 detected of 224: last irq: 27 on CPU0
0,1,2,3: last irqs: 27,27,27,106
0,1,2,3: last irqs: 27,27,27,106
gic0: gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on =
CPU2
Spurious interrupt 1023 detected of 224: last irq: 27 on CPU0
0,1,2,3: last irqs: 27,27,27,106
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU2
0,1,2,3: last irqs: 27,114,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU2
0,1,2,3: last irqs: 27,114,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU2
0,1,2,3: last irqs: 27,114,27,106
. . .
Eventually there is evidence of 114 (see above) and of
32 or such in the list of last irqs across the cores,
for example:
Starting background file system checks in 60 seconds.
gic0: gic0: Spurious interrupt 1023 detected of 224: last irq: 32 on =
CPU1
Spurious interrupt 1023 detected of 224: last irq: 27 on CPU2
0,1,2,3: last irqs: 27,32,27,27
0,1,2,3: last irqs: 27,32,27,27
. . .
114 and 32 are not as common.
Eventually when sitting idle it quits generating messages.
Then if I run openssl speed, possibly in parallel,
it is not generating messages while busy, other than
possibly some at the start.
But something like find / -name test print does generate
messages. For example:
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,27,27,27
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,27,27,27
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,27,27,27
gic0: nextirq: Spurious interrupt 1023 detected of 224: last irq: 92 on =
CPU0
0,1,2,3: last irqs: 92,27,27,27
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU2
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU2
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 106 on CPU3
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU0
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU0
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 106 on CPU3
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 106 on CPU3
0,1,2,3: last irqs: 27,27,27,106
gic0: gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on =
CPU0
Spurious interrupt 1023 detected of 224: last irq: 106 on CPU3
0,1,2,3: last irqs: 27,27,27,106
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 27 on CPU0
0,1,2,3: last irqs: 27,27,27,106
gic0: Spurious interrupt 1023 detected of 224: last irq: 106 on CPU3
0,1,2,3: last irqs: 27,27,27,106
. . .
Only initially did it get 92's, but note that they are "nextirq:"
messages again!
The rest being 27's and 106's and being from the first message
code instead of from the "nextirq:" message.
Trying find looking at the mmcsd0 gets nearly all 92's with
"nextirq:" messages, suggesting that it is tied to the microSD
card I/O, much like 27 seems to be for USB.
For now I stop with that. I've not figured out how to get any
better/non-redundant information.
I vaguely remember that I've once seen something that had a
table with something about what irq's numbers were for what in
some possibly analogous context. But I do not remember where
I ran into such a document. (And may be it was not for the
Pine64+ context.)
=3D=3D=3D
Mark Millard
markmi at dsl-only.net
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?D128A050-9688-4BDB-9D16-50DFEF15D6A5>