From owner-freebsd-arm@freebsd.org Tue Apr 25 04:06:14 2017 Return-Path: Delivered-To: freebsd-arm@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 8EF9BD4FB55 for ; Tue, 25 Apr 2017 04:06:14 +0000 (UTC) (envelope-from markmi@dsl-only.net) Received: from asp.reflexion.net (outbound-mail-210-26.reflexion.net [208.70.210.26]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 546571F94 for ; Tue, 25 Apr 2017 04:06:13 +0000 (UTC) (envelope-from markmi@dsl-only.net) Received: (qmail 10684 invoked from network); 25 Apr 2017 04:06:12 -0000 Received: from unknown (HELO mail-cs-02.app.dca.reflexion.local) (10.81.19.2) by 0 (rfx-qmail) with SMTP; 25 Apr 2017 04:06:12 -0000 Received: by mail-cs-02.app.dca.reflexion.local (Reflexion email security v8.40.0) with SMTP; Tue, 25 Apr 2017 00:06:12 -0400 (EDT) Received: (qmail 12350 invoked from network); 25 Apr 2017 04:06:12 -0000 Received: from unknown (HELO iron2.pdx.net) (69.64.224.71) by 0 (rfx-qmail) with (AES256-SHA encrypted) SMTP; 25 Apr 2017 04:06:12 -0000 Received: from [192.168.1.106] (c-76-115-7-162.hsd1.or.comcast.net [76.115.7.162]) by iron2.pdx.net (Postfix) with ESMTPSA id B3E98EC8552; Mon, 24 Apr 2017 21:06:11 -0700 (PDT) Content-Type: text/plain; charset=us-ascii Mime-Version: 1.0 (Mac OS X Mail 10.3 \(3273\)) 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) From: Mark Millard In-Reply-To: Date: Mon, 24 Apr 2017 21:06:11 -0700 Content-Transfer-Encoding: quoted-printable Message-Id: References: To: freebsd-arm , freebsd-hackers@freebsd.org X-Mailer: Apple Mail (2.3273) X-BeenThere: freebsd-arm@freebsd.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: "Porting FreeBSD to ARM processors." List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 25 Apr 2017 04:06:14 -0000 [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 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: 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: > aw_ccu0: on ofwbus0 > clk_fixed0: on aw_ccu0 > clk_fixed1: on aw_ccu0 > aw_pll0: mem 0x1c20000-0x1c20003 on aw_ccu0 > aw_pll1: mem 0x1c20028-0x1c2002b on aw_ccu0 > clk_fixed2: on aw_ccu0 > aw_pll2: mem 0x1c2002c-0x1c2002f on aw_ccu0 > aw_cpuclk0: mem 0x1c20050-0x1c20053 on aw_ccu0 > aw_axiclk0: mem 0x1c20050-0x1c20053 on aw_ccu0 > aw_ahbclk0: mem 0x1c20054-0x1c20057 on aw_ccu0 > aw_ahbclk1: mem 0x1c2005c-0x1c2005f on aw_ccu0 > aw_apbclk0: mem 0x1c20054-0x1c20057 on aw_ccu0 > aw_apbclk1: mem 0x1c20058-0x1c2005b on aw_ccu0 > aw_gate0: mem 0x1c20060-0x1c20073 on = aw_ccu0 > aw_modclk0: mem 0x1c20088-0x1c2008b on = aw_ccu0 > aw_modclk1: mem 0x1c2008c-0x1c2008f on = aw_ccu0 > aw_modclk2: mem 0x1c20090-0x1c20093 on = aw_ccu0 > aw_pll3: mem 0x1c20044-0x1c20047 on aw_ccu0 > aw_usbclk0: mem 0x1c200cc-0x1c200cf on aw_ccu0 > aw_thsclk0: mem 0x1c20074-0x1c20077 on aw_ccu0 > simplebus0: on ofwbus0 > aw_reset0: mem 0x1c202c0-0x1c202cb on = simplebus0 > aw_reset1: mem 0x1c202d0-0x1c202d3 on = simplebus0 > aw_reset2: mem 0x1c202d8-0x1c202db on = simplebus0 > regfix0: on simplebus0 > psci0: on ofwbus0 > aw_sid0: mem 0x1c14000-0x1c143ff on = simplebus0 > iichb0: mem 0x1f03400-0x1f037ff irq 24 on simplebus0 > iicbus0: on iichb0 > awusbphy0: mem = 0x1c19400-0x1c19423,0x1c1a800-0x1c1a803,0x1c1b800-0x1c1b803 on = simplebus0 > gic0: 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: mem 0x1c20800-0x1c20bff irq = 8,9,10 on simplebus0 > gpiobus0: on gpio0 > aw_nmi0: mem 0x1f00c0c-0x1f00c43 irq 23 on = simplebus0 > axp81x_pmu0: at addr 0x746 irq = 30 on iicbus0 > gpiobus1: on axp81x_pmu0 > generic_timer0: 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: mem 0x1f00000-0x1f00053 irq 16,17 on simplebus0 > cpulist0: on ofwbus0 > cpu0: on cpulist0 > cpufreq_dt0: on cpu0 > cpu1: on cpulist0 > cpu2: on cpulist0 > cpu3: on cpulist0 > a10_mmc0: mem = 0x1c0f000-0x1c0ffff irq 5 on simplebus0 > mmc0: on a10_mmc0 > gpioc0: on gpio0 > uart0: <16750 or compatible> mem 0x1c28000-0x1c283ff irq 11 on = simplebus0 > uart0: console (115384,n,8,1) > awg0: mem = 0x1c30000-0x1c300ff,0x1c00030-0x1c00033 irq 21 on simplebus0 > miibus0: on awg0 > rgephy0: 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: 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: mem 0x1c20ca0-0x1c20cbf irq 22 on = simplebus0 > gpioc1: on axp81x_pmu0 > iic0: on iicbus0 > aw_thermal0: mem = 0x1c25000-0x1c253ff irq 25 on simplebus0 > ohci0: mem 0x1c1a400-0x1c1a4ff irq 26 on = simplebus0 > usbus0 on ohci0 > ehci0: mem = 0x1c1a000-0x1c1a0ff irq 27 on simplebus0 > usbus1: EHCI version 1.0 > usbus1 on ehci0 > ohci1: mem 0x1c1b400-0x1c1b4ff irq 28 on = simplebus0 > usbus2 on ohci1 > ehci1: mem = 0x1c1b000-0x1c1b0ff irq 29 on simplebus0 > usbus3: EHCI version 1.0 > usbus3 on ehci1 > cryptosoft0: > 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: at usbus0 uhub0: on = usbus0 ugen1.1: at usbus1 uhub1: on = usbus1 ugen2.1: at usbus2 uhub2: on = usbus2 ugen3.1: at usbus3 uhub3: 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: Fixed Direct Access SPC-4 SCSI device da0: Serial Number da0: 40.000MB/s transfers da0: 228936MB (468862128 512 byte sectors) da0: quirks=3D0x2 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 Instruction Set Attributes 1 =3D <0> Processor Features 0 =3D 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 metric 0 mtu 16384 options=3D600003 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 awg0: flags=3D8843 metric 0 mtu = 1500 options=3D8000b ether 02:ba:58:11:06:4e inet 192.168.1.103 netmask 0xffffff00 broadcast 192.168.1.255=20 media: Ethernet autoselect (1000baseT ) status: active nd6 options=3D29 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