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
    

    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()
    


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


  • @daniel
    it looks like good concept - not overlapped events


  • administrators

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



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


  • administrators

    @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).
    0_1491899191521_exprise_100us.jpg


  • administrators

    @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
    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 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)
    


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



  • @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.
    0_1491840787559_DS1Z_QuickPrint2.png



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


  • administrators

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



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



  • @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
    


  • @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
    0_1491595587146_triangle_resp_3.jpg
    Pulse width 10 µs, rise/fall time 5 µs: Two pulses
    0_1491595606305_triangle_resp_10.jpg
    Pulse width 400µs, rise/fall time 200 µs: Four pulses
    0_1491595629099_triangle_resp_400.jpg
    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)
    


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


Log in to reply
 

Looks like your connection to Pycom Forum was lost, please wait while we try to reconnect.