Serial print executing several times per loop

Projects General Guidance
1

I'm trying to measure the execution time of different functions, and I'm using serial print. However, I noticed the function printing several times per loop iteration, rather than only once. I would be grateful for any help to try to understand why.

/**************************************************************************/
void setup(void) {
  // sensor_setup ();
  // radio_setup ();
  SerialUSB.begin(115200);
}

/**************************************************************************/
// timing measurement
unsigned long time1 = 0;
unsigned long time2 = 0;

void loop(void) {
  time1 = micros();
  // get_sensor_data ();
  delay(5);
  time2 = micros();
  SerialUSB.print("time:");
  SerialUSB.println(time2 - time1);
}

serial
serial1776×968 97.2 KB

2

Post code, in code tags, not pictures.

3

Done!

4

Hello

It's not printing more than once per loop, it's just that the Serial monitor is not as fast as you expect :slight_smile:

1 Like
5

add SerialUSB.flush(); after SerialUSB.println(time2 - time1);

1 Like
6

@guix and @Juraj thank you for the insight. I'll test this later today! Would you say this is the "best" way to measure execution time of a function?

edit: so if it's not printing several times per loop, then is it looping through several times per print? I just don't get why it looks like it prints several times per iteration. If it's not fast enough, wouldn't that mean it would print old data, but with new timestamps each time? What's confusing is the timestamps make it seem that several prints are happening at the same time stamp, even though the function is called only once per loop.

7

Look at your selection and the timestamps in the Serial monitor:

  • the timestamp of the selection is .282
  • the timestamp of the line above the selection is .228
  • the timestamp of the line after the selection is .329
  • and there are 9 lines printed before the timestamp has changed,

( 329 - 282 ) / 9 = ~5ms
( 282 - 228 ) / 9 = ~5ms

1 Like
8

...but the code should be printing 5000, no?

9

sorry I changed to micros to see if any difference, but same result, just printing 5000 as you said.

10

Thank you for the input, I'm being a bit daft here (sorry!) but I still don't get why it's printing it several times instead of just once? I can understand from your explanation why the data would be the same, but why would it print it several times instead of just once?

11

I'm just saying that the timestamps shown in the Serial monitor is not very accurate, it does not show the exact time when the message was received. It's not updated every millisecond

If you are still not convinced, just print the value of millis(), you will see that each line is unique

SerialUSB.print("time:");
SerialUSB.print(time2 - time1);
SerialUSB.print(" millis:");
SerialUSB.println(millis());
1 Like
12

Thanks for the clarification. I was just curious why, but you're right.

14

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