Program timing with micros()

Projects Programming
1

if I run the code below, I get the following output. Can someone explain why the 'delta' value degenerates like that? I am missing something, obviously.

Thanks

delta 140
delta 212
delta 212
delta 212
delta 212
delta 220
delta 5168
delta 13536
delta 14576
delta 14576
delta 14576
delta 14576
delta 14576
... etc.

typedef unsigned long usl;

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

int counter(25);
usl lastMicro(0);
usl delta(0);

void loop() {
    while (counter > 0)
    {             
      delta = micros() - lastMicro;
      lastMicro = micros();

      Serial.print("delta  ");              
      Serial.println(delta);
      counter--;
    }
}
2

Probably because at 9600 Baud it takes roughly 1ms to transmit 1 character over serial. The buffer probably fills up making Serial.print blocking.

What happens with a higher Baud rate?

3

Essentially the same. The buffer fills in about same number of steps, except it just happens more quickly.

If I store the results in an array and dump it after the loop I get useful results. A couple of '4's in there are interesting.

140
8
8
8
8
8
8
8
8
4
4
8
8
8
...

4

I ran your original code on a Nano Every with the Baud rate set at 9600 and got this:

18:00:12.674 -> delta  144
18:00:12.674 -> delta  212
18:00:12.674 -> delta  212
18:00:12.714 -> delta  212
18:00:12.714 -> delta  220
18:00:12.714 -> delta  220
18:00:12.754 -> delta  5156
18:00:12.754 -> delta  13508
18:00:12.754 -> delta  14548
18:00:12.794 -> delta  14548
18:00:12.794 -> delta  14544
18:00:12.794 -> delta  14548
18:00:12.834 -> delta  14552
18:00:12.834 -> delta  14544
18:00:12.834 -> delta  14548
18:00:12.874 -> delta  14548
18:00:12.874 -> delta  14548
18:00:12.874 -> delta  14548
18:00:12.914 -> delta  14548
18:00:12.914 -> delta  14544
18:00:12.954 -> delta  14552
18:00:12.954 -> delta  14548
18:00:12.954 -> delta  14544
18:00:12.994 -> delta  14548
18:00:12.994 -> delta  14548

I ran it with the Baud rate at 230400 and got:


17:51:42.675 -> delta  144
17:51:42.675 -> delta  248
17:51:42.675 -> delta  256
17:51:42.675 -> delta  256
17:51:42.675 -> delta  264
17:51:42.675 -> delta  248
17:51:42.675 -> delta  248
17:51:42.675 -> delta  256
17:51:42.675 -> delta  264
17:51:42.675 -> delta  256
17:51:42.675 -> delta  256
17:51:42.675 -> delta  256
17:51:42.675 -> delta  480
17:51:42.675 -> delta  516
17:51:42.675 -> delta  504
17:51:42.675 -> delta  520
17:51:42.675 -> delta  504
17:51:42.675 -> delta  516
17:51:42.675 -> delta  512
17:51:42.675 -> delta  512
17:51:42.675 -> delta  516
17:51:42.675 -> delta  512
17:51:42.675 -> delta  512
17:51:42.675 -> delta  516
17:51:42.675 -> delta  512

I thought I'd try the other extreme, so here is the result with the Baud rate at 2400:
(I tried lower rates than 2400 but they don't work at all on the Nano Every)

17:54:40.044 -> delta  144
17:54:40.124 -> delta  220
17:54:40.164 -> delta  212
17:54:40.204 -> delta  212
17:54:40.244 -> delta  220
17:54:40.324 -> delta  216
17:54:40.364 -> delta  23880
17:54:40.404 -> delta  58212
17:54:40.484 -> delta  58212
17:54:40.524 -> delta  58212
17:54:40.604 -> delta  58212
17:54:40.644 -> delta  58212
17:54:40.724 -> delta  58212
17:54:40.764 -> delta  58212
17:54:40.844 -> delta  58212
17:54:40.884 -> delta  58212
17:54:40.964 -> delta  58212
17:54:41.004 -> delta  58212
17:54:41.044 -> delta  58216
17:54:41.124 -> delta  58208
17:54:41.164 -> delta  58216
17:54:41.244 -> delta  58208
17:54:41.284 -> delta  58216
17:54:41.364 -> delta  58212
17:54:41.404 -> delta  58212

I think that confirms that the serial port becoming blocked with queued data is the cause of what you are seeing. Compare the last result at 2400 Baud: delta 58212, which is 58 milliseconds, to the last result at 230400 Baud: delta 512, which is half a millisecond.

I note that 14 characters are being printed each time and the delta at 9600 Baud is about 14 milliseconds, which compares well to it taking about 1 millisecond to transmit 1 character at 9600 Baud.

Unless someone else knows different :thinking:

5

No, you've nailed it, Perry. The buffer is full. It's not a matter of cranking the baud up, unfortunately, because that just fills the buffer faster. If you drop a 20 ms delay in the main loop the OP posted, no over flow happens.

@kmanuele You do understand what's happening, correct? If this is an artificial test, just file away the knowledge. If you need to time the processor activities, you'll need to find a smarter way to communicate the results.

6

Thanks for that, and I am certain you are correct.

My tests were run on a Nano Every also, which I use at my desk for testing.

Uno in the shop gives similar results.

K

7

Yes, understand.

It was an artificial test to understand where/why my main code was bogging down.

Once I removed all the repeating Serial.print() code, it is running at full speed.

thanks

K

8

This topic was automatically closed 180 days after the last reply. New replies are no longer allowed.