Unhandled exception in interrupt handler
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
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()
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 ================= ...
it looks like good concept - not overlapped events
@livius I mean to disable the interrupt on that same pin.
Then we can miss interrupt on different pin?
Or you mean interrupt on exact pin?
@robert-hh thanks. Could the solution here be to disable GPIO interrupts while the C handler is executing (this is fast)?
@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..
@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).
@robert-hh thanks for the super detailed analysis! Can you share how did you solve this issue on the ESP8266?
@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!
@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)
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)
@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.
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.
@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.
@robert-hh thanks. I'll investigate around your findings today.
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.
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
@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)
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.