Options for FBSD support with LCD device - new project

classic Classic list List threaded Threaded
67 messages Options
1234
Reply | Threaded
Open this post in threaded view
|

Re: Options for FBSD support with LCD device - new project [[Maybe related: I2c issues on the Pi2]]

Karl Denninger

On 3/25/2019 12:09, Bernd Walter wrote:

> On Mon, Mar 25, 2019 at 06:05:35PM +0100, Bernd Walter wrote:
>> On Mon, Mar 25, 2019 at 10:52:26AM -0600, Ian Lepore wrote:
>>> On Mon, 2019-03-25 at 17:48 +0100, Bernd Walter wrote:
>>>> On Mon, Mar 25, 2019 at 11:33:32AM -0500, Karl Denninger wrote:
>>>>>> What do you mean by an insane rate?  It's normal for the usb
>>>>>> controller
>>>>>> to be showing around thousands of int/sec.  Despite what seems
>>>>>> like a
>>>>>> high rate, even on an on rpi-b it uses under 2% cpu to service
>>>>>> that.
>>>>>>
>>>>>> root@rpi:~ # vmstat -i
>>>>>> interrupt                        total       rate
>>>>>> intc0,2: vchiq0                      2          0
>>>>>> intc0,11: systimer0           10103206       1110
>>>>>> intc0,17:-x_dwcotg0          218596055      24007
>>>>>> intc0,28: bcm_dma0                 834          0
>>>>>> intc0,61: iichb0                  5778          1
>>>>>> intc0,65: uart0                   1817          0
>>>>>> intc0,70:-dhci_bcm0                172          0
>>>>>> Total                        228707864      25118
>>>>>>
>>>>>> -- Ian
>>>>> The story gets more odd.
>>>>>
>>>>> The same *physical* unit that I saw this on last night with no I2c
>>>>> device connected I restarted this morning -- changing NOTHING --
>>>>> and it
>>>>> disappeared.
>>>>>
>>>>> But -- on another unit it's still there (I haven't shut down,
>>>>> pulled
>>>>> power and restarted that one.)
>>>>>
>>>>> vmstat -i on both doesn't show anything all that odd:
>>>>> misbehaving that's not there, and neither are the missed interrupt
>>>>> complaints.
>>>>>
>>>>> But again, last night the one that this morning is NOT misbehaving
>>>>> WAS,
>>>>> and was showing the exact same thing.
>>>>>
>>>>> So this looks like something that is not being initialized property
>>>>> at
>>>>> boot time, and sometimes however it comes up causes trouble, and
>>>>> other
>>>>> times it does not -- which is likely to make it a "lot" of fun to
>>>>> find.
>>>> By causing trouble - do you mean it doesn't work?
>>>> I noticed that my system has this message:
>>>> nxprtc0: RTC clock not running
>>>> Warning: bad time from time-of-day clock, system time will not be set
>>>> accurately
>>>> This shouldn't happen, but I wonder if the iic communication works at
>>>> all.
>>>> I likely wouldn't notice if the rtc failed.
>>>> Maybe there was an initial problem at start as you said.
>>>> Will reboot it and see what happens.
>>>> After a reboot the message about the rtc is gone.
>>>> Have to wait at least a day to see if the Spurious are gone too.
>>>>
>>> That's not a symptom of i2c comms failure, it's a symptom of a dead rtc
>>> battery.  The driver has to communicate with the rtc chip to determine
>>> that the oscillator was stopped.  After a reboot all is well, because
>>> the rtc oscillator gets started when the time is written to the chip,
>>> and it keeps running through a reboot and only stops on a power cycle.
>> Agreed, but there is a story behind.
>> The board had a design flaw in that it drained the battery over the
>> pullups into the Pi when the Pi was powered down.
>> I fixed that circuit and did power down tests as well.
>> Don't know if the previous boot was after power down, but it is
>> unlikely that the battery is dead again and if it was a power down then
>> it was a rather short one.
>> It is not a test system, I run it 24/7 as a local ntp server since about
>> only 1-2 months.
> Well - lets reveal another point.
> I have removed the pull ups completely, in the assumption that the Pi itself
> has propper pull ups for at least short wiring.
> It did work, so I left it that way.
> So it could indeed be transfer errors by inadequate pull ups causing it.
Not in my case - the board that was doing it, I power-cycled it and it
disappeared has NOTHING on any of the header/GPIO pins except for the
three wires connected to the USB/Serial interface for the console.
--
Karl Denninger
[hidden email] <mailto:[hidden email]>
/The Market Ticker/
/[S/MIME encrypted email preferred]/

smime.p7s (6K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Options for FBSD support with LCD device - new project [[Maybe related: I2c issues on the Pi2]]

Ian Lepore-3
In reply to this post by Karl Denninger
On Mon, 2019-03-25 at 12:16 -0500, Karl Denninger wrote:

> On 3/25/2019 12:05, Ian Lepore wrote:
> > On Mon, 2019-03-25 at 11:58 -0500, Karl Denninger wrote:
> > > [...]
> >
> > Is the interrupt rate consistent from second to second?  Running
> > 'vmstat 1' for a while might be useful to see that.  That many
> > interrupts almost sounds like a line is floating, but if that were the
> > case I'd expect a widely varying number of int/sec.
> >
> > If you build custom kernels, it might be helpful to apply r345475
> > locally... it will display partial device names instead of just '+'
> > when the name doesn't fit in the vmstat output.
> >
> > -- Ian
>
> No, but it's in the same general range -- around 500k although it does
> flop around some, and occasionally by a lot (e.g. if I sit and watch it
> it'll occasionally put up VERY different numbers -- e.g. a ~730k number,
> then it goes back, etc.)
>
> I don't generally build custom kernels on these but I CAN put this into
> the STABLE tree I'm building that from since I keep a separate one for
> Crochet builds on these boxes.  Where do I find that specific delta?  (I
> usually just svn things and I don't want to roll it all the way back to
> there, right -- or do I?)
>

Apply this patch...

https://svnweb.freebsd.org/base/head/sys/kern/kern_intr.c?view=patch&r1=345475&r2=345474&pathrev=345475

-- Ian

_______________________________________________
[hidden email] mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-arm
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: Options for FBSD support with LCD device - new project [[Maybe related: I2c issues on the Pi2]]

Karl Denninger

On 3/25/2019 12:37, Ian Lepore wrote:

> On Mon, 2019-03-25 at 12:16 -0500, Karl Denninger wrote:
>> On 3/25/2019 12:05, Ian Lepore wrote:
>>> On Mon, 2019-03-25 at 11:58 -0500, Karl Denninger wrote:
>>>> [...]
>>> Is the interrupt rate consistent from second to second?  Running
>>> 'vmstat 1' for a while might be useful to see that.  That many
>>> interrupts almost sounds like a line is floating, but if that were the
>>> case I'd expect a widely varying number of int/sec.
>>>
>>> If you build custom kernels, it might be helpful to apply r345475
>>> locally... it will display partial device names instead of just '+'
>>> when the name doesn't fit in the vmstat output.
>>>
>>> -- Ian
>> No, but it's in the same general range -- around 500k although it does
>> flop around some, and occasionally by a lot (e.g. if I sit and watch it
>> it'll occasionally put up VERY different numbers -- e.g. a ~730k number,
>> then it goes back, etc.)
>>
>> I don't generally build custom kernels on these but I CAN put this into
>> the STABLE tree I'm building that from since I keep a separate one for
>> Crochet builds on these boxes.  Where do I find that specific delta?  (I
>> usually just svn things and I don't want to roll it all the way back to
>> there, right -- or do I?)
>>
> Apply this patch...
>
> https://svnweb.freebsd.org/base/head/sys/kern/kern_intr.c?view=patch&r1=345475&r2=345474&pathrev=345475
>
> -- Ian
Here's where it's coming from:

root@rpi2:~ # vmstat -i
interrupt                                             total       rate
local_intc0,1:-mer0                                   80944       1361
local_intc0,3:-mer0                                32210287     541604
local_intc0,8:-ntc0                                  888341      14937
local_intc0,9: pmu0                                       2          0
intc0,1: mbox0                                           40          1
intc0,2: vchiq0                                           2          0
intc0,17:-x_dwcotg0                                 1242279      20888
intc0,28: bcm_dma0                                    74686       1256
intc0,61: iichb0                                          1          0
intc0,65: uart0                                        1856         31
intc0,70:-dhci_bcm0                                    8952        151
cpu0:rendezvous                                          13          0
cpu1:rendezvous                                          14          0
cpu2:rendezvous                                          15          0
cpu3:rendezvous                                          18          0
cpu2:ast                                                  1          0
cpu0:preempt                                           3167         53
cpu1:preempt                                          13062        220
cpu2:preempt                                          11133        187
cpu0:hardclock                                            2          0
Total                                              34534815     580690

Uh, yeah.  Cold boot, NO I2c connected.

FreeBSD 12.0-STABLE #0 r345490M: Mon Mar 25 14:05:47 CDT 2019    
[hidden email]:/work/Crochet-work-ARM32/obj/work/CrossBuild-12STABLE/src/arm.armv7/sys/GENERIC

(plus the patch of course)

No .kos loaded either

root@rpi2:~ # kldstat
Id Refs Address        Size Name
 1    1 0xc0000000   ca53e4 kernel

And the load average of 1.0 + real is there:

root@rpi2:~ # uptime
 7:15PM  up 4 mins, 1 user, load averages: 1.04, 0.75, 0.35

--
Karl Denninger
[hidden email] <mailto:[hidden email]>
/The Market Ticker/
/[S/MIME encrypted email preferred]/

smime.p7s (6K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Options for FBSD support with LCD device - new project [[Maybe related: I2c issues on the Pi2]]

Ian Lepore-3
On Mon, 2019-03-25 at 14:25 -0500, Karl Denninger wrote:
> On 3/25/2019 12:37, Ian Lepore wrote:
> > > >
> > > [...]
> >
> > Apply this patch...
> >
> >
https://svnweb.freebsd.org/base/head/sys/kern/kern_intr.c?view=patch&r1=345475&r2=345474&pathrev=345475

> >
> > -- Ian
>
> Here's where it's coming from:
>
> root@rpi2:~ # vmstat -i
> interrupt                                             total       rate
> local_intc0,1:-mer0                                   80944       1361
> local_intc0,3:-mer0                                32210287     541604
> local_intc0,8:-ntc0                                  888341      14937
> local_intc0,9: pmu0                                       2          0
> intc0,1: mbox0                                           40          1
> intc0,2: vchiq0                                           2          0
> intc0,17:-x_dwcotg0                                 1242279      20888
> intc0,28: bcm_dma0                                    74686       1256
> intc0,61: iichb0                                          1          0
> intc0,65: uart0                                        1856         31
> intc0,70:-dhci_bcm0                                    8952        151
> cpu0:rendezvous                                          13          0
> cpu1:rendezvous                                          14          0
> cpu2:rendezvous                                          15          0
> cpu3:rendezvous                                          18          0
> cpu2:ast                                                  1          0
> cpu0:preempt                                           3167         53
> cpu1:preempt                                          13062        220
> cpu2:preempt                                          11133        187
> cpu0:hardclock                                            2          0
> Total                                              34534815     580690
>
>

We really need to change the name of the local_intc controller to
something shorter.  I'm going to venture a guess that -mer0 is
'timer0'.  That leads to the question of whether the driver is broken
somehow, or whether some callout is being scheduled for a crazy-high
rate.

-- Ian

_______________________________________________
[hidden email] mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-arm
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: insanely-high interrupt rates

Ian Lepore-3
In reply to this post by Karl Denninger
On Mon, 2019-03-25 at 12:16 -0500, Karl Denninger wrote:

> On 3/25/2019 12:05, Ian Lepore wrote:
> > On Mon, 2019-03-25 at 11:58 -0500, Karl Denninger wrote:
> > > On 3/25/2019 11:48, Bernd Walter wrote:
> > > > On Mon, Mar 25, 2019 at 11:33:32AM -0500, Karl Denninger wrote:
> > > > > > [insanely high interrupt rates]
> > Is the interrupt rate consistent from second to second?  Running
> > 'vmstat 1' for a while might be useful to see that.  That many
> > interrupts almost sounds like a line is floating, but if that were
> > the
> > case I'd expect a widely varying number of int/sec.
> >
> > If you build custom kernels, it might be helpful to apply r345475
> > locally... it will display partial device names instead of just '+'
> > when the name doesn't fit in the vmstat output.
> >
> > -- Ian
>
> No, but it's in the same general range -- around 500k although it does
> flop around some, and occasionally by a lot (e.g. if I sit and watch it
> it'll occasionally put up VERY different numbers -- e.g. a ~730k number,
> then it goes back, etc.)
>
> I don't generally build custom kernels on these but I CAN put this into
> the STABLE tree I'm building that from since I keep a separate one for
> Crochet builds on these boxes.  Where do I find that specific delta?  (I
> usually just svn things and I don't want to roll it all the way back to
> there, right -- or do I?)
>

I now have an rpi2b, and I see the same thing you do in the 'vmstat -i'
output, including rates like 500K int/sec on cpu3 timer0.  But while it
was behaving like that, the output from 'vmstat 1' showed a perfectly
steady 8800-9200 int/sec, which is certainly more consistent with top
showing under 2% being used for combined system+interrupt.

I think the problem here is with vmstat -i, not with actual interrupts.
Something about the stats reporting is wrong on armv6/v7.

Note that this is completely separate from the spurious interrupt
problem, which I still haven't been able to reproduce.

-- Ian

_______________________________________________
[hidden email] mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-arm
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: insanely-high interrupt rates

Andrew Gierth
>>>>> "Ian" == Ian Lepore <[hidden email]> writes:

 Ian> I now have an rpi2b, and I see the same thing you do in the
 Ian> 'vmstat -i' output, including rates like 500K int/sec on cpu3
 Ian> timer0. But while it was behaving like that, the output from
 Ian> 'vmstat 1' showed a perfectly steady 8800-9200 int/sec, which is
 Ian> certainly more consistent with top showing under 2% being used for
 Ian> combined system+interrupt.

I'm seeing this too right now. The problem is that whatever this problem
is, it's not being accounted for in the %cpu statistics, probably
because it takes one CPU completely out of play.

So here's what I see. First, top:

last pid:  6110;  load averages:  1.00,  1.00,  1.00        up 1+19:26:47  08:35:02
107 threads:   6 running, 81 sleeping, 20 waiting
CPU:  0.3% user,  0.0% nice,  0.7% system,  0.2% interrupt, 98.8% idle
Mem: 10M Active, 611M Inact, 32M Laundry, 168M Wired, 98M Buf, 115M Free
Swap: 4096M Total, 4096M Free

  PID USERNAME    PRI NICE   SIZE    RES STATE    C   TIME     CPU COMMAND
   10 root        155 ki31      0    32K CPU2     2  43.3H  99.35% idle{idle: cpu2}
   10 root        155 ki31      0    32K RUN      1  43.3H  98.71% idle{idle: cpu1}
   10 root        155 ki31      0    32K CPU0     0  43.1H  98.49% idle{idle: cpu0}
 1186 andrew       20    0    14M  8728K select   1   0:01   0.90% xterm

Notice the load average of 1+, and that while it's reporting 98.8% idle,
only three of the four cpu idle processes show up. The fourth idle
process shows no accumulated CPU time, as shown here by ps axlH:

   0   10    0   0 155  0     0    32 -        RNL   -  2589:43.57 [idle/idle: cpu0]
   0   10    0   0 155  0     0    32 -        RNL   -  2597:14.64 [idle/idle: cpu1]
   0   10    0   0 155  0     0    32 -        RNL   -  2597:19.11 [idle/idle: cpu2]
   0   10    0   0 155  0     0    32 -        RNL   -     0:00.00 [idle/idle: cpu3]

The CPU time spent handling these interrupts is not being accounted for
anywhere.

Also, to confirm that there is something odd going on, the CPU is
running hotter than it would normally do while idle: ~42C rather than
the ~38C that I would normally see with this level of activity.

 Ian> I think the problem here is with vmstat -i, not with actual
 Ian> interrupts. Something about the stats reporting is wrong on
 Ian> armv6/v7.

There are two obvious issues with vmstat -i: it double- or triple-counts
some interrupts, and it reports a false rate once the counters wrap
(which happens quite quickly when this issue is in play). But these
don't account for the problem described here.

Here's lines from vmstat -i taken 10 seconds apart:

local_intc0,3: +                                 3085878928      19685

local_intc0,3: +                                 3094431425      19738

That's 8552497 interrupts in 10 seconds, which matches systat -vm's
report of ~850k interrupts/sec. Since these are 32-bit counters they
will wrap in an hour and a half at that rate, so the ~19700/sec rate
reported is entirely spurious (since it's just counter/uptime).

Looking at the generic_timer driver, there's an obvious problem: it
installs one interrupt handler on all the irqs and supposedly enables
only one of the timers, but the interrupt handler code simply assumes
that the timer causing the interrupt is the one that it enabled; if it
gets an interrupt from one of the others, it'll never clear it or mask
it, it'll just return with the interrupt unhandled, hence the interrupt
storm. On 32-bit arm it is only supposed to enable the timer that's
attached to local_intc0,1 and this indeed shows an interrupt rate of
~1100/sec which seems about right for the clock interrupt; the timer on
local_intc0,3 (the virtual one) is never supposed to be enabled so far
as I can tell.

--
Andrew.
_______________________________________________
[hidden email] mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-arm
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: insanely-high interrupt rates

Rodney W. Grimes-6
In reply to this post by Ian Lepore-3
> On Mon, 2019-03-25 at 12:16 -0500, Karl Denninger wrote:
> > On 3/25/2019 12:05, Ian Lepore wrote:
> > > On Mon, 2019-03-25 at 11:58 -0500, Karl Denninger wrote:
> > > > On 3/25/2019 11:48, Bernd Walter wrote:
> > > > > On Mon, Mar 25, 2019 at 11:33:32AM -0500, Karl Denninger wrote:
> > > > > > > [insanely high interrupt rates]
> > > Is the interrupt rate consistent from second to second?  Running
> > > 'vmstat 1' for a while might be useful to see that.  That many
> > > interrupts almost sounds like a line is floating, but if that were
> > > the
> > > case I'd expect a widely varying number of int/sec.
> > >
> > > If you build custom kernels, it might be helpful to apply r345475
> > > locally... it will display partial device names instead of just '+'
> > > when the name doesn't fit in the vmstat output.
> > >
> > > -- Ian
> >
> > No, but it's in the same general range -- around 500k although it does
> > flop around some, and occasionally by a lot (e.g. if I sit and watch it
> > it'll occasionally put up VERY different numbers -- e.g. a ~730k number,
> > then it goes back, etc.)
> >
> > I don't generally build custom kernels on these but I CAN put this into
> > the STABLE tree I'm building that from since I keep a separate one for
> > Crochet builds on these boxes.  Where do I find that specific delta?  (I
> > usually just svn things and I don't want to roll it all the way back to
> > there, right -- or do I?)
> >
>
> I now have an rpi2b, and I see the same thing you do in the 'vmstat -i'
> output, including rates like 500K int/sec on cpu3 timer0.  But while it
> was behaving like that, the output from 'vmstat 1' showed a perfectly
> steady 8800-9200 int/sec, which is certainly more consistent with top
> showing under 2% being used for combined system+interrupt.
>
> I think the problem here is with vmstat -i, not with actual interrupts.
> Something about the stats reporting is wrong on armv6/v7.
>
> Note that this is completely separate from the spurious interrupt
> problem, which I still haven't been able to reproduce.

I do not know if this data is of any relavance but when I was
trying to get a Samsung chrome book snow working:
https://wiki.freebsd.org/FreeBSD/arm/Chromebook

I had tons of problems with spurious interrupts if I tried
to use the internal keyboard.  I found that if I plugged
a USB keyboard in and never touched the built in keyboard
I could infact get booted to multiuser and use the system
somewhat.

This testing was done on head before the stable/12 branch,
I can re-aquire the hardware if there is anyone interested
in helping to debug this platform.

> -- Ian
--
Rod Grimes                                                 [hidden email]
_______________________________________________
[hidden email] mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-arm
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: insanely-high interrupt rates

Andrew Gierth
In reply to this post by Ian Lepore-3
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.

--
Andrew.


diff --git a/sys/arm/arm/generic_timer.c b/sys/arm/arm/generic_timer.c
index df8fca4674c1..08f00608fb67 100644
--- a/sys/arm/arm/generic_timer.c
+++ b/sys/arm/arm/generic_timer.c
@@ -450,6 +450,8 @@ arm_tmr_attach(device_t dev)
  /* If we do not have the interrupt, skip it. */
  if (sc->res[i] == NULL)
  continue;
+ if (sc->physical && i >= 2)
+ continue;
  error = bus_setup_intr(dev, sc->res[i], INTR_TYPE_CLK,
     arm_tmr_intr, NULL, sc, &sc->ihl[i]);
  if (error) {

_______________________________________________
[hidden email] mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-arm
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: insanely-high interrupt rates

Karl Denninger
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?
--
Karl Denninger
[hidden email] <mailto:[hidden email]>
/The Market Ticker/
/[S/MIME encrypted email preferred]/

smime.p7s (6K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: insanely-high interrupt rates

Ian Lepore-3
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

_______________________________________________
[hidden email] mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-arm
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

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

Karl Denninger
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
   
[hidden email]:/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@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
[hidden email] <mailto:[hidden email]>
/The Market Ticker/
/[S/MIME encrypted email preferred]/

smime.p7s (6K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

I2c producing crazy console messages [[Re: insanely-high interrupt rates -- PARTIAL resolution (Pi2)]]

Karl Denninger
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
>    
> [hidden email]:/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@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
[hidden email] <mailto:[hidden email]>
/The Market Ticker/
/[S/MIME encrypted email preferred]/

smime.p7s (6K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: I2c producing crazy console messages [[Re: insanely-high interrupt rates -- PARTIAL resolution (Pi2)]]

Ian Lepore-3
On Thu, 2019-04-18 at 16:51 -0500, Karl Denninger wrote:
> I2CRSTCARD

Why are you resetting the bus after every transaction?  There's no need
to do that.  Does removing that make the spurious interrupts go away?

-- Ian

_______________________________________________
[hidden email] mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-arm
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: I2c producing crazy console messages [[Re: insanely-high interrupt rates -- PARTIAL resolution (Pi2)]]

Karl Denninger
In reply to this post by Karl Denninger





- Karl (on PDA)



          Original Message  



From: [hidden email]
Sent: April 18, 2019 17:20
To: [hidden email]; [hidden email]
Subject: Re: I2c producing crazy console messages [[Re: insanely-high interrupt rates -- PARTIAL resolution (Pi2)]]


On Thu, 2019-04-18 at 16:51 -0500, Karl Denninger wrote:
> I2CRSTCARD

Why are you resetting the bus after every transaction?  There's no need
to do that.  Does removing that make the spurious interrupts go away?

-- Ian




No I added it in an attempt to stop them original code did not have that.

smime.p7s (6K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: I2c producing crazy console messages [[Re: insanely-high interrupt rates -- PARTIAL resolution (Pi2)]]

Ian Lepore-3
In reply to this post by Karl Denninger
On Thu, 2019-04-18 at 16:51 -0500, Karl Denninger wrote:

> 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

BTW, a spurious interrupt is not an unhandled interrupt.  What it means
is that some device signalled an interrupt, then by time the interrupt
dispatching code runs, the interrupt controller says "there are no
interrupts pending".  That means that whatever condition signalled the
interrupt went away by itself before software could see what it is, and
that is sometimes a sign of trouble, but is usually harmless.

Usually there are two things that can lead to a spurious interrupt:

 - A device driver writes to a device register to cause the condition
signalling the interrupt to be cleared, then returns from the driver
interrupt handler to the interrupt dispatcher code.  The dispatcher
does EOI processing which includes unmasking the interrupt at the
interrupt controller.  If the i2c device and the interrupt controller
device are on separate busses that run at unequal speeds, it can happen
that the write to unmask the interrupt arrives at the controller before
the write to clear the interrupt-signalling condition at the i2c
device.  So, as soon as the interrupt is unmasked, a fresh IRQ is
signalled to the arm processor.  But before the arm gets around to
dispatching it, the write finally arrives at the i2c hardware, clears
the condition, and the interrupt goes away.  Then we complain that the
interrupt was spurious.

 - An interrupt is configured as shared, so it gets dispatched to
multiple cores at once, and each of those cores asks the interrupt
controller "what interrupts are pending right now?"  One core gets a
good answer "the i2c device" and the other core(s) get told "there is
no pending interrupt" (because it just got delivered to some other
core).  So we complain that it was spurious.  This situation is normal
and expected and it's why we don't complain about spurious interrupts
anymore in any multicore chip except RPi.  We need to stop complaining
on rpi as well.  But it does seem a bit strange to me that you never
saw them until 12.0, so I would like to understand the situation better
before just removing the message.  (Actually, it won't get removed, but
it will be off by default with a tunable/sysctl to enable it.)

-- Ian


_______________________________________________
[hidden email] mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-arm
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: I2c producing crazy console messages [[Re: insanely-high interrupt rates -- PARTIAL resolution (Pi2)]]

Ian Lepore-3
In reply to this post by Karl Denninger
On Thu, 2019-04-18 at 16:51 -0500, Karl Denninger wrote:

> 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.

Hmm, another interesting question occurred to me:  Can you tell whether
you are getting multiple spurious interrupt messages per single
transfer your code does, or is it one per transfer, or more
intermittent, like not on every transfer?

-- Ian

_______________________________________________
[hidden email] mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-arm
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: I2c producing crazy console messages [[Re: insanely-high interrupt rates -- PARTIAL resolution (Pi2)]]

Karl Denninger

On 4/18/2019 17:57, Ian Lepore wrote:

> On Thu, 2019-04-18 at 16:51 -0500, Karl Denninger wrote:
>> 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.
> Hmm, another interesting question occurred to me:  Can you tell whether
> you are getting multiple spurious interrupt messages per single
> transfer your code does, or is it one per transfer, or more
> intermittent, like not on every transfer?
>
> -- Ian
It logs the message on "many" accesses, but not all.

The code scans each of the declared analogs once per second.  There are
two inputs defined on this unit right now, so if it was on every access
there would be two messages per second logged, and there isn't; nor is
it "one per cluster" of accesses.  I removed the reset and restarted the
code and this is the frequency of log entries I'm getting, which implies
frequent and random, but much less than 1:1.

Apr 18 20:22:25 Pool-MCP kernel: intc0: Spurious interrupt detected
Apr 18 20:22:26 Pool-MCP kernel: local_intc0: Spurious interrupt detected
Apr 18 20:22:27 Pool-MCP kernel: intc0: Spurious interrupt detected
Apr 18 20:22:33 Pool-MCP kernel: local_intc0: Spurious interrupt detected
Apr 18 20:22:36 Pool-MCP kernel: intc0: Spurious interrupt detected
Apr 18 20:22:38 Pool-MCP kernel: local_intc0: Spurious interrupt detected
Apr 18 20:22:39 Pool-MCP kernel: intc0: Spurious interrupt detected
Apr 18 20:22:40 Pool-MCP syslogd: last message repeated 1 times
Apr 18 20:22:40 Pool-MCP kernel: local_intc0: Spurious interrupt detected
Apr 18 20:22:42 Pool-MCP kernel: intc0: Spurious interrupt detected
Apr 18 20:22:49 Pool-MCP kernel: local_intc0: Spurious interrupt detected
Apr 18 20:22:52 Pool-MCP kernel: intc0: Spurious interrupt detected
Apr 18 20:22:53 Pool-MCP kernel: local_intc0: Spurious interrupt detected

--
Karl Denninger
[hidden email] <mailto:[hidden email]>
/The Market Ticker/
/[S/MIME encrypted email preferred]/

smime.p7s (6K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: I2c producing crazy console messages [[Re: insanely-high interrupt rates -- PARTIAL resolution (Pi2)]]

Per Hedeland
On 2019-04-19 03:25, Karl Denninger wrote:

>
> On 4/18/2019 17:57, Ian Lepore wrote:
>> On Thu, 2019-04-18 at 16:51 -0500, Karl Denninger wrote:
>>> 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.
>> Hmm, another interesting question occurred to me:  Can you tell whether
>> you are getting multiple spurious interrupt messages per single
>> transfer your code does, or is it one per transfer, or more
>> intermittent, like not on every transfer?
>>
>> -- Ian
>
> It logs the message on "many" accesses, but not all.
>
> The code scans each of the declared analogs once per second.  There are
> two inputs defined on this unit right now, so if it was on every access
> there would be two messages per second logged, and there isn't; nor is
> it "one per cluster" of accesses.  I removed the reset and restarted the
> code and this is the frequency of log entries I'm getting, which implies
> frequent and random, but much less than 1:1.
>
> Apr 18 20:22:25 Pool-MCP kernel: intc0: Spurious interrupt detected
> Apr 18 20:22:26 Pool-MCP kernel: local_intc0: Spurious interrupt detected
> Apr 18 20:22:27 Pool-MCP kernel: intc0: Spurious interrupt detected
> Apr 18 20:22:33 Pool-MCP kernel: local_intc0: Spurious interrupt detected
> Apr 18 20:22:36 Pool-MCP kernel: intc0: Spurious interrupt detected
> Apr 18 20:22:38 Pool-MCP kernel: local_intc0: Spurious interrupt detected
> Apr 18 20:22:39 Pool-MCP kernel: intc0: Spurious interrupt detected
> Apr 18 20:22:40 Pool-MCP syslogd: last message repeated 1 times
> Apr 18 20:22:40 Pool-MCP kernel: local_intc0: Spurious interrupt detected
> Apr 18 20:22:42 Pool-MCP kernel: intc0: Spurious interrupt detected
> Apr 18 20:22:49 Pool-MCP kernel: local_intc0: Spurious interrupt detected
> Apr 18 20:22:52 Pool-MCP kernel: intc0: Spurious interrupt detected
> Apr 18 20:22:53 Pool-MCP kernel: local_intc0: Spurious interrupt detected

Hm, I've recently gotten an i2c device to work on RPi - FWIW it's an
ads1015 AD-converter, my code is pretty similar to yours - you may
actually be using the same device - and I don't see *any* "Spurious
interrupt" messages when using it. But a) I've only run it on RPi Zero
(currently connected) and RPi 1B (briefly when testing), and b) I
don't have a console connected (but I assume the messages should also
show up in dmesg and /var/log/messages, the above seems to be from the
log).

But anyway I would be *extremely* surprised if I saw them, since AFAIU
the i2c bus per se has no concept of interrupts - you need to connect
some other wire from the device to e.g. a gpio pin (with appropriate
config) in order to generate interrupts - and I haven't done that. (The
ads1015 does have an ALERT/RDY pin that could potentially be used for
it, but since FreeBSD AFAIK doesn't have a way to deliver the
interrupts to userland code, I had no interest in it.)

So, your code like mine doesn't seem to use interrupts at all - do you
nevertheless have some interrupt-generating connection from the
device? And if these interrupts really happen only on RPi 2 and not on
any of 0/1/3, I guess it makes sense to look at the dts/dtb files.
Diffing bcm2708-rpi-0-w.dts and bcm2709-rpi-2-b.dts, I see this:

                 interrupt-controller@7e00b200 {

-                       compatible = "brcm,bcm2835-armctrl-ic";
+                       compatible = "brcm,bcm2836-armctrl-ic";
                         reg = <0x7e00b200 0x200>;
                         interrupt-controller;
                         #interrupt-cells = <0x2>;
+                       interrupt-parent = <0x3>;
+                       interrupts = <0x8>;
                         phandle = <0x1>;
                 };

and this:

+               local_intc@40000000 {
+
+                       compatible = "brcm,bcm2836-l1-intc";
+                       reg = <0x40000000 0x100>;
+                       interrupt-controller;
+                       #interrupt-cells = <0x1>;
+                       interrupt-parent = <0x3>;
+                       phandle = <0x3>;
+               };

I have (as yet) no idea what it actually means, but it clearly seems
to be interrupt-related... There are a few more "interrupt-related"
diffs, but those two kind of "stand out" for me. Btw, shouldn't these
.dts files exist somewhere under /usr/src/sys/gnu/dts/arm? I
decompiled them from the .dtb's in installed images to be able to
compare...

--Per Hedeland
_______________________________________________
[hidden email] mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-arm
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: I2c producing crazy console messages [[Re: insanely-high interrupt rates -- PARTIAL resolution (Pi2)]]

Karl Denninger
On 4/19/2019 06:32, Per Hedeland wrote:

> On 2019-04-19 03:25, Karl Denninger wrote:
>>
>> On 4/18/2019 17:57, Ian Lepore wrote:
>>> On Thu, 2019-04-18 at 16:51 -0500, Karl Denninger wrote:
>>>> 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.
>>> Hmm, another interesting question occurred to me:  Can you tell whether
>>> you are getting multiple spurious interrupt messages per single
>>> transfer your code does, or is it one per transfer, or more
>>> intermittent, like not on every transfer?
>>>
>>> -- Ian
>>
>> It logs the message on "many" accesses, but not all.
>>
>> The code scans each of the declared analogs once per second.  There are
>> two inputs defined on this unit right now, so if it was on every access
>> there would be two messages per second logged, and there isn't; nor is
>> it "one per cluster" of accesses.  I removed the reset and restarted the
>> code and this is the frequency of log entries I'm getting, which implies
>> frequent and random, but much less than 1:1.
>>
>> Apr 18 20:22:25 Pool-MCP kernel: intc0: Spurious interrupt detected
>> Apr 18 20:22:26 Pool-MCP kernel: local_intc0: Spurious interrupt
>> detected
>> Apr 18 20:22:27 Pool-MCP kernel: intc0: Spurious interrupt detected
>> Apr 18 20:22:33 Pool-MCP kernel: local_intc0: Spurious interrupt
>> detected
>> Apr 18 20:22:36 Pool-MCP kernel: intc0: Spurious interrupt detected
>> Apr 18 20:22:38 Pool-MCP kernel: local_intc0: Spurious interrupt
>> detected
>> Apr 18 20:22:39 Pool-MCP kernel: intc0: Spurious interrupt detected
>> Apr 18 20:22:40 Pool-MCP syslogd: last message repeated 1 times
>> Apr 18 20:22:40 Pool-MCP kernel: local_intc0: Spurious interrupt
>> detected
>> Apr 18 20:22:42 Pool-MCP kernel: intc0: Spurious interrupt detected
>> Apr 18 20:22:49 Pool-MCP kernel: local_intc0: Spurious interrupt
>> detected
>> Apr 18 20:22:52 Pool-MCP kernel: intc0: Spurious interrupt detected
>> Apr 18 20:22:53 Pool-MCP kernel: local_intc0: Spurious interrupt
>> detected
>
> Hm, I've recently gotten an i2c device to work on RPi - FWIW it's an
> ads1015 AD-converter, my code is pretty similar to yours - you may
> actually be using the same device - and I don't see *any* "Spurious
> interrupt" messages when using it. But a) I've only run it on RPi Zero
> (currently connected) and RPi 1B (briefly when testing), and b) I
> don't have a console connected (but I assume the messages should also
> show up in dmesg and /var/log/messages, the above seems to be from the
> log).
>
> But anyway I would be *extremely* surprised if I saw them, since AFAIU
> the i2c bus per se has no concept of interrupts - you need to connect
> some other wire from the device to e.g. a gpio pin (with appropriate
> config) in order to generate interrupts - and I haven't done that. (The
> ads1015 does have an ALERT/RDY pin that could potentially be used for
> it, but since FreeBSD AFAIK doesn't have a way to deliver the
> interrupts to userland code, I had no interest in it.)
Correct.  Indeed these are ADS1015s -- the code also supports ads1115s. 
The delay for conversion is different, thus the multiplier (you set a
different constant in the config file) plus, of course, the shift
required for 12-bit alignment into a 16-bit result.

>
> So, your code like mine doesn't seem to use interrupts at all - do you
> nevertheless have some interrupt-generating connection from the
> device?

No.  Thus the delay for conversion via usleep within my code since
there's no way for a device on the I2c bus itself (at least as far as I
know) to alert that the conversion is complete.  While theoretically I
could use the Alert/RDY pin I do not at present.

The spurious interrupt message is coming from
sys/arm/broadcom/bcm2835/bcm2835_intr.c -- which is, of course, not
present in a RPI3 build since that's aarch64 (the "arm64" branch of the
sys tree) and not arm.

But the below is indeed interesting....

> And if these interrupts really happen only on RPi 2 and not on
> any of 0/1/3, I guess it makes sense to look at the dts/dtb files.
> Diffing bcm2708-rpi-0-w.dts and bcm2709-rpi-2-b.dts, I see this:
>
>                 interrupt-controller@7e00b200 {
>
> -                       compatible = "brcm,bcm2835-armctrl-ic";
> +                       compatible = "brcm,bcm2836-armctrl-ic";
>                         reg = <0x7e00b200 0x200>;
>                         interrupt-controller;
>                         #interrupt-cells = <0x2>;
> +                       interrupt-parent = <0x3>;
> +                       interrupts = <0x8>;
>                         phandle = <0x1>;
>                 };
>
> and this:
>
> +               local_intc@40000000 {
> +
> +                       compatible = "brcm,bcm2836-l1-intc";
> +                       reg = <0x40000000 0x100>;
> +                       interrupt-controller;
> +                       #interrupt-cells = <0x1>;
> +                       interrupt-parent = <0x3>;
> +                       phandle = <0x3>;
> +               };
>
> I have (as yet) no idea what it actually means, but it clearly seems
> to be interrupt-related... There are a few more "interrupt-related"
> diffs, but those two kind of "stand out" for me. Btw, shouldn't these
> .dts files exist somewhere under /usr/src/sys/gnu/dts/arm? I
> decompiled them from the .dtb's in installed images to be able to
> compare...
>
> --Per Hedeland
The "newer build environment" has both rpi-firmware and u-boot running
off packages/ports, which are nominally in /usr/local/share; in this
case /usr/local/share/rpi-firmware.  The dtb files are there, but not
the source dts files.  FreeBSD picks up the binary dtb files; it does
not compile the .dts files at build time.

root@NewFS:/usr/local/share/rpi-firmware # ls -al
total 9427
drwxr-xr-x    3 root  wheel       26 Feb 10 12:08 .
drwxr-xr-x  112 root  wheel      113 Mar  4 11:31 ..
-rw-r--r--    1 root  wheel    18693 Nov 12 10:05 COPYING.linux
-rw-r--r--    1 root  wheel     1494 Nov 12 10:05 LICENCE.broadcom
-rw-r--r--    1 root  wheel     5888 Feb  8 11:55 armstub8.bin
-rw-r--r--    1 root  wheel    23315 Nov 12 10:05 bcm2708-rpi-0-w.dtb
-rw-r--r--    1 root  wheel    23071 Nov 12 10:05 bcm2708-rpi-b-plus.dtb
-rw-r--r--    1 root  wheel    22812 Nov 12 10:05 bcm2708-rpi-b.dtb
-rw-r--r--    1 root  wheel    22589 Nov 12 10:05 bcm2708-rpi-cm.dtb
-rw-r--r--    1 root  wheel    24115 Nov 12 10:05 bcm2709-rpi-2-b.dtb
-rw-r--r--    1 root  wheel    25574 Nov 12 10:05 bcm2710-rpi-3-b-plus.dtb
-rw-r--r--    1 root  wheel    25311 Nov 12 10:05 bcm2710-rpi-3-b.dtb
-rw-r--r--    1 root  wheel    24087 Nov 12 10:05 bcm2710-rpi-cm3.dtb
-rw-r--r--    1 root  wheel    52116 Nov 12 10:05 bootcode.bin
-rw-r--r--    1 root  wheel       89 Feb  8 11:55 config.txt
-rw-r--r--    1 root  wheel      151 Feb  8 11:55 config_rpi3.txt
-rw-r--r--    1 root  wheel      114 Feb  8 11:55 config_rpi_0_w.txt
-rw-r--r--    1 root  wheel     6666 Nov 12 10:05 fixup.dat
-rw-r--r--    1 root  wheel     2621 Nov 12 10:05 fixup_cd.dat
-rw-r--r--    1 root  wheel     9895 Nov 12 10:05 fixup_db.dat
-rw-r--r--    1 root  wheel     9895 Nov 12 10:05 fixup_x.dat
drwxr-xr-x    2 root  wheel      151 Feb 10 12:08 overlays
-rw-r--r--    1 root  wheel  2857060 Nov 12 10:05 start.elf
-rw-r--r--    1 root  wheel   678532 Nov 12 10:05 start_cd.elf
-rw-r--r--    1 root  wheel  5120484 Nov 12 10:05 start_db.elf
-rw-r--r--    1 root  wheel  4057956 Nov 12 10:05 start_x.elf

root@NewFS:/usr/local/share/rpi-firmware # pkg info |grep rpi
rpi-firmware-1.20181112        Firmware for RaspberryPi Single Board
Computer
u-boot-rpi2-2019.01            Cross-build das u-boot for model rpi2
u-boot-rpi3-2019.01            Cross-build das u-boot for model rpi3

--
Karl Denninger
[hidden email] <mailto:[hidden email]>
/The Market Ticker/
/[S/MIME encrypted email preferred]/

smime.p7s (6K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: I2c producing crazy console messages [[Re: insanely-high interrupt rates -- PARTIAL resolution (Pi2)]]

Per Hedeland
On 2019-04-19 16:16, Karl Denninger wrote:

> On 4/19/2019 06:32, Per Hedeland wrote:
>> On 2019-04-19 03:25, Karl Denninger wrote:
>>>
>>> On 4/18/2019 17:57, Ian Lepore wrote:
>>>> On Thu, 2019-04-18 at 16:51 -0500, Karl Denninger wrote:
>>>>> 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.
>>>> Hmm, another interesting question occurred to me:  Can you tell whether
>>>> you are getting multiple spurious interrupt messages per single
>>>> transfer your code does, or is it one per transfer, or more
>>>> intermittent, like not on every transfer?
>>>>
>>>> -- Ian
>>>
>>> It logs the message on "many" accesses, but not all.
>>>
>>> The code scans each of the declared analogs once per second. There are
>>> two inputs defined on this unit right now, so if it was on every access
>>> there would be two messages per second logged, and there isn't; nor is
>>> it "one per cluster" of accesses.  I removed the reset and restarted the
>>> code and this is the frequency of log entries I'm getting, which implies
>>> frequent and random, but much less than 1:1.
>>>
>>> Apr 18 20:22:25 Pool-MCP kernel: intc0: Spurious interrupt detected
>>> Apr 18 20:22:26 Pool-MCP kernel: local_intc0: Spurious interrupt detected
>>> Apr 18 20:22:27 Pool-MCP kernel: intc0: Spurious interrupt detected
>>> Apr 18 20:22:33 Pool-MCP kernel: local_intc0: Spurious interrupt detected
>>> Apr 18 20:22:36 Pool-MCP kernel: intc0: Spurious interrupt detected
>>> Apr 18 20:22:38 Pool-MCP kernel: local_intc0: Spurious interrupt detected
>>> Apr 18 20:22:39 Pool-MCP kernel: intc0: Spurious interrupt detected
>>> Apr 18 20:22:40 Pool-MCP syslogd: last message repeated 1 times
>>> Apr 18 20:22:40 Pool-MCP kernel: local_intc0: Spurious interrupt detected
>>> Apr 18 20:22:42 Pool-MCP kernel: intc0: Spurious interrupt detected
>>> Apr 18 20:22:49 Pool-MCP kernel: local_intc0: Spurious interrupt detected
>>> Apr 18 20:22:52 Pool-MCP kernel: intc0: Spurious interrupt detected
>>> Apr 18 20:22:53 Pool-MCP kernel: local_intc0: Spurious interrupt detected
>>
>> Hm, I've recently gotten an i2c device to work on RPi - FWIW it's an
>> ads1015 AD-converter, my code is pretty similar to yours - you may
>> actually be using the same device - and I don't see *any* "Spurious
>> interrupt" messages when using it. But a) I've only run it on RPi Zero
>> (currently connected) and RPi 1B (briefly when testing), and b) I
>> don't have a console connected (but I assume the messages should also
>> show up in dmesg and /var/log/messages, the above seems to be from the
>> log).
>>
>> But anyway I would be *extremely* surprised if I saw them, since AFAIU
>> the i2c bus per se has no concept of interrupts - you need to connect
>> some other wire from the device to e.g. a gpio pin (with appropriate
>> config) in order to generate interrupts - and I haven't done that. (The
>> ads1015 does have an ALERT/RDY pin that could potentially be used for
>> it, but since FreeBSD AFAIK doesn't have a way to deliver the
>> interrupts to userland code, I had no interest in it.)
>
> Correct.  Indeed these are ADS1015s -- the code also supports ads1115s.  The delay for conversion is different, thus the multiplier (you set a different constant in the config file) plus, of course,
> the shift required for 12-bit alignment into a 16-bit result.
>
>>
>> So, your code like mine doesn't seem to use interrupts at all - do you
>> nevertheless have some interrupt-generating connection from the
>> device?
>
> No.  Thus the delay for conversion via usleep within my code since there's no way for a device on the I2c bus itself (at least as far as I know) to alert that the conversion is complete.  While
> theoretically I could use the Alert/RDY pin I do not at present.
>
> The spurious interrupt message is coming from sys/arm/broadcom/bcm2835/bcm2835_intr.c -- which is, of course, not present in a RPI3 build since that's aarch64 (the "arm64" branch of the sys tree) and
> not arm.

OK, but... - the interrupts "have to" be generated by some "electrical
change" *somewhere* - if you haven't connected anything else, that
would seem to leave only the actual SDA/SCL lines of the i2c bus
itself. Which would be "crazy", and everyone using any i2c device
would see them - at least on the RPi 2...

> But the below is indeed interesting....
>
>> And if these interrupts really happen only on RPi 2 and not on
>> any of 0/1/3, I guess it makes sense to look at the dts/dtb files.
>> Diffing bcm2708-rpi-0-w.dts and bcm2709-rpi-2-b.dts, I see this:
>>
>>                 interrupt-controller@7e00b200 {
>>
>> -                       compatible = "brcm,bcm2835-armctrl-ic";
>> +                       compatible = "brcm,bcm2836-armctrl-ic";
>>                         reg = <0x7e00b200 0x200>;
>>                         interrupt-controller;
>>                         #interrupt-cells = <0x2>;
>> +                       interrupt-parent = <0x3>;
>> +                       interrupts = <0x8>;
>>                         phandle = <0x1>;
>>                 };
>>
>> and this:
>>
>> +               local_intc@40000000 {
>> +
>> +                       compatible = "brcm,bcm2836-l1-intc";
>> +                       reg = <0x40000000 0x100>;
>> +                       interrupt-controller;
>> +                       #interrupt-cells = <0x1>;
>> +                       interrupt-parent = <0x3>;
>> +                       phandle = <0x3>;
>> +               };
>>
>> I have (as yet) no idea what it actually means, but it clearly seems
>> to be interrupt-related... There are a few more "interrupt-related"
>> diffs, but those two kind of "stand out" for me. Btw, shouldn't these
>> .dts files exist somewhere under /usr/src/sys/gnu/dts/arm? I
>> decompiled them from the .dtb's in installed images to be able to
>> compare...
>>
>> --Per Hedeland
>
> The "newer build environment" has both rpi-firmware and u-boot running off packages/ports, which are nominally in /usr/local/share; in this case /usr/local/share/rpi-firmware.  The dtb files are
> there, but not the source dts files.  FreeBSD picks up the binary dtb files; it does not compile the .dts files at build time.

Thanks, all clear now!

--Per

> root@NewFS:/usr/local/share/rpi-firmware # ls -al
> total 9427
> drwxr-xr-x    3 root  wheel       26 Feb 10 12:08 .
> drwxr-xr-x  112 root  wheel      113 Mar  4 11:31 ..
> -rw-r--r--    1 root  wheel    18693 Nov 12 10:05 COPYING.linux
> -rw-r--r--    1 root  wheel     1494 Nov 12 10:05 LICENCE.broadcom
> -rw-r--r--    1 root  wheel     5888 Feb  8 11:55 armstub8.bin
> -rw-r--r--    1 root  wheel    23315 Nov 12 10:05 bcm2708-rpi-0-w.dtb
> -rw-r--r--    1 root  wheel    23071 Nov 12 10:05 bcm2708-rpi-b-plus.dtb
> -rw-r--r--    1 root  wheel    22812 Nov 12 10:05 bcm2708-rpi-b.dtb
> -rw-r--r--    1 root  wheel    22589 Nov 12 10:05 bcm2708-rpi-cm.dtb
> -rw-r--r--    1 root  wheel    24115 Nov 12 10:05 bcm2709-rpi-2-b.dtb
> -rw-r--r--    1 root  wheel    25574 Nov 12 10:05 bcm2710-rpi-3-b-plus.dtb
> -rw-r--r--    1 root  wheel    25311 Nov 12 10:05 bcm2710-rpi-3-b.dtb
> -rw-r--r--    1 root  wheel    24087 Nov 12 10:05 bcm2710-rpi-cm3.dtb
> -rw-r--r--    1 root  wheel    52116 Nov 12 10:05 bootcode.bin
> -rw-r--r--    1 root  wheel       89 Feb  8 11:55 config.txt
> -rw-r--r--    1 root  wheel      151 Feb  8 11:55 config_rpi3.txt
> -rw-r--r--    1 root  wheel      114 Feb  8 11:55 config_rpi_0_w.txt
> -rw-r--r--    1 root  wheel     6666 Nov 12 10:05 fixup.dat
> -rw-r--r--    1 root  wheel     2621 Nov 12 10:05 fixup_cd.dat
> -rw-r--r--    1 root  wheel     9895 Nov 12 10:05 fixup_db.dat
> -rw-r--r--    1 root  wheel     9895 Nov 12 10:05 fixup_x.dat
> drwxr-xr-x    2 root  wheel      151 Feb 10 12:08 overlays
> -rw-r--r--    1 root  wheel  2857060 Nov 12 10:05 start.elf
> -rw-r--r--    1 root  wheel   678532 Nov 12 10:05 start_cd.elf
> -rw-r--r--    1 root  wheel  5120484 Nov 12 10:05 start_db.elf
> -rw-r--r--    1 root  wheel  4057956 Nov 12 10:05 start_x.elf
>
> root@NewFS:/usr/local/share/rpi-firmware # pkg info |grep rpi
> rpi-firmware-1.20181112        Firmware for RaspberryPi Single Board Computer
> u-boot-rpi2-2019.01            Cross-build das u-boot for model rpi2
> u-boot-rpi3-2019.01            Cross-build das u-boot for model rpi3
>
> --
> Karl Denninger
> [hidden email] <mailto:[hidden email]>
> /The Market Ticker/
> /[S/MIME encrypted email preferred]/

_______________________________________________
[hidden email] mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-arm
To unsubscribe, send any mail to "[hidden email]"
1234