Using micros() inside interrupt will return larger value than later in loop()?

I tried to capture a really long infrared remote signal that IRremote library cannot handle, so I came up with this:

#define IR_IN 2
#define FINISH_THERSHOLD 10000UL
/* Other consts */

volatile unsigned long lastTimestamp = 0, nowTimestamp;
volatile unsigned long nowTimestamp2 = 0;
volatile unsigned long durationAwaiting = 0;
/* Other variables */

void ExtIsr()
{
    nowTimestamp = micros();
    if(lastTimestamp)
        durationAwaiting = nowTimestamp - lastTimestamp;
    lastTimestamp = nowTimestamp;
}

void setup()
{
    Serial.begin(230400);
    pinMode(IR_IN, INPUT);
    attachInterrupt(digitalPinToInterrupt(IR_IN), ExtIsr, CHANGE);
}

void loop()
{
        if(lastTimestamp != 0)  // If it's capturing
        {
            nowTimestamp2 = micros();   // Get current timestamp
            if(nowTimestamp2 > lastTimestamp)   // If now is ahead of the last ISR is fired (the problem happens here)
            {
                if((nowTimestamp2 - lastTimestamp) > FINISH_THERSHOLD)  // Assume the receiving is finished if the time span is greater than the maximum time span allowed
                {
                    /* For DEBUG purpose */
                    Serial.print("NOW:");
                    Serial.println(nowTimestamp2);
                    Serial.print("LAST:");
                    Serial.println(lastTimestamp);
                    Serial.print("Greater:");
                    Serial.println(nowTimestamp2 > lastTimestamp);
                    Serial.print("Difference:");
                    Serial.println(nowTimestamp2 - lastTimestamp);
                    lastTimestamp = 0;
                }
            }
        }
        /* if(durationAwaiting) do the enqueueing; durationAwaiting = 0; */
        /* Do the dequeueing and sending */
}

However when testing I found that the "receiving finished" part is executed incorrectly, so I put some serial print code inside the if block to see what happened, and this happened:

22:13:50.897 -> NOW:443576
22:13:50.897 -> LAST:443580
22:13:50.897 -> Greater:0
22:13:50.897 -> Difference:4294966680
22:13:50.897 -> NOW:446496
22:13:50.897 -> LAST:446504
22:13:50.944 -> Greater:0
22:13:50.944 -> Difference:4294966720
22:13:50.944 -> NOW:455108
22:13:50.944 -> LAST:455116
22:13:50.944 -> Greater:0
22:13:50.944 -> Difference:4294966700
22:13:50.944 -> NOW:468688
22:13:50.944 -> LAST:468696
22:13:50.944 -> Greater:0
22:13:50.944 -> Difference:4294966704
22:13:50.944 -> NOW:477788
22:13:50.944 -> LAST:477796
22:13:50.944 -> Greater:0
22:13:50.944 -> Difference:4294966700
22:13:50.944 -> NOW:483528
22:13:50.944 -> LAST:483536
22:13:50.944 -> Greater:0
22:13:50.944 -> Difference:4294966700
22:13:50.944 -> NOW:486952
22:13:50.944 -> LAST:486960
22:13:50.944 -> Greater:0
22:13:50.944 -> Difference:4294966696
22:13:50.991 -> NOW:494912
22:13:50.991 -> LAST:494920
22:13:50.991 -> Greater:0
22:13:50.991 -> Difference:4294966700
22:13:50.991 -> NOW:508944
22:13:50.991 -> LAST:498936
22:13:50.991 -> Greater:1
22:13:50.991 -> Difference:10008
22:13:51.038 -> NOW:551072
22:13:51.038 -> LAST:551080
22:13:51.038 -> Greater:0
22:13:51.038 -> Difference:4294967288
22:13:51.129 -> NOW:669424
22:13:51.129 -> LAST:659420
22:13:51.129 -> Greater:1
22:13:51.129 -> Difference:10004

Some timestamp inside loop() is actually behind the timestamp in ISR? Also if this happens, the if(nowTimestamp2 > lastTimestamp) shouldn't execute the block, but seems like it still does? I wonder if anyone can tell me what happened here, I am assuming it's something interrupt related but doesn't know further more. Thanks.

Hi,

I think the ExtIsr() function is executed after you print NOW, but before you print LAST in your Serial output.

To confirm that, print the LAST value twice, and tell us what the output is.

Like this:

                   /* For DEBUG purpose */
                    Serial.print("LAST:");              // <--  add this line
                    Serial.println(lastTimestamp); // <--  add this line
                    Serial.print("NOW:");
                    Serial.println(nowTimestamp2);
                    Serial.print("LAST:");
                    Serial.println(lastTimestamp);

Also consider that operation on 4 byte variables are not atomic. The interrupt service routine could be updating part of it while you are reading it in the loop.
You can solve this by suspending interrupts in the loop, making a copy of the variable, resuming interrupts, then processing the copy.

cadence22:
Hi,

I think the ExtIsr() function is executed after you print NOW, but before you print LAST in your Serial output.

To confirm that, print the LAST value twice, and tell us what the output is.

Like this:

                   /* For DEBUG purpose */

Serial.print(“LAST:”);              // ← add this line
                    Serial.println(lastTimestamp); // ← add this line
                    Serial.print(“NOW:”);
                    Serial.println(nowTimestamp2);
                    Serial.print(“LAST:”);
                    Serial.println(lastTimestamp);

Seems like you are correct, but I have no idea how this happened. Maybe the interrupt is way too frequent that it got fired multiple times during the loop() being executed once?

23:39:49.341 -> LAST_Before:373704
23:39:49.341 -> NOW:373696
23:39:49.341 -> LAST:374332
23:39:49.341 -> Greater:0
23:39:49.341 -> Difference:4294966128
23:39:49.341 -> LAST_Before:381240
23:39:49.341 -> NOW:381232
23:39:49.341 -> LAST:381804
23:39:49.341 -> Greater:0
23:39:49.341 -> Difference:4294966128
23:39:49.387 -> LAST_Before:391460
23:39:49.387 -> NOW:391452
23:39:49.387 -> LAST:392012
23:39:49.387 -> Greater:0
23:39:49.387 -> Difference:4294966736
23:39:49.387 -> LAST_Before:402764
23:39:49.387 -> NOW:402756
23:39:49.387 -> LAST:403324
23:39:49.387 -> Greater:0
23:39:49.387 -> Difference:4294966132
23:39:49.387 -> LAST_Before:408496
23:39:49.387 -> NOW:408488
23:39:49.387 -> LAST:409068
23:39:49.387 -> Greater:0
23:39:49.387 -> Difference:4294966116
23:39:49.387 -> LAST_Before:413640
23:39:49.387 -> NOW:413632
23:39:49.387 -> LAST:414232
23:39:49.387 -> Greater:0
23:39:49.387 -> Difference:4294966132
23:39:49.387 -> LAST_Before:417060
23:39:49.387 -> NOW:417052
23:39:49.387 -> LAST:417656
23:39:49.387 -> Greater:0
23:39:49.387 -> Difference:4294966132
23:39:49.387 -> LAST_Before:427840
23:39:49.387 -> NOW:427832
23:39:49.432 -> LAST:428432
23:39:49.432 -> Greater:0
23:39:49.432 -> Difference:4294966696

6v6gt:
Also consider that operation on 4 byte variables are not atomic. The interrupt service routine could be updating part of it while you are reading it in the loop.
You can solve this by suspending interrupts in the loop, making a copy of the variable, resuming interrupts, then processing the copy.

I'll try it, but I am not sure whether doing this will be fast enough for not losing the infrared packet, as the shortest bit only length for ~400us.

whc2001:
Seems like you are correct, but I have no idea how this happened. Maybe the interrupt is way too frequent that it got fired multiple times during the loop() being executed once?

Yes, I believe this is what is happening here.

Serial.print is not particularly fast and your attempts to debug may themselves cause the problem.
What is this IR protocol? Can you give the timings for a mark and a space, carrier frequency etc. ?

6v6gt:
Serial.print is not particularly fast and your attempts to debug may themselves cause the problem.
What is this IR protocol? Can you give the timings for a mark and a space, carrier frequency etc. ?

I tried it and seems like it's almost done. But when I tried to use another arduino to simulate a long random infrared signal (no carrier just high-low as the infrared receiver will demodulate the signal), it will receive one duration error at some point in the middle ("glitch" for one duration, and misalign the durations received and the actual durations transmitted). For example, here is the compare of one of my attempt:

...
tx1690=13120 rx1690=13120 diff=0 pass=True
tx1691=916 rx1691=924 diff=-8 pass=True
tx1692=3655 rx1692=3652 diff=3 pass=True
tx1693=9601 rx1693=9608 diff=-7 pass=True
tx1694=16862 rx1694=11164 diff=5698 pass=False
!!! Duration 1694 mismatch
tx1695=13649 rx1695=5704 diff=7945 pass=False
!!! Duration 1695 mismatch
tx1696=3874 rx1696=13660 diff=-9786 pass=False
!!! Duration 1696 mismatch
tx1697=18295 rx1697=3872 diff=14423 pass=False
!!! Duration 1697 mismatch
tx1698=16465 rx1698=18300 diff=-1835 pass=False
!!! Duration 1698 mismatch
...

6v6gt:
Serial.print is not particularly fast and your attempts to debug may themselves cause the problem.
What is this IR protocol? Can you give the timings for a mark and a space, carrier frequency etc. ?

Forgot to mention what I tried is to copy the variables that are modified inside ISR. There is a ring buffer in the program and for each execution of loop(), it will check whether one duration is received and it will put it in the ring buffer. Then checks if there are any unsent data in the ring buffer and send them to the serial port. For reference here is the full code:

#define IR_IN 2 // Infrared receiver pin (Physical pin, not interrupt ID)
#define BUFFER_SIZE 512 // Internal ring buffer size, will be cycled through so no need to set too large unless you experienced buffer overflow.
#define FINISH_THERSHOLD 32768UL    // Time to wait before timing out

// Ring buffer
const unsigned char intId = digitalPinToInterrupt(IR_IN);
unsigned int ringBuffer[BUFFER_SIZE];
unsigned int *readPtr = ringBuffer, *writePtr = ringBuffer;
unsigned char cycled = 0, lose = 0;

volatile unsigned long lastTimestamp = 0, nowTimestamp = 0, lastTimespan = 0;
unsigned long lastTimestampCopy = 0, nowTimestampCopy = 0, lastTimespanCopy = 0;
unsigned int bufferReadTmp;
unsigned char sendBuf[3];
unsigned char flag = 1; // For the plus or minus sign before time value

void RingBufferWrite(unsigned int n)
{
    if(cycled && writePtr >= readPtr)
        lose = 1;
    *writePtr++ = n;
    if(writePtr - ringBuffer >= BUFFER_SIZE)
    {
         cycled = 1;
        writePtr = ringBuffer;
    }
}

unsigned int RingBufferRead()
{
    if(readPtr == writePtr && !cycled)
        return 65535;
    unsigned int val = *readPtr++;
    if(readPtr - ringBuffer >= BUFFER_SIZE)
    {
        cycled = 0;
        readPtr = ringBuffer;
    }
    return val;
}

void ExtIsr()
{
    nowTimestamp = micros();
    if(lastTimestamp)
        lastTimespan = nowTimestamp - lastTimestamp;
    lastTimestamp = nowTimestamp;
}

void AttachIsr()
{
    attachInterrupt(intId, ExtIsr, CHANGE);
}

void DetachIsr()
{
    detachInterrupt(intId);
}

void setup()
{
    Serial.begin(230400);
    pinMode(IR_IN, INPUT);
    AttachIsr();
}

void loop()
{
    // Detach ISR temporarily to prevent variable change during executing
    DetachIsr();
    lastTimestampCopy = lastTimestamp;
    nowTimestampCopy = micros();
    lastTimespanCopy = lastTimespan;
    lastTimespan = 0;
    AttachIsr();
    
    // Test for timeout (one packet is finished)
    if(lastTimestampCopy != 0 && (nowTimestampCopy > lastTimestampCopy) && (nowTimestampCopy - lastTimestampCopy) > FINISH_THERSHOLD)
    {
        lastTimestamp = 0;
        Serial.print(flag ? "+" : "-");
        Serial.println("32767"); // Some interpreter (e.g. irdb.tk) require a dummy end sign to parse correctly
        flag = 1;
    }
    
    // Save the last captured timespan
    if(lastTimespanCopy)
    {
        RingBufferWrite(lastTimespanCopy);
        lastTimespanCopy = 0;
    }

    // Read from ring buffer and send to serial port
    bufferReadTmp = RingBufferRead();
    if(bufferReadTmp != 0xFFFF)
    {
        Serial.print(flag ? "+" : "-");
        Serial.print(bufferReadTmp, DEC);
        Serial.print(" ");
        flag = !flag;
    }

    // Detect for ring buffer overflow
    if(lose)
    {
        Serial.println("!!! Ring buffer overrun, this packet is invalid !!!");
        lose = 0;
    }
}

After some investigation, it seems like it's because of hardware issue (like interference) that make the program think it's a new duration, as the compare result showed below, [R1694]11164 + [R1695]5704 = 16868 ≈ [T1694]16862, and [R1696]13660 ≈ [T1695]13649. I am still waiting for the air conditioner remote control that I am going to hack to be delivered, when it arrives I will test the code using a real infrared receiver.

tx1693=9601 rx1693=9608 diff=-7 pass=True
tx1694=16862 rx1694=11164 diff=5698 pass=False
!!! Duration 1694 mismatch
tx1695=13649 rx1695=5704 diff=7945 pass=False
!!! Duration 1695 mismatch
tx1696=3874 rx1696=13660 diff=-9786 pass=False
!!! Duration 1696 mismatch