What does Arduino do in 15ms?

Question

I was wondering why there is a 15 ms delay between each iteration of a the main loop.

Code: The following code shows the execution time expressed in microsec between each loop

void setup()
{
 Serial.begin(9600);
}
void loop()
{
 Serial.println();
 Serial.print("Start: ");
 Serial.print(micros());
 Serial.print("/////////////////////");
 Serial.print("End:");
 Serial.print(micros()); 
}

Output:

Start: 789452/////////////////////End:821692
Start: 837292/////////////////////End:869532
Start: 885132/////////////////////End:917372
Start: 932972/////////////////////End:965212

Arduino needs 32,240 msec to print the messages to serial and to call the micros() function twice. And this it's fine. Now, considering the difference between the values of the End and the following Start, one question arises:

What does Arduino do between each loop?

Answer 1

Your serial connection is set to 9600 baud, which is 9600 actual data bits per second. The communication consists (*) of 8 bit characters and every bit is useful data (no parity), so you would be able to achieve at most 9600 / 8 = 1200 characters per second.

You have a message of 46 characters including the line break, which brings you to 1200 / 46 = 26 iterations per second.

1000 milliseconds / 26 iterations = about 39 milliseconds per iterations.

This is the theoretic maximum you would get if you would send the data over serial without any other overhead. Pretty close to the 32 + 15 = 47 milliseconds you measured.

Since you print a part of the message (Enter + 'Start:') between the end of the previous iteration and the start of the next (if you take the call to micros() as the start and end), it makes sense that a part of the time is in between there as well.

So the actual overhead you are looking at is about 8ms per iteration. This delay is spread out over the loop and the call overhead of the various functions you use. After all, when you call Serial.print, a lot of work needs to be done before the data can actually be sent to the serial port. You would probably gain more speed/less overhead if you would construct one big string, and send it with a single print command.

Arduino itself is slow, but still much faster than this. It should be able to do a big(ger) number of iterations per second, but you basically limited it by initialising the serial connection to such a slow speed. You can partially eliminate this by picking a higher number. I think both your Arduino and any modern serial port should be able to handle 115200 baud. Nevertheless, you will always have a relatively big overhead when you are sending data over serial. Use your bandwidth wisely, and reduce the number of calls to Serial.print as much as you reasonably can.

* ) 8 bit, no parity is the de facto default. See Serial.begin() for more information about initializing the serial connection.

• John Burger: Note that the 9600 figure is "bits per second", not "baud". You are right that "baud" means "actual data bits" (as opposed to overhead bits, such as start, parity and stop bits), but that distinction is often lost - and in this case incorrect. Each character is 10 bits - 1 start, 8 data, and 1 stop - so the correct number is 960 characters per scond.
• GolezTrol: @JohnBurger Thanks for that addition. The default setting is indeed 8 data bits and 1 stop bit, no parity, so with a start bit that would be 10 bits per character indeed. You can by the way configure this in the optional second parameter of Serial.begin(). Anyway, the documentation says 'bits per second (baud)', so if you are right, then the docs are wrong (or I misunderstood something).
• Solomon Slow: @JohnBurger, The distinction between "baud rate" and "bit rate" is not about which bits are data, and which bits are framing. The "baud rate" on a wire tells how many times per second the line state changes. When there are only two line states (usually called "0" and "1", or "mark" and "space"), then the baud rate equals the bit rate. But when you're using modems for long-distance comms, there can be four or eight line states, and the baud rate then is 1/2 or 1/3 of the effective bit rate. All most of us ever care about is effective bit rate. Baud rate is for modem designers.
• John Burger: @jameslarge Huh. I was taught what I explained above nearly 30 years ago. I can find other articles on the web with the same misunderstanding (or indeed the opposite w.r.t. bps vs baud!) - but all the scholarly articles agree with your description. Apologies @GolezTrol!
• John Burger: Also note that "how many times per second the line state changes" isn't completely correct either: it should be "...the line state could change". A series of 0 or 1 bits (for NRZ encoding) would not involve line state changes, but the number of bits sent would still go up.

Answer 2

Just check the sourcecode

for (;;) {
 loop();
 if (serialEventRun) serialEventRun();
}

So it does a check if serialEventRun is True, and then a jump back to the beginning of the for-loop. And then a call to loop.

Also note that Serial.print is blocking if the TX-buffer is full. So you might want to add a delay somewhere to ensure the buffer is never full.

Answer 3

Your code is slightly off if you want to accurately time this

Serial.print("End:");
Serial.print(micros()); 

Will get micros() before printing to serial, and then take the time to print it. You also print some text before taking the time at the top of the loop. Your 15 ms is the time to print these to serial between reading micros. For example, change the loop code to something like this:

uint32_t time, endTime;
...
void loop(){
 time = micros();
 Serial.print(endTime);
 Serial.print('\t');
 Serial.print(time);
 Serial.print('\n');
 endTime = micros();
}

and you should only see a small difference. It showed a 4 microsecond difference when I ran it. The only other thing that runs outside the loop is the serial event handlers, but if you don't use one it obviously doesn't take long.

Answer 4

TL;DR: The delays you measure (32.24 ms between Start and End, and 15.6 ms between End and Start) are exactly what is expected from the amount of data you send through the serial port. Yes, exactly: there is zero overhead from the CPU doing other things.

Let me show how the expected timings can be computed. First, a note about the exact baud rate. A rate of 9600 bps implies that each bit takes about 104.17 μs to send. However, the Arduino being clocked at 16 MHz, it cannot achieve this exact baud rate. Instead, when you request 9600 bps, you get the closest value it can achieve, which is about 9615 bps. Then, each bit takes exactly 104 μs. Or at least "exactly" as per the Arduino clock: it really takes 1664 CPU cycles.

Then, as already noted in previous answers, one character is worth 10 raw bits. It thus needs 1040 μs to be transmitted.

Now, let's look at your code. It should be noted that

Serial.print(micros());

is compiled into something equivalent to

unsigned long timestamp = micros();
Serial.print(timestamp);

i.e. the timestamp is taken and then it is transmitted. Your loop() is then equivalent to:

void loop()
{
 Serial.println(); // 2 chars: CR and LF
 Serial.print("Start: "); // 7 chars
 unsigned long time_start = micros();
 Serial.print(time_start); // 6 chars
 Serial.print("/////////////////////"); // 21 chars
 Serial.print("End:"); // 4 chars
 unsigned long time_end = micros();
 Serial.print(time_end); // 6 chars
}

By folding the last Serial.print() of one iteration into the beginning of the next one, one gets the pseudo-code:

forever {
 print 15 chars; // 15*1040 = 15600 μs
 read time_start;
 print 31 chars; // 31*1040 = 32240 μs
 read time_end;
}

The computed durations match exactly your printout. This shows that, once the Serial output buffer is full, the timing of your code execution is completely governed by how fast the UART sends the bits out the line. The time taken by the Arduino to do actual CPU work (calling micros(), formatting numbers...) is irrelevant because the CPU works in parallel with the UART and, being faster, it ends up waiting for the UART anyway.

• Peter Mortensen: Re "zero overhead from the CPU": Because there is hardware transmit buffer (even if it is only one slot)?
• Edgar Bonet: @PeterMortensen: Indeed. The one-byte hardware buffer and the larger software buffer, combined, ensure that the UART is never stalled, waiting for the CPU to provide data to send. Without the hardware buffer, the latency of the "USART data register empty" interrupt would show up in the transmission.

Answer 5

At 9600now each data byte needs 10 bits to be transmit. Or 1ms per byte.

20 bytes will take 20me to transmit.

However, the existence of a buffer and the way the transmission is carried out can greatly impact the duration of execution of your code - actual time for transmission is invariant however.

If your transmission is done via the interrupt, the execution can be almost instantaneous.

• Edgar Bonet: "the existence of a buffer and the way the transmission is carried out can greatly impact the duration of execution of your code". In the OP's example, this is true only at the very beginning. Once the output buffer is full, the timing of the code execution is entirely dictated by the UART.
• Peter Mortensen: ("me" → "ms")