From owner-freebsd-hackers@freebsd.org Tue Apr 25 01:42:27 2017 Return-Path: Delivered-To: freebsd-hackers@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 E9C2DD4E3A5 for ; Tue, 25 Apr 2017 01:42:27 +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 AFB591EFF for ; Tue, 25 Apr 2017 01:42:26 +0000 (UTC) (envelope-from markmi@dsl-only.net) Received: (qmail 9513 invoked from network); 25 Apr 2017 01:43:31 -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 01:43:31 -0000 Received: by mail-cs-02.app.dca.reflexion.local (Reflexion email security v8.40.0) with SMTP; Mon, 24 Apr 2017 21:42:25 -0400 (EDT) Received: (qmail 8880 invoked from network); 25 Apr 2017 01:42:25 -0000 Received: from unknown (HELO iron2.pdx.net) (69.64.224.71) by 0 (rfx-qmail) with (AES256-SHA encrypted) SMTP; 25 Apr 2017 01:42:25 -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 C73A6EC88B5; Mon, 24 Apr 2017 18:42:24 -0700 (PDT) From: Mark Millard Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: quoted-printable Mime-Version: 1.0 (Mac OS X Mail 10.3 \(3273\)) Subject: 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: Date: Mon, 24 Apr 2017 18:42:24 -0700 Cc: Tom Vijlbrief To: freebsd-arm , freebsd-hackers@freebsd.org X-Mailer: Apple Mail (2.3273) X-BeenThere: freebsd-hackers@freebsd.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: Technical Discussions relating to FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 25 Apr 2017 01:42:28 -0000 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.) 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. I made the following change in order to gather more evidence for the spurious interrupts that I and others have seen on Pine64+'s: 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); } 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. 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: ehci0: mem 0x1c1a000-0x1c1a0ff = irq 27 on simplebus0 That 27 is involved in what is shown below. >> FreeBSD EFI boot block Loader path: /boot/loader.efi 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) 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 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 . . . The messages just seem to be continuously generated. I ended up = unplugging the Pine64+ 2GB power. But they were all 27's expect for that first one being a 107 (or 64). So this starts before any of the other cores are started. I'll see if I can come up with a test showing later behavior. =3D=3D=3D Mark Millard markmi at dsl-only.net