Strange ISR timing

Hello guys,
i've set up an ISR routine, and i wanted to measure the time elapsed between two consecutive ISRs. I've written this program

void setup(){
  //set PWM: FastPWM, OC2A as top, OC2B sets at bottom, clears on compare
  //COM2B1=1 sets PWM active on pin3, COM2B1=0 disables it
  Serial.begin(9600);
  pinMode(3, OUTPUT);
  pinMode(11, OUTPUT);
  TCCR2A = _BV(COM2A0) | _BV(WGM21) | _BV(WGM20);
  TCCR2B = _BV(WGM22) | _BV(CS21);
  OCR2A = 49; // gives 20KHz PWM on pin11
  OCR2B = 24; // gives 40KHz PWM on pin3
  TIMSK2 |= _BV(TOIE2); //activate interrupt on overflow (on counter = OCR2A)
  
}

[other stuff here]

ISR(TIMER2_OVF_vect){
   timer++;
   now = micros();
   if(timer==2){
     Serial.println(now-previous);
     timer=0;   
   }
   previous = now; 
}

curious results are

20
12
20
12
24
20
12
20
12
24
20
12
20
12
24

it looks like 20,12,20,12,24 is repeated many times, and i have no idea why.

A simpler code such as this one:

ISR(TIMER2_OVF_vect){
  Serial.println(micros());
}

outputs this:

1236
1332
1428
1524
1620
1716
1812

From this code it looks like 96usec pass between two consectuive ISRs. How strange.

According to my calculations, the ISR should be executed every 25usec, because 1/40 000 = 0,000 025.

Do you have any idea why i get these strange results? How can i calculate time elapsed precisely?

A serial.print is a very very slow thing, and it is not good to put one inside one isr.

I see. That indeed could explain that 96usec delay between ISRs. But in the first code, since i expected that Serial.print could be somehow affecting the ISR, i used the 2 variables "now" and "previous" before calling Serial.print, so actual measurements of elapsed time shouldn't be affected by that.

Still with the first method i get different results. I guess the result 24 is ok, but why 12 and 20? 12 (or 20) usecs would mean a much higher frequency, while i've set it at 40KHz and that should be around 25usecs.

Declare an array of values, and in the ISR, put the calculated value into the array and increment the index.
After the index gets up to some pre-determined value, print out the contents of the array.

That's a neat way to do it! Thanks, i'll try and then post the results.

Make the ISR non-blocking.

Eg:

ISR(TIMER2_OVF_vect, ISR_NOBLOCK){
...
}

This will ensure the time is not disabled temporarily while the previous is still running.

But like the others said, the Serial.print will probably not finish during an iteration of the ISR.

But like the others said, the Serial.print will probably not finish during an iteration of the ISR.

Serial.begin(9600);

just change to

Serial.begin(115200);

to make it more likely that the serial printing will finish in time. Choose the same speed at the bottom of the Serial monitor window.

Thank you for all those nice replies.
I've tried both making my serial transmission faster, and using an array and i do get much better results now : mostly 24 and some 28 now and then.

And coolest of all: thanks to leppie i've discovered ISR_NOBLOCK. It won't really help me in calculating the speed (looks like the ISR is fast enough to end before another one begins, as i get the same results) but it will help me a lot for my lasertag project.

Thanks to all your answers i was able to complete my code snippet for sending IR remote codes in background which you can find here: Arduino Playground - MultiIR

Thank you once again!