I2c producing crazy console messages [[Re: insanely-high interrupt rates -- PARTIAL resolution (Pi2)]]
Karl Denninger
karl at denninger.net
Thu Apr 18 21:52:08 UTC 2019
On 4/17/2019 14:56, Karl Denninger wrote:
> 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?
BTW the code that is generating this (if there's an endpoint that is
active then this is executed) is:
(analog_address is usually 0x48 although it can be set in the config
file for the code, which is where the I2c analog card is on the I2c bus.)
#ifdef IIC
#include <sys/ioctl.h>
#include <dev/iicbus/iic.h>
#endif
struct iic_msg i2c_msg[2]; /* At most we need two messages */
struct iic_rdwr_data iic_rdwr; /* Read-write structure for ioctl */
unsigned char iic_buf[16]; /* Message buffer */
....
uint8_t offset = 0;
unsigned int analog_val;
....
iic_buf[0] = 0x01; /* Write register 1 */
iic_buf[1] = 0x81; /* Base first byte */
iic_buf[2] = 0x83; /* 1600 s/s, normal */
switch(x) { /* Unit number */
case 0:
iic_buf[1] |= 0x40;
break;
case 1:
iic_buf[1] |= 0x50;
break;
case 2:
iic_buf[1] |= 0x60;
break;
case 4:
iic_buf[1] |= 0x70;
break;
default:
break;
}
iic_buf[1] |= (analog_gain & 0x0e); /* Gain */
i2c_msg[0].slave = analog_address << 1;
i2c_msg[0].flags = !IIC_M_RD;
i2c_msg[0].len = 3; /* 3 bytes to send */
i2c_msg[0].buf = (unsigned char *) &iic_buf;
iic_rdwr.msgs = i2c_msg;
iic_rdwr.nmsgs = 1; /* Send register write */
if (ioctl(iic_handle, I2CRDWR, &iic_rdwr) < 0) {
sprintf(sysbuf, "I2c select failed for analog input on
address [0x%x]", analog_address);
addlog(sysbuf, LOG_WARNING);
analog_available = 0;
}
usleep(analog_delay * 1000);/* Delay for conversion */
iic_buf[0] = 0; /* Clear response area */
iic_buf[1] = 0;
i2c_msg[0].slave = analog_address << 1 | !IIC_M_RD;
i2c_msg[0].flags = !IIC_M_RD; /* Write select */
i2c_msg[0].len = sizeof(offset);
i2c_msg[0].buf = &offset;
i2c_msg[1].slave = analog_address << 1 | IIC_M_RD;
i2c_msg[1].flags = IIC_M_RD;
i2c_msg[1].len = 2; /* Get two bytes of value */
i2c_msg[1].buf = (unsigned char *) &iic_buf;
iic_rdwr.msgs = i2c_msg;
iic_rdwr.nmsgs = 2;
if (ioctl(iic_handle, I2CRDWR, &iic_rdwr) < 0) {
sprintf(sysbuf, "I2c read failed for analog input");
addlog(sysbuf, LOG_WARNING);
analog_available = 0;
}
ioctl(iic_handle, I2CRSTCARD, &iic_rdwr); /* Release */
analog_val = ((iic_buf[0] << 8) + iic_buf[1]) >> analog_shift;
Up until 12.0 this code both worked and did *not* generate complaints
about unhandled interrupts. It still runs fine and returns valid data
BUT if there are any analog endpoints actually on the bus that the code
can read then it generates a lot of these:
local_intc0: Spurious interrupt detected
local_intc0: Spurious interrupt detected
intc0: Spurious interrupt detected
.....
If I do not connect the I2c device then there are no messages. If I
stop the code that is running (e.g. no accesses to the i2c bus) then the
messages stop as well, so it's not something that happens but remains
active after the code halts; it's happening on the actual accesses to
the bus from those ioctl's.
--
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/20190418/d5a0e2b9/attachment.bin>
More information about the freebsd-arm
mailing list