Unhandled exception in interrupt handler

[danielm]

I am prototyping 3-channel pulse counter based on LoPy. External opto-isolators are connected to P13, P14 and P15 with pull-ups to 3.3V. Counting is based on interrupts.
I am feeding approx. 3Hz test signal to P13 and approx. 2Hz signal to P14 and P15 (through opto-isolators of course).
It seems to work after start of the code but after some time it starts to throw unhandled exception in interrupt handler or crashes with Guru Meditation Error.

The time after it starts to misbehave seems to depend on unallocated/free memory. Tested with 1.6.7.b1 and 1.6.9.b1.

Full code output (1.6.7.b1):

[1970-01-01 00:06:40] INFO: Counter 1: 1125 Counter 2: 703 Counter 3: 702
bytearray(b'\x00\x02$\n\xc4\x00\x11\x0e$\n\xc4\x00\x8f\xbee\x04\x00\x00\xbf\x02\x00\x00\xbe\x02\x00\x00')
[1970-01-01 00:06:45] INFO: Counter 1: 1140 Counter 2: 714 Counter 3: 712
bytearray(b'\x00\x02$\n\xc4\x00\x11\x0e$\n\xc4\x00\x8f\xbet\x04\x00\x00\xca\x02\x00\x00\xc8\x02\x00\x00')
Unhandled exception in interrupt handler
TypeError: 'str' object is not callable
Unhandled exception in interrupt handler
TypeError: 'str' object is not callable

Full code output (1.6.9.b1):

[1970-01-01 00:07:45] INFO: Counter 1: 1494 Counter 2: 968 Counter 3: 956
bytearray(b'\x00\x02$\n\xc4\x00\x11\x0e$\n\xc4\x00\x8f\xbe\xd6\x05\x00\x00\xc8\x03\x00\x00\xbc\x03\x00\x00')
[1970-01-01 00:07:50] INFO: Counter 1: 1510 Counter 2: 979 Counter 3: 966
bytearray(b'\x00\x02$\n\xc4\x00\x11\x0e$\n\xc4\x00\x8f\xbe\xe6\x05\x00\x00\xd3\x03\x00\x00\xc6\x03\x00\x00')
Unhandled exception in interrupt handler
TypeError: '' object is not callable
Unhandled exception in interrupt handler
TypeError: '' object is not callable

Simplified code output (1.6.9.b1):

Counter 1: 10711 Counter 2: 6657 Counter 3: 6585
Counter 1: 10727 Counter 2: 6668 Counter 3: 6595
Counter 1: 10742 Counter 2: 6679 Counter 3: 6605
Counter 1: 10760 Counter 2: 6689 Counter 3: 6616
Counter 1: 10776 Counter 2: 6700 Counter 3: 6626
Counter 1: 10794 Counter 2: 6710 Counter 3: 6636
Counter 1: 10811 Counter 2: 6720 Counter 3: 6647
Counter 1: 10826 Counter 2: 6730 Counter 3: 6658
Guru Meditation Error of type InstrFetchProhibited occurred on core  0. Exception was unhandled.
Register dump:
PC      : 0x34006427  PS      : 0x00060a30  A0      : 0x800eb1d8  A1      : 0x3ffe1f00
A2      : 0x3ffe2880  A3      : 0x00000001  A4      : 0x00000000  A5      : 0x3ffe1f20
A6      : 0x00050a23  A7      : 0x00000000  A8      : 0x800eb194  A9      : 0x3ffe1ee0
A10     : 0x3ffe2880  A11     : 0x00000001  A12     : 0x00000000  A13     : 0x3ffe1f20
A14     : 0x00000003  A15     : 0x00060a23  SAR     : 0x00000012  EXCCAUSE: 0x00000014
EXCVADDR: 0x34006424  LBEG    : 0x400e3ce4  LEND    : 0x400e3d10  LCOUNT  : 0x00000f98

Backtrace: 0x34006427:0x3ffe1f00 0x400eb1d8:0x3ffe1f20 0x400dcc5c:0x3ffe1f50 0x400e159e:0x3ffe1f70 0x400d820c:0x3ffe2000

Counter 1: 10651 Counter 2: 6704 Counter 3: 6619
Counter 1: 10666 Counter 2: 6714 Counter 3: 6629
Counter 1: 10682 Counter 2: 6725 Counter 3: 6639
Counter 1: 10698 Counter 2: 6735 Counter 3: 6649
Counter 1: 10713 Counter 2: 6745 Counter 3: 6659
Guru Meditation Error of type IllegalInstruction occurred on core  0. Exception was unhandled.
Register dump:
PC      : 0x7e0069d0  PS      : 0x00050c30  A0      : 0x800eb1d8  A1      : 0x3ffe1f00
A2      : 0x3ffe2880  A3      : 0x00000001  A4      : 0x7e006398  A5      : 0x3ffe1f20
A6      : 0x400dcc4c  A7      : 0x3ffc11ec  A8      : 0x800eb194  A9      : 0x3ffe1ee0
A10     : 0x3ffe2880  A11     : 0x00000001  A12     : 0x00000000  A13     : 0x3ffe1f20
A14     : 0x000000a5  A15     : 0x3ffbc680  SAR     : 0x00000012  EXCCAUSE: 0x00000000
EXCVADDR: 0x00000000  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff

Backtrace: 0x7e0069d0:0x3ffe1f00 0x400eb1d8:0x3ffe1f20 0x400dcc5c:0x3ffe1f50 0x400e159e:0x3ffe1f70 0x400d820c:0x3ffe2000

Counter 1: 10578 Counter 2: 6699 Counter 3: 6587
Counter 1: 10594 Counter 2: 6711 Counter 3: 6597
Counter 1: 10609 Counter 2: 6721 Counter 3: 6607
Counter 1: 10626 Counter 2: 6731 Counter 3: 6617
Counter 1: 10642 Counter 2: 6742 Counter 3: 6627
Unhandled exception in interrupt handler
TypeError: 'str' object is not callable
Unhandled exception in interrupt handler
TypeError: 'str' object is not callable
Unhandled exception in interrupt handler
TypeError: 'str' object is not callable
Unhandled exception in interrupt handler
TypeError: 'str' object is not callable

Simplified code:

import time
import pycom
import machine
from machine import Pin

pycom.heartbeat(False)

class PulseCounter():
	def __init__(self):
		self.counter1pin = Pin('P13', mode=Pin.IN)
		self.counter2pin = Pin('P14', mode=Pin.IN)
		self.counter3pin = Pin('P15', mode=Pin.IN)
		self.counter1 = 0 
		self.counter2 = 0
		self.counter3 = 0
		self.lastReportTime = 0
		self.temporary1 = 0									
		self.temporary2 = 0		
		self.temporary3 = 0		

	def counter1irq(self, obj):
		self.temporary1 = self.counter1
		self.counter1 = self.temporary1 + 1

	def counter2irq(self, obj):
		self.temporary2 = self.counter2
		self.counter2 = self.temporary2 + 1

	def counter3irq(self, obj):
		self.temporary2 = self.counter3
		self.counter3 = self.temporary2 + 1

	def pulseCounterMode(self):
		self.counter1pin.callback(trigger = Pin.IRQ_RISING, handler=self.counter1irq, arg=None)
		self.counter2pin.callback(trigger = Pin.IRQ_RISING, handler=self.counter2irq, arg=None)
		self.counter3pin.callback(trigger = Pin.IRQ_RISING, handler=self.counter3irq, arg=None)

		while True:
			self.now = time.time()
			if self.now - self.lastReportTime >= 5:
				self.lastReportTime = self.now
				print("Counter 1: %s Counter 2: %s Counter 3: %s" % (self.counter1, self.counter2, self.counter3))

node = PulseCounter()
node.pulseCounterMode()

[danielm]

I just want to remind that this issue remains unsolved on 1.6.13.b1

Counter 1: 10009 Counter 2: 6449 Counter 3: 12757
Counter 1: 10024 Counter 2: 6459 Counter 3: 12778
Counter 1: 10040 Counter 2: 6470 Counter 3: 12798
Counter 1: 10055 Counter 2: 6480 Counter 3: 12818
Counter 1: 10070 Counter 2: 6490 Counter 3: 12838
Counter 1: 10086 Counter 2: 6501 Counter 3: 12858
Counter 1: 10101 Counter 2: 6511 Counter 3: 12878
Counter 1: 10116 Counter 2: 6521 Counter 3: 12899
Counter 1: 10132 Counter 2: 6531 Counter 3: 12919
Counter 1: 10147 Counter 2: 6541 Counter 3: 12939
Guru Meditation Error of type InstrFetchProhibited occurred on core  0. Exception was unhandled.
Register dump:
PC      : 0xffffffff  PS      : 0x00060a30  A0      : 0x800eb2f0  A1      : 0x3ffe1f50
A2      : 0x3ffe28d0  A3      : 0x00000001  A4      : 0x00000000  A5      : 0x3ffe1f70
A6      : 0x00050823  A7      : 0x00000000  A8      : 0x800eb2ac  A9      : 0x3ffe1f30
A10     : 0x3ffe28d0  A11     : 0x00000001  A12     : 0x00000000  A13     : 0x3ffe1f70
A14     : 0x00000003  A15     : 0x00060823  SAR     : 0x00000012  EXCCAUSE: 0x00000014
EXCVADDR: 0xfffffffc  LBEG    : 0x400f753a  LEND    : 0x400f7543  LCOUNT  : 0x00000000

Backtrace: 0x7fffffff:0x3ffe1f50 0x400eb2f0:0x3ffe1f70 0x400dccb8:0x3ffe1fa0 0x400e1672:0x3ffe1fc0 0x400d8244:0x3ffe2050

================= CORE DUMP START =================

...

[livius]

@daniel
it looks like good concept - not overlapped events

[daniel]

@livius I mean to disable the interrupt on that same pin.

[livius]

@daniel
Then we can miss interrupt on different pin?
Or you mean interrupt on exact pin?

[daniel]

@robert-hh thanks. Could the solution here be to disable GPIO interrupts while the C handler is executing (this is fast)?

[robert-hh]

@daniel Actually it were two different cases:
a) Timer interrupt. If the handler took longer than about 500 µs, the handler seemed to be raised a second time. Solved by a flag in the handler, which checked whether it was already busy.
b) External interrupt, which was called twice in a row. Solved by using a different drive with faster slopes..

[robert-hh]

@danielm @livius Until now I was testing with a symmetric triangle pulse of 50 µs duration. I switched now to a exp-rise pulse, with a rise time of ~25 µs. Funny enough, the double pulse disappeared, until I changed to trigger on the falling edge. I had made the same observation with other asymmetric pulses. The red trace is the input pulse for the green response. I cannot extend the pulse independently form the rise time without creating my own pulse shapes, which somehow fails with the vendors software (Windows only, with missing NI libs).

[daniel]

@robert-hh thanks for the super detailed analysis! Can you share how did you solve this issue on the ESP8266?

[robert-hh]

@livius If you scroll down and read in this post, you'll see the answers to your questions, and also has @daniel already expressed interest in this topic. For the last test I used the rise time seen bye @danielm.
Using the pulse mode of my signal generator with transition times of about 7 ns the multiple interupts do not occur. B.T.W.: I had a similar effect on the ESP8266 with slow pulses. Very nasty!

[livius]

@robert-hh
can you show how that signals looks like
maybe characteristic of raising and falling edge matters (how fast raise and how fast falling
)
or maybe @danielm have some noise in real signal?

[robert-hh]

@robert-hh I managed to make the test with at least two signals (the signal generator has two channels!). SO I could test all variants of slow vs. fast pulses, pulses at the same time and pulses properly apart. I've set the pulse frequency to 100Hz. Setting the delays I could fine shift the two pulses in relation to each other, so that they happened either at the same time or with some µs distance. And I modified my test code to register two signals and to detect, when the ISR for one signal is interrupted by the one for the other signal. That never happened, the code never crashed. Only when I pushed Ctrl-C to end the test, I got sometimes a core dump, and the probability of that seems to depend on the chance, that the test program is interrupted in a critical state, so the increasing probability was.

• single source fast pulse (lowest)
• single source slow pulse or double source fast pulse
• double source slow pulse (highest)

Test code:

from machine import Pin, idle

resp_pin1 = Pin("G11", mode=Pin.OUT)
resp_pin1(1)

resp_pin2 = Pin("G13", mode=Pin.OUT)
resp_pin2(1)

flag1 = False
flag2 = False
count1 = 0
count2 = 0

def resp1(p, pout = resp_pin1):
    global flag2, flag1, count1
    flag1 = True
    if flag2:
        count1 += 1
    pout(0)
    pout(1)
    flag1 = False

def resp2(p, pout = resp_pin2):
    global flag2, flag1, count2
    flag2 = True
    if flag1:
        count2 += 1
    pout(0)
    pout(1)
    flag2 = False

def run(flag = True):
    irq_pin1 = Pin("G7", mode=Pin.IN, pull=Pin.PULL_UP)
    irq_pin2 = Pin("G9", mode=Pin.IN, pull=Pin.PULL_UP)
    irq_pin1.callback(trigger = Pin.IRQ_RISING, handler = resp1, arg=None)
    if flag:
        irq_pin2.callback(trigger = Pin.IRQ_RISING, handler = resp2, arg=None)
    try:
        while True:
            idle()
    except:
        print("%5d %5d" % (count1, count2))
        irq_pin1.callback(handler = None)
        irq_pin2.callback(handler = None)

[robert-hh]

@danielm I'm not saying, that this does not happen, only my test did not reveal it. What is even more likely, that with your three ISR functions you have the chance of stacked calls. Daniel wanted to look into it. I have just one signal generator, but I could set up another micro to generate pulses.

But in any case you have to deal with multiple calls form that single source. Didn't you see increments of your counter faster than excepted? In order to shape the signal, you could add a Schmitt-Trigger gate, like the 74HC14. You could also try the falling edge of your opto-isolator, which should be faster.

[danielm]

@robert-hh
If your hypothesis is right and there are no recursively called ISRs could it somehow cause memory issues anyway?
Btw, my opto-isolators are quite slow, as one could expect from opto-isolators... Rise time is around 23us.

[robert-hh]

@daniel I could not find evidence that the simple IRS I used is called recursively. To catch that event, I had set up a global flag, which is set and clear upon entry, and i set upon entry, would increase a global counter, like this:

resp_pin = Pin("G11", mode=Pin.OUT)
resp_pin(1)
flag = False
counter = 0
def resp(p, pout = resp_pin):
    global flag, counter
    if flag:
        counter += 1
    else:
        flag = True
        pout(0)
        pout(1)
        flag = False

That counter stayed 0, even if I extended the time between the two pout() calls.
Hy hypothesis is, that the input stage of the esp32 has not Schmitt-Trigger characteristics, and noise in a slow transition causes the input stage to toggle fast. At a slope time of 1ms for instance, I had the ISR called 12 times in a row.

[daniel]

@robert-hh thanks. I'll investigate around your findings today.

[danielm]

@robert-hh
Yes, of course it should. I was just too quick with copy-paste :)
Thank you for your previous reply as well. I am not sure how fast are my opto-isolators. I will check with oscilloscope in the beginning of next week.

[robert-hh]

@danielm said in Unhandled exception in interrupt handler:

def counter3irq(self, obj):
self.temporary2 = self.counter3
self.counter3 = self.temporary2 + 1

Not that I think it's the reason, but should'nt that piece of code be:

	def counter3irq(self, obj):
		self.temporary3 = self.counter3
		self.counter3 = self.temporary3 + 1

[robert-hh]

@danielm Maybe the problem is somewhere else. The LoPy (and WiPy) use a soft interrupt handler. That means this handler can be interrupted by another event. This event can come from the same source, when the signal, which you count has a slow slope, and slow means rise/fall time >2-3 µs. I had seen this phenomenon without following it in my tests of irq latency, where I had unexpected responses first when using a 'slow' source. Now I made a test, and triggered the lopy with triangle pulses. The code is simple. The ISR just responds with a pulse when triggered. If the slope is slow, is see several pulses.
Pulse width 3.3 µs, rise/fall time 1.65 µs: Single pulse

Pulse width 10 µs, rise/fall time 5 µs: Two pulses

Pulse width 400µs, rise/fall time 200 µs: Four pulses

Maybe that's a reason for the effect here. I recall an observation, that interrupt handler may be called recursively, if the next event happens, before handling of the first has finished. And with your three timers that may stack up even more, if by chance the event coincide. In another application I used therefore a flag to avoid recursive calls.
And yes, here is my test code:

from machine import Pin, idle

resp_pin = Pin("G11", mode=Pin.OUT)
resp_pin(1)
def resp(p, pout = resp_pin):
    pout(0)
    pout(1)

irq_pin = Pin("G7", mode=Pin.IN, pull=Pin.PULL_UP)
irq_pin.callback(trigger = Pin.IRQ_FALLING, handler = resp, arg=None)

try:
    while True:
        idle()
except:
    pass

irq_pin.callback(handler = None)

[danielm]

@daniel
Did you generate enough pulses to increment all three counters? As you can see, in my experiments 22-24k pulses were needed in total to encounter those issues.