Sporadic value from micros()

Troubleshooting
1

Hey everyone,

Just starting with a Photon. I am trying to measure pulse times via a low triggered interrupt. I think it’s a pretty simple handler.

I started getting occasional random errors, and began storing the micros() values into an array, so when I got a bad value I could print the timings. The bit errors come in different places, but each time it appears there is a reading with an extra 1ms, and the next delta is negative because the reading gets back on track. Time jumping ahead leads me to believe I’m not missing counts, and since it jumps backwards, not missing an interrupt.

Example 1:

        Current         Previous        Delta
        27062216        27062135        81
        27062297        27062216        81
        27062424        27062297        127
        27062505        27062424        81
        27062586        27062505        81
        27062666        27062586        80
        27062759        27062666        93
        27062840        27062759        81
        27062921        27062840        81
        27064002        27062921        1081
        27063083        27064002        -919
        27063163        27063083        80
        27063244        27063163        81
        27063323        27063244        79
        27063464        27063323        141

Example 2:

        32194423        32194295        128
        32194504        32194423        81
        32194584        32194504        80
        32194664        32194584        80
        32194758        32194664        94
        32194839        32194758        81
        32194919        32194839        80
        32196001        32194919        1082
        32195083        32196001        -918
        32195163        32195083        80
        32195244        32195163        81
        32195323        32195244        79
        32195464        32195323        141
        32195592        32195464        128

The measuredMicros[][] and bad* variables are for debugging this issue.

volatile int intCount = 0;

volatile int badTemp = 0;
volatile int badRH = 0;
volatile int badSum = 0;
volatile int badCheck = 0;

volatile int measuredMicros[3][45];

void sensorInterrupt(void) {
    static unsigned long lastMicros;
    static unsigned int measuringTemp;
    static unsigned int measuringRH;
    static unsigned int checksum;
        
    intCount++;
    if (intCount == 1) {
        // First interrupt is sensor ack
        measuringTemp = 0;
        measuringRH = 0;
        checksum = 0;
        return;
    }
    
    unsigned long currentMicros = micros();
    if (intCount > 2) {
        measuredMicros[0][intCount] = currentMicros;
        measuredMicros[1][intCount] = lastMicros;
        measuredMicros[2][intCount] = currentMicros - lastMicros;
        int newBit = (currentMicros - lastMicros) < 100 ? 0x00 : 0x01;
        if (intCount <= 18) {
            measuringRH = (measuringRH << 1) | newBit;
        } else if (intCount <= 34) {
            measuringTemp = (measuringTemp << 1) | newBit;
        } else {
            checksum = (checksum << 1) | newBit;
        }
        if (intCount == 42) {
            unsigned int sum = 0;
            sum += measuringRH >> 8;
            sum += measuringRH & 0x0ff;
            sum += measuringTemp >> 8;
            sum += measuringTemp & 0x0ff;
            if ((sum & 0x0ff) == checksum) {
                if (measuringTemp & 0x08000) {
                    lastTemp = -(measuringTemp & 0x7fff);
                } else {
                    lastTemp = measuringTemp;
                }
                lastRH = measuringRH;
            } else {
                badTemp = measuringTemp;
                badRH = measuringRH;
                badSum = sum;
                badCheck = checksum;
            }
        }
    }
    lastMicros = currentMicros;
}

Any suggestions?

Thanks.

2

How are you attaching the interrupt?
Since you see a 1ms glitch from time to time I could be that higher priority interrupts (e.g. WiFi communication) get in your way and cause some “out of order” execution due to queueing same priority interrupts.
Could you try to elevate the priority of your interrupt?

But this might still be something for @mdma to look at.

BTW: Try to have all your micros variables unsigned long and volatile.

3

I’ve been thinking about how millis() is implemented, and that it’s totally reliant upon the SysTick interrupt, which may be delayed/unsurped by a higher IRQ. Also, millis() isn’t ticked while the device is in stop-mode sleep.

4

But in this case it’s micros() that’s usually still doing its job even inside ISRs.

5

Right, but micros is based on millis() indirectly so any problem with millis() will also affect micros.

6

OK?
I would have thought it to be the other way round.
After all if millis() not get updated inside ISRs how would micros() do the magic of counting 1000th fractions of a frozen variable and get updated anyhow?

7

Last night I had tried making the micros variables volatile, after reading an article on code reordering. It seemed to be working, even as I was convincing myself that wouldn’t explain the issue, but then more failures.

I have not tried changing the interrupt priority. I understand that tick interrupts could possibly be missed, but looking at the firmware code, I think that would only delay millis(), and in no case cause a jump forward, and then backwards by micros(). The only way I could see this happening is if the GetSystem1UsTick() call was out of order, but its variables are volatile.

I am attaching the interrupt as follows

void startRead(void) {
    detachInterrupt(SENSOR_PIN);
    intCount = 0;
    lastTemp = -101;
    lastRH = -101;
    digitalWrite(SENSOR_PIN, LOW);
    pinMode(SENSOR_PIN, OUTPUT);
    delay(2); // Wait for sensor to detect start
    noInterrupts();
    pinMode(SENSOR_PIN, INPUT);
    attachInterrupt(SENSOR_PIN, sensorInterrupt, FALLING);
    interrupts();
}

Thanks everyone.

8

Even if millis() is incorrect, micros() is based off the last DWT->CYCCNT value when millis() was calculated. So wouldn’t micros() still be correct?

9

I see it now. If my interrupt is higher priority, it could interrupt System1MsTick() between its two statements, which would cause me to be off 1ms.

I’m having a hard time finding the priority level of the SysTick interrupt, so I can set my interrupt to be a lower priority. Where could I find this information?

Thanks.

10

I found

#define SYSTICK_IRQ_PRIORITY 13,

and registered my interrupt with priority 14

attachInterrupt(SENSOR_PIN, sensorInterrupt, FALLING, SYSTICK_IRQ_PRIORITY + 1);

Letting the code run for about 9 hours, which should have read the sensor about 32k times, I still had 8 readings where delta micros() jumped forward and then went negative to correct itself.

Should priority 14 have kept my code from interrupting the system timer? Any other ideas?

11

Has this changed anything on the frequency of that glitch at all?

Since micros() returns a uint32_t it will have roled over 7 to 8 times during your 9 hours (once every 71 minutes).
While unsigned subtractions should not show this behaviour, this could well be a possible reason.
Have you printed the readings causing the error?

12

It seems to be less frequent. However looking at the micros value where it happened previously, it does not appear to be when the value crosses the word boundary. From example 1 above, the values were:

27062921   0x19C F289
27064002   0x19C F6C2 (+1081)
27063083   0x19C F32B  (-919)

The error was in the high byte of the low word, and isn’t a case of being caught incremented before the low byte was updated, F6 is larger than the target value of F3. I stopped logging the current micros value, but each second I am logging how many errors I have seen with a line like
Temp: 21.5C Humidity: 36.8% badChecksums: 55 negativeMicros: 9

If this only occurred at rollover, it should never happen with fewer than about 4260 samples (71 minutes * 60). But I do see if more frequently than that.

Michaels-MacBook-Pro:~ mcarland$ egrep "Micros: [0-9]" mgc.out | sed -e "s/.*negativeMicros: \([0-9]\)/\1/" | uniq -c
7640 0
 619 1
2766 2
1117 3
2650 4
4697 5
2799 6
9549 7
5443 8
1134 9

So it went as few as 619 seconds without error, and erred five times total under 71 minutes, not counting the last sample which wasn’t complete.

I am going to connect another Arduino as a waveform generator that I don’t have to trigger, and see if I can repeat this with a simpler case. I’ll also go back to logging the current micros value to see when it is happening.

13

OK, this sounds different to what I understood from that

Which made it appear likely, and since the code was changed since the previous data log, I couldn't tell any different :wink:

14

Yes, your suggestion made sense. I had to go back and look to see if your theory fit the data. Wish is was true, would be an easier thing to fix.

15

Yup, too bad - so it’s still a puzzle that might need the insight and a possible solution of @mdma

16

Ok, stripped down my code to an example. Removed the sensor I was reading, and used a Bus Pirate to put a 10kHz pulse on D1. Only thing connected is USB and GND/D1 to the Bus Pirate. Once per second (roughly) I attached the interrupt, and measure 40 pulses before disconnecting the interrupt. It went a while with no problem, but then had quite a few, sometimes more than one per minute, so I don’t think it was either counter doing a rollover.

@mdma, should setting the interrupt priority to SYSTICK_IRQ_PRIORITY + 1 take the millis counter issue out of the problem like I’m thinking?

negatives: 4
Read found negative delta micros():1313172
        1313165105      1313165205     100
        1313165205      1313165304      99
        1313165304      1313165404      100
        1313165404      1313165503      99
        1313165503      1313165603      100
        1313165603      1313165703      100
        1313165703      1313165802      99
        1313165802      1313165902      100
        1313165902      1313167001      1099
        1313167001      1313166098      -903
        1313166098      1313166198      100
        1313166198      1313166297      99
        1313166297      1313166397      100
        1313166397      1313166496      99
        1313166496      1313166596      100
        1313166596      1313166696      100
        1313166696      1313166795      99
        1313166795      1313166895      100
        1313166895      1313166994      99
        1313166994      1313167097      103
        1313167097      1313167196      99
        1313167196      1313167296      100
        1313167296      1313167395      99
        1313167395      1313167495      100
        1313167495      1313167594      99
        1313167594      1313167694      100
        1313167694      1313167794      100
        1313167794      1313167893      99
        1313167893      1313167993      100
        1313167993      1313168094      101
        1313168094      1313168193      99
        1313168193      1313168292      99
        1313168292      1313168392      100
        1313168392      1313168492      100
        1313168492      1313168591      99
        1313168591      1313168691      100
        1313168691      1313168791      100
        1313168791      1313168890      99
        1313168890      1313168990      100
negatives: 5
negatives: 5
negatives: 5
negatives: 5
negatives: 5
negatives: 5
negatives: 5
negatives: 5
Read found negative delta micros():1322334
        1322326711      1322326810     99
        1322326810      1322326910      100
        1322326910      1322327010      100
        1322327010      1322327109      99
        1322327109      1322327208      99
        1322327208      1322327308      100
        1322327308      1322327408      100
        1322327408      1322327507      99
        1322327507      1322327607      100
        1322327607      1322327706      99
        1322327706      1322327806      100
        1322327806      1322327906      100
        1322327906      1322328006      100
        1322328006      1322328105      99
        1322328105      1322328205      100
        1322328205      1322328304      99
        1322328304      1322328404      100
        1322328404      1322328503      99
        1322328503      1322328603      100
        1322328603      1322328703      100
        1322328703      1322328802      99
        1322328802      1322328902      100
        1322328902      1322330001      1099
        1322330001      1322329102      -899
        1322329102      1322329201      99
        1322329201      1322329300      99
        1322329300      1322329400      100
        1322329400      1322329499      99
        1322329499      1322329599      100
        1322329599      1322329699      100
        1322329699      1322329798      99
        1322329798      1322329898      100
        1322329898      1322329998      100
        1322329998      1322330097      99
        1322330097      1322330196      99
        1322330196      1322330296      100
        1322330296      1322330395      99
        1322330395      1322330495      100
        1322330495      1322330594      99
negatives: 6
negatives: 6


int SENSOR_PIN = D1;

volatile int intCount = 0;

volatile int negativeMicrosCount = 0;
volatile int negativeFound = 0;
volatile int readComplete = 0;
volatile int measuredMicros[40];

void sensorInterrupt(void) {
    static volatile unsigned long lastMicros;

    volatile unsigned long currentMicros = micros();

    long microsDiff = currentMicros - lastMicros;
    if (microsDiff < 0) {
        negativeFound = 1;
        negativeMicrosCount++;
    }
    
    intCount++;
    if (microsDiff > 5000) {
        intCount = 0;
    }

    lastMicros = currentMicros;

    if (intCount < 40) {
        measuredMicros[intCount] = currentMicros;
    } else {
        readComplete = 1;
    }

}

void setup() {
    Serial.begin(9600);

    delay(1000);
    
    pinMode(SENSOR_PIN, INPUT);
    attachInterrupt(SENSOR_PIN, sensorInterrupt, FALLING, SYSTICK_IRQ_PRIORITY + 1);
}

void loop() {
    while (1) {
        if (readComplete) {
            detachInterrupt(SENSOR_PIN);
            if (negativeFound) {
                negativeFound = 0;
                Serial.print("Read found negative delta micros():");
                Serial.print(millis());
                for (int i = 1; i < 40; i++) {
                    Serial.print("\t");
                    Serial.print(measuredMicros[i-1]);
                    Serial.print("\t");
                    Serial.print(measuredMicros[i]);
                    Serial.print("\t");
                    Serial.print(measuredMicros[i] - measuredMicros[i-1]);
                    Serial.println();
                }
            } else {
                Serial.print("negatives: ");
                Serial.println(negativeMicrosCount);
            }
            readComplete = 0;
            delay(1000);
            attachInterrupt(SENSOR_PIN, sensorInterrupt, FALLING, SYSTICK_IRQ_PRIORITY + 1);
        }
    }
}
17

Setting the priority will certainly remove one possible cause of delaying the systick interrupt, but presently the millis/micros code is not thread safe so an interrupt at just the right (wrong?) time can cause the data to be computed incorrectly.

1 Like