Interrupts setuped with `attachInterrupt` are very slow.

[sweetpi]

Something seems to be wrong with the way how interrupts are handled.

I'm trying to record pulses of length 250-2000 micros. Example sketch:

volatile int lastTime = 0;

void setup()
{                
  Serial.begin(115200);
  attachInterrupt(2, pinChanged, CHANGE);
}

void loop()                     
{
}

void pinChanged()
{
  int time = micros();
  int duration = time - lastTime;
  Serial.print(duration);
  Serial.print("\r\n");
  lastTime = time;
}

But this outputs something like:

76131
3683
76143
3752
76146
3667
76128
3768
76141
3741
76148
3661
76114
3785
76130
3683
...

I exprected numbers around 250-2000. It's stange that its almost all time a longer dealy and then a shorter. I double checked the wiring and the interrupts only occure with connected sensor.

I did the same using nodemcu (using gpio.trig) and got ver accurate timings.

Any ideas what is going wrong here?

[igrr]

I don't have access to my signal generator and scope today, so did a quick test by touching gpio2 with a ground wire. This generates a random signal on the input pin.
The shortest intervals I get are around 12us, which looks sane for the interrupt processing plus Serial.print overhead.

At the moment I can't really think of a reason for the behaviour you see. But I need to check with a scope to be sure.

24706393
191
14
593
30
12
131
14
34
12
112
16
11
12
15
23
12
24
14
11
12
43
12
48
188
14
196
222
33
11
25
25
43
34
96
106
32
14
19
1479
687
143
17
287
382
51
14
15
158
103
120
17
46
187
55
58
62
15
14
34
23
15
25
148
103
256
69
15
198
784
891
90
24
154
1176
20
109
39
25
58
292
28
14
15
16
15
66
37
473
47
15
14
15
14
360
150
17
14
116
23
15
109
17
14
15
71
18
23
14
22
2418
109
68
31
405
52
3359
64
14
15
1735
54
242
18
58
20
21
14
60
425
18
230
27
94
20
71
23
37
24
5046
485
132
17
27
100
17
171
244
142
381
775
23
15
140
1583
440
4894
373
442
215
1287
30
170
266
5392
2626
5152
242
4114495
43
51
24
111
120
44
610
1681
26738
1871
48
12
11
46
12
12
34
14
50
761
145
230
761
26
126
604
44
1162
170
18
85
136
39
144
49
234
252
364
103
61
60
33
5039
1844
16
1255
16
226
54
12
14
48
65
12
198
1053
15
22
14
29
195
21
13
83
12
12
282
20
12
20
12
16
15
40
12
52
12
29
32
50
32
17
16
18
52
15
15
14
17
174
17
26
1514
27
14
148
17
14
15
14
18
39
15
61
15
16
345
200
17
19
32
83

[sweetpi]

I don't have access to my signal generator and scope today, so did a quick test by touching gpio2 with a ground wire. This generates a random signal on the input pin.
The shortest intervals I get are around 12us, which looks sane for the interrupt processing plus Serial.print overhead.

I get the same results if I touch the ground. That's really strange. Are there some periodically scheduled "background" tasks that could block the interrupt for a longer delay?

At the moment I can't really think of a reason for the behaviour you see. But I need to check with a scope to be sure.

If you could check it, it would be cool. If it's working for you I know the error must be somewhere else.

While browsing the code I noticed that most ESP8266 firmware set some special register settings when enabling interrupts:

https://github.com/zazolabs/esp8266_easyintr/blob/master/easyintr.c#L110-L114
https://github.com/nodemcu/nodemcu-firmware/blob/84a9ab35a8eb9b4ae2229bba7b2626c2a285818d/app/platform/platform.c#L98-L101

I can't find any docs about that, but I think the Arduino lib is missing this and this could lead to errors on other scenarios where the pin was set as an output some time before its used as an interrupt.

[igrr]

Are there some periodically scheduled "background" tasks that could block the interrupt for a longer delay?

There are other tasks running on the chip which deal with WiFi and TCP/IP processing. But these are tasks, not interrupt handlers, so they shouldn't be blocking GPIO interrupts.

While browsing the code I noticed that most ESP8266 firmware set some special register settings when enabling interrupts.

While you're at it, could you please try this version of __attachInterrupt:

extern void __attachInterrupt(uint8_t pin, voidFuncPtr handler, int mode) 
{
    if (pin < 0 || pin > PINCOUNT)
        return;

    g_handlers[pin] = handler;
    ETS_GPIO_INTR_DISABLE();   
    if (mode == RISING)
    {
        gpio_pin_intr_state_set(pin, GPIO_PIN_INTR_POSEDGE);
    }
    else if (mode == FALLING)
    {
        gpio_pin_intr_state_set(pin, GPIO_PIN_INTR_NEGEDGE);
    }
    else if (mode == CHANGE)
    {
        gpio_pin_intr_state_set(pin, GPIO_PIN_INTR_ANYEDGE);
    }
    else
    {
        gpio_pin_intr_state_set(pin, GPIO_PIN_INTR_DISABLE);
    }
    GPIO_REG_WRITE(GPIO_STATUS_W1TC_ADDRESS, BIT(gpio_pin));
    ETS_GPIO_INTR_ENABLE();
}

and check if it breaks anything?

[sweetpi]

extern void __attachInterrupt(uint8_t pin, voidFuncPtr handler, int mode) 
{
    if (pin < 0 || pin > PINCOUNT)
        return;

    g_handlers[pin] = handler;
    ETS_GPIO_INTR_DISABLE();   
    if (mode == RISING)
    {
        gpio_pin_intr_state_set(pin, GPIO_PIN_INTR_POSEDGE);
    }
    else if (mode == FALLING)
    {
        gpio_pin_intr_state_set(pin, GPIO_PIN_INTR_NEGEDGE);
    }
    else if (mode == CHANGE)
    {
        gpio_pin_intr_state_set(pin, GPIO_PIN_INTR_ANYEDGE);
    }
    else
    {
        gpio_pin_intr_state_set(pin, GPIO_PIN_INTR_DISABLE);
    }
    GPIO_REG_WRITE(GPIO_STATUS_W1TC_ADDRESS, BIT(pin));
    ETS_GPIO_INTR_ENABLE();
}

does not break anything. Still same results like before.

[sweetpi]

Some more quirks: Following try seems to be crash the module:

volatile int lastTime = 0;
#define MAX_TIMINGS 256
volatile unsigned int timings[MAX_TIMINGS];
volatile int i = 0;

void setup()
{                
  Serial.begin(115200);
  attachInterrupt(2, pinChanged, CHANGE);
}

void loop()                     
{
}

void pinChanged()
{
  int time = micros();
  int duration = time - lastTime;
  lastTime = time;
  if(i < MAX_TIMINGS) {
    timings[i] = duration;
    i++;
  } else {
    for(int j=0; j < MAX_TIMINGS; j++) {
      Serial.print(timings[j]);
      Serial.print(" ");     
    }
    Serial.print("\r\n");
    i = 0;
  }
}

1348062 143 302832 1361 594316 5763 75883 5717 75848 5747 75856 5734 74835 6849 75846 5742 75863 5731 34457 395 40964 5857 75825 5770 72322 9269 75849 5741 75847 5830 75808 5841 52750 676 22382 5774 73765 7819 75828 5754 12948 651 62240 961828 4426 76480 4567 15454 852 192 4402 14673 4568 11039 9095 5306 6993 2911 4701 4198 9150 1927 23563 432 101251 1108 101375 3520 98901 1005 101492 1124 28336 5504 67614 1559 103012 1886 98429 1480 102245 358 5205 5576 88838 694 98671 1241 101222 1383 89782 5537 4516 470 99381 3234 98740 1164 102984 1904 69449 5516 19520 845 101675 931 101147 3744 94673 250 59067 5507 37308 1127 101361 1244 101061 1133 97535 2375 38716 757321 4484 213513 4368 97607 4473 2407 4589 15422 5723 4171 5498 24508 5544 2887 26838 902 13270 652 87533 44 819210 74 58946 2544 1070 1620 971 4013 33276 167 182016 5524 17316 3044 98521 1395 101946 663 101380 3512 54073 5524 39859 1271 103616 1275 98728 1187 101223 1378 33281 5545 61026 461 103029 1868 99688 224 102287 318 12917 5549 83708 836 101675 3212 99145 769 92476 5538 3396 1595 101296 1312 101177 3714 97903 2003 69425 850741 4353 200539 4398 27592 70756 267 4612 6001 75875 5720 75846 5752 75847 5743 51165 131 24529 5849 73077 8527 75827 5764 75804 5879 31558 622 43648 5775 52900 534 22387 5771 73105 8486 75848 5736 13048 548 62199 639555 619 115918 4346 98625 4314 97627 4367 82441 4577 6638 4050 883 4504 16624 
92233 37702 5269 42756 1519 1018563 818 2273427 61 685 461 1438 246 1302727 73 205256 98 204273 153 509300 26 100328 1672 147967 303 822211 330 213409 1283 2736 26 1370721 515 77556 4376 20238 845 95614 4388 3976 2953 96906 272 12596 4385 86933 1065 28695 4401 67863 1578 47280 4368 47123 1314 68306 4349 29049 3268 84400 4262 5187 31928 9036 1895 67651 243 817865 461 1147029 24 1219 447
 ets Jan  8 2013,rst cause:4, boot mode:(3,7)

wdt reset
load 0x40100000, len 27736, room 16 
tail 8
chksum 0xf1
load 0x3ffe8000, len 2548, room 0 
tail 4
chksum 0x50
load 0x3ffe8a00, len 1356, room 4 
tail 8
chksum 0x85
csum 0x85

It seems to keep working with MAX_TIMINGS set to 64.

[igrr]

I see you're calling Serial.print from the interrupt. Serial.print is interrupt-driven, so it is "fire and forget" most of the time, unless the TX buffer overflows. When it does, it blocks hard until it gets a TX_EMPTY interrupt, then it puts more data into the buffer.
Since you're calling it from GPIO interrupt, UART interrupt will never fire (it has lower priority).
Long story short: don't call Serial.print from interrupt, or expect that long strings will lead to a halt (and a WDT reset afterwards).

There's ets_printf which doesn't buffer and you can use it from interrupts. It may loose some characters though.

[iMarvinS]

@igrr Which header needs to be included to use the ets_printf function?
I also wondered why the ESP resets itself when I do a Serial.print in a interrupt callback function.

[igrr]

@iMarvinS as my previous post in this topic says:

Serial.print is interrupt-driven, so it is "fire and forget" most of the time, unless the TX buffer overflows. When it does, it blocks hard until it gets a TX_EMPTY interrupt, then it puts more data into the buffer.
Since you're calling it from GPIO interrupt, UART interrupt will never fire (it has lower priority).

[sweetpi]

Problem solved. The voltage source was not strong enough. @igrr Thank you very much for this great project and your support.