insanely-high interrupt rates -- PARTIAL resolution (Pi2)

Wed Apr 17 19:56:35 UTC 2019

On 4/9/2019 19:25, Ian Lepore wrote:
> On Tue, 2019-04-09 at 09:55 -0500, Karl Denninger wrote:
>> On 4/3/2019 11:48, Andrew Gierth wrote:
>>> Per my earlier analysis, and the discussion on IRC, I'm now running
>>> my
>>> RPI2B with the attached patch (against 12-stable). So far, I'm not
>>> seeing any issues.
>>>
>>> I don't think this patch is really a complete fix (in particular,
>>> on
>>> arm64 I would expect the opposite problem to exist, with spurious
>>> physical timer interrupts instead). I'm only running it to confirm
>>> my
>>> analysis of the problem and to get a working system. It should do
>>> fine
>>> on 32-bit arm though.
>> Any progress on this into or within the tree (or comments on what is
>> a
>> trivially small patch) for 12-STABLE?
> I've just posted https://reviews.freebsd.org/D19871 for this. 
> Hopefully I'll get it committed in a day or so and merged to 12-stable
> a few days after that.
>
> -- Ian

I am running that now on a Pi2 and so far the load problem is gone but
the spurious interrupt warnings are not....

---<<BOOT>>---
Copyright (c) 1992-2019 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-STABLE #0 r346327M: Wed Apr 17 14:00:58 CDT 2019

karl at NewFS.denninger.net:/work/Crochet-work-ARM32/obj/work/CrossBuild-12STABLE/src/arm.armv7/sys/GENERIC
arm
FreeBSD clang version 8.0.0 (tags/RELEASE_800/final 356365) (based on
LLVM 8.0.0)
VT: init without driver.
module_register: cannot register ofwbus/pcib from kernel; already loaded
from kernel
Module ofwbus/pcib failed to register: 17
module_register: cannot register simplebus/pcib from kernel; already
loaded from kernel
Module simplebus/pcib failed to register: 17
No PSCI/SMCCC call function found
CPU: ARM Cortex-A7 r0p5 (ECO: 0x00000000)
CPU Features:
  Multiprocessing, Thumb2, Security, Virtualization, Generic Timer, VMSAv7,
  PXN, LPAE, Coherent Walk
Optional instructions:
  SDIV/UDIV, UMULL, SMULL, SIMD(ext)
LoUU:2 LoC:3 LoUIS:2
Cache level 1:
 32KB/64B 4-way data cache WB Read-Alloc Write-Alloc
 32KB/32B 2-way instruction cache Read-Alloc
Cache level 2:
 512KB/64B 8-way unified cache WB Read-Alloc Write-Alloc
real memory  = 994045952 (947 MB)
avail memory = 957923328 (913 MB)
FreeBSD/SMP: Multiprocessor System Detected: 4 CPUs
arc4random: no preloaded entropy cache
random: entropy device external interface
kbd0 at kbdmux0
ofwbus0: <Open Firmware Device Tree>
simplebus0: <Flattened device tree simple bus> on ofwbus0
ofw_clkbus0: <OFW clocks bus> on ofwbus0
clk_fixed0: <Fixed clock> on ofw_clkbus0
clk_fixed1: <Fixed clock> on ofw_clkbus0
regfix0: <Fixed Regulator> on ofwbus0
regfix1: <Fixed Regulator> on ofwbus0
local_intc0: <BCM2836 Interrupt Controller> mem 0x40000000-0x400000ff on
simplebus0
intc0: <BCM2835 Interrupt Controller> mem 0x7e00b200-0x7e00b3ff irq 20
on simplebus0
gpio0: <BCM2708/2835 GPIO controller> mem 0x7e200000-0x7e2000b3 irq
23,24 on simplebus0
gpiobus0: <OFW GPIO bus> on gpio0
generic_timer0: <ARMv7 Generic Timer> irq 0,1,2,3 on ofwbus0
Timecounter "ARM MPCore Timecounter" frequency 19200000 Hz quality 1000
Event timer "ARM MPCore Eventtimer" frequency 19200000 Hz quality 1000
bcm_dma0: <BCM2835 DMA Controller> mem 0x7e007000-0x7e007eff irq
4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19 on simplebus0
bcmwd0: <BCM2708/2835 Watchdog> mem 0x7e100000-0x7e100027 on simplebus0
bcmrng0: <Broadcom BCM2835 RNG> mem 0x7e104000-0x7e10400f irq 21 on
simplebus0
mbox0: <BCM2835 VideoCore Mailbox> mem 0x7e00b880-0x7e00b8bf irq 22 on
simplebus0
gpioc0: <GPIO controller> on gpio0
uart0: <PrimeCell UART (PL011)> mem 0x7e201000-0x7e201fff irq 25 on
simplebus0
uart0: console (115200,n,8,1)
spi0: <BCM2708/2835 SPI controller> mem 0x7e204000-0x7e204fff irq 27 on
simplebus0
spibus0: <OFW SPI bus> on spi0
spibus0: <unknown card> at cs 0 mode 0
spibus0: <unknown card> at cs 1 mode 0
iichb0: <BCM2708/2835 BSC controller> mem 0x7e804000-0x7e804fff irq 40
on simplebus0
bcm283x_dwcotg0: <DWC OTG 2.0 integrated USB controller (bcm283x)> mem
0x7e980000-0x7e98ffff,0x7e006000-0x7e006fff irq 46,47 on simplebus0
usbus0 on bcm283x_dwcotg0
pmu0: <Performance Monitoring Unit> irq 49 on simplebus0
sdhci_bcm0: <Broadcom 2708 SDHCI controller> mem 0x7e300000-0x7e3000ff
irq 50 on simplebus0
mmc0: <MMC/SD bus> on sdhci_bcm0
fb0: <BCM2835 VT framebuffer driver> on simplebus0
fbd0 on fb0
VT: initialize with new VT driver "fb".
fb0: 656x416(656x416 at 0,0) 24bpp
fb0: fbswap: 1, pitch 1968, base 0x3eb33000, screen_size 818688
vchiq0: <BCM2835 VCHIQ> mem 0x7e00b840-0x7e00b84e irq 53 on simplebus0
vchiq: local ver 8 (min 3), remote ver 8.
pcm0: <VCHIQ audio> on vchiq0
cpulist0: <Open Firmware CPU Group> on ofwbus0
cpu0: <Open Firmware CPU> on cpulist0
bcm2835_cpufreq0: <CPU Frequency Control> on cpu0
cpu1: <Open Firmware CPU> on cpulist0
cpu2: <Open Firmware CPU> on cpulist0
cpu3: <Open Firmware CPU> on cpulist0
gpioled0: <GPIO LEDs> on ofwbus0
cryptosoft0: <software crypto>
Timecounters tick every 1.000 msec
iicbus0: <OFW I2C bus> on iichb0
iic0: <I2C generic I/O> on iicbus0
usbus0: 480Mbps High Speed USB v2.0
ugen0.1: <DWCOTG OTG Root HUB> at usbus0
uhub0: <DWCOTG OTG Root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus0
mmcsd0: 32GB <SDHC GB2MW 3.0 SN AB4D5328 MFG 09/2017 by 27 SM> at mmc0
50.0MHz/4bit/65535-block
bcm2835_cpufreq0: ARM 600MHz, Core 250MHz, SDRAM 400MHz, Turbo OFF
Release APs
Trying to mount root from ufs:/dev/mmcsd0s2a [ro]...
Warning: no time-of-day clock registered, system time will not be set
accurately
arc4random: no preloaded entropy cache
uhub0: 1 port with 1 removable, self powered
arc4random: no preloaded entropy cache
arc4random: no preloaded entropy cache
ugen0.2: <vendor 0x0424 product 0x9514> at usbus0
uhub1 on uhub0
uhub1: <vendor 0x0424 product 0x9514, class 9/0, rev 2.00/2.00, addr 2>
on usbus0
uhub1: MTT enabled
uhub1: 5 ports with 4 removable, self powered
ugen0.3: <vendor 0x0424 product 0xec00> at usbus0
smsc0 on uhub1
smsc0: <vendor 0x0424 product 0xec00, rev 2.00/2.00, addr 3> on usbus0
smsc0: chip 0xec00, rev. 0002
miibus0: <MII bus> on smsc0
smscphy0: <SMC LAN8700 10/100 interface> PHY 1 on miibus0
smscphy0:  10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
ue0: <USB Ethernet> on smsc0
ue0: Ethernet address: b8:27:eb:0d:05:01
ugen0.4: <Realtek 802.11n WLAN Adapter> at usbus0
Setting hostuuid: 71cb8b11-9e46-11e8-9b11-b827eb8521de.
Setting hostid: 0x0c208d92.
Starting file system checks:
/dev/mmcsd0s2a: FILE SYSTEM CLEAN; SKIPPING CHECKS
/dev/mmcsd0s2a: clean, 315681 free (137 frags, 39443 blocks, 0.0%
fragmentation)
/dev/mmcsd0s2d: FILE SYSTEM CLEAN; SKIPPING CHECKS
/dev/mmcsd0s2d: clean, 7360 free (16 frags, 918 blocks, 0.2% fragmentation)
/dev/mmcsd0s2e: FILE SYSTEM CLEAN; SKIPPING CHECKS
/dev/mmcsd0s2e: clean, 44409 free (17 frags, 5549 blocks, 0.0%
fragmentation)
Mounting local filesystems:.
ELF ldconfig path: /lib /usr/lib /usr/lib/compat /usr/local/lib
/usr/local/lib/perl5/5.28/mach/CORE
random: unblocking device.
Soft Float compatibility ldconfig path:
Setting hostname: Pool-MCP.Denninger.Net.
Setting up harvesting:
[UMA],[FS_ATIME],SWI,INTERRUPT,NET_NG,NET_ETHER,NET_TUN,MOUSE,KEYBOARD,ATTACH,CACHED
Feeding entropy: dd: /entropy: Read-only file system
dd: /boot/entropy: Read-only file system

ifconfig: SIOCIFCREATE2: Invalid argument
lo0: link state changed to UP
smsc0: chip 0xec00, rev. 0002
ue0: link state changed to DOWN
Starting Network: lo0 ue0.
lo0: flags=8049<UP,LOOPBACK,RUNNING,MULTICAST> metric 0 mtu 16384
        options=680003<RXCSUM,TXCSUM,LINKSTATE,RXCSUM_IPV6,TXCSUM_IPV6>
        inet6 ::1 prefixlen 128
        inet6 fe80::1%lo0 prefixlen 64 scopeid 0x1
        inet 127.0.0.1 netmask 0xff000000
        groups: lo
        nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>
ue0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
        options=80009<RXCSUM,VLAN_MTU,LINKSTATE>
        ether b8:27:eb:0d:05:01
        media: Ethernet autoselect (none)
        status: no carrier
        nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
Starting devd.
Autoloading module: if_rtwn_usb.ko
rtwn0 on uhub1
rtwn0: <Realtek 802.11n WLAN Adapter, class 0/0, rev 2.00/2.00, addr 4>
on usbus0
rtwn0: MAC/BB RTL8188CUS, RF 6052 1T1R
ieee80211_load_module: load the wlan_amrr module by hand for now.
wlan0: Ethernet address: 74:da:38:59:ec:93
Created wlan(4) interfaces: wlan0.
Starting wpa_supplicant.
Starting Network: wlan0.
wlan0: flags=8c43<UP,BROADCAST,RUNNING,OACTIVE,SIMPLEX,MULTICAST> metric
0 mtu 1500
        ether 74:da:38:59:ec:93
        inet 192.168.10.215 netmask 0xffffff00 broadcast 192.168.10.255
        groups: wlan
        ssid "" channel 10 (2457 MHz 11g)
        regdomain FCC country US authmode WPA1+WPA2/802.11i privacy MIXED
        deftxkey UNDEF txpower 30 bmiss 7 scanvalid 60 protmode CTS wme
        roaming MANUAL
        media: IEEE 802.11 Wireless Ethernet autoselect (autoselect)
        status: no carrier
        nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
wlan0: link state changed to UP
add host 127.0.0.1: gateway lo0 fib 0: route already in table
add net default: gateway 192.168.10.200
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
Generating host.conf.
Creating and/or trimming log filesnewsyslog: can't mkstemp logfile
/tmp/HD-MCP.log.zxtuCOV: Read-only file system
.
Starting syslogd.
Apr 17 19:06:57 Pool-MCP syslogd: /tmp/HD-MCP.log: Read-only file system
Clearing /tmp (X related).
Starting local daemons:Stopping syslogd.
Apr 17 19:06:58 Pool-MCP syslogd: exiting on signal 15
Waiting for PIDS: 794.
Starting syslogd.
HomeDaemon-MCP V5.1.0
Copyright 2016-2018 Karl Denninger
All Rights Reserved
Beginning detached (normal) operation...
.
Updating motd:.
Mounting late filesystems:.
intc0: Spurious interrupt detected
Starting powerd.
Starting ntimed.
RESTART
Configuring vt: blanktime.
intc0: Spurious interrupt detected
Performing sanity check on sshd configuration.
Starting sshd.
Starting sendmail_submit.
Starting sendmail_msp_queue.
Starting cron.
Starting background file system checks in 60 seconds.
rm: /firstboot: Read-only file system

Wed Apr 17 19:07:01 CDT 2019
intc0: Spurious interrupt detected
local_intc0: Spurious interrupt detected
intc0: Spurious interrupt detected
local_intc0: Spurious interrupt detected
intc0: Spurious interrupt detected
local_intc0: Spurious interrupt detected
intc0: Spurious interrupt detected
local_intc0: Spurious interrupt detected
local_intc0: Spurious interrupt detected
local_intc0: Spurious interrupt detected
local_intc0: Spurious interrupt detected
local_intc0: Spurious interrupt detected
intc0: Spurious interrupt detected
intc0: Spurious interrupt detected

....

$ uptime
 2:51PM  up 8 mins, 1 user, load averages: 0.10, 0.13, 0.10

    1 users    Load  0.08  0.12  0.10                  Apr 17 14:52
   Mem usage:   9%Phy  6%Kmem
Mem: KB    REAL            VIRTUAL                      VN PAGER   SWAP
PAGER
        Tot   Share      Tot    Share    Free           in   out    
in   out
Act   27108    8944   125028     9980  849592  count
All   27812    9628   128812    13744          pages
Proc:                                                            Interrupts
  r   p   d   s   w   Csw  Trp  Sys  Int  Sof  Flt        ioflt 35779 total
             25      1001   52  331 9432  109    5        cow    1155
local_intc
                                                        5 zfod   8059
local_intc
 0.4%Sys   0.1%Intr  0.1%User  0.0%Nice 99.5%Idle         ozfod      
local_intc
|    |    |    |    |    |    |    |    |    |           %ozfod      
intc0,1: m
                                                          daefr      
intc0,2: v
                                           dtbuf          prcfr 26306
intc0,17:-
Namei     Name-cache   Dir-cache     30805 desvn          totfr      
intc0,28:
   Calls    hits   %    hits   %      2199 numvn          react     4
intc0,61:
    3007    3005 100                  1034 frevn          pdwak      
intc0,65:
                                                        5 pdpgs      
intc0,70:-
Disks mmcsd                                               intrn      
cpu0:rende
KB/t   0.00                                         66728 wire       
cpu1:rende
tps       0                                         20800 act        
cpu2:rende
MB/s   0.00                                          1388 inact      
cpu3:rende
%busy     0                                               laund      
cpu0:ast
                                                   849592 free       
cpu1:ast
                                                    38884 buf        
cpu2:ast

cpu3:ast
                                                                   23
cpu0:preem
                                                                  122
cpu1:preem
                                                                   55
cpu2:preem
                                                                   55
cpu3:preem

cpu0:hardc

On my bench without the I2c inputs connected (which do analog reads) I
do NOT get the spurious interrupt prints.  With it connected I do.  The
process that reads them is code that is running in both cases, but if it
cannot find the I2c devices it logs the error but continues, so all it
gets to is trying to open the unit, doesn't see it when probed, and
gives up.

It appears that I2c is an inherent part of the spurious interrupt thing
still and while the timer issue appears to be fixed that doesn't resolve
the other problem.

Any ideas on how to track down exactly what is generating those warnings?

-- 
Karl Denninger
karl at denninger.net <mailto:karl at denninger.net>
/The Market Ticker/
/[S/MIME encrypted email preferred]/
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 4897 bytes
Desc: S/MIME Cryptographic Signature
URL: <http://lists.freebsd.org/pipermail/freebsd-arm/attachments/20190417/38010300/attachment.bin>