This is an example for Arduino using the clockCyclesPerMicrosecond() function to calculate the clocks that have passed. This code will wait 4 seconds, then print the time passed since start of program. Left 3 values are total time (microseconds, milliseconds, total clock cycles) and right most 3 are elapsed times:
Output:
clocks for 1us:16
runtime us, ms, ck :: elapsed tme us, ms ck
4003236 4002 64051776 :: 4003236 4002 64051760
8006668 8006 128106688 :: 4003432 4004 64054912
12010508 12010 192168128 :: 4003840 4004 64061440
16014348 16014 256229568 :: 4003840 4004 64061440
20018188 20018 320291008 :: 4003840 4004 64061440
24022028 24022 384352448 :: 4003840 4004 64061440
28026892 28026 448430272 :: 4004864 4004 64077824
32030732 32030 512491712 :: 4003840 4004 64061440
36034572 36034 576553152 :: 4003840 4004 64061440
40038412 40038 640614592 :: 4003840 4004 64061440
44042252 44042 704676032 :: 4003840 4004 64061440
48046092 48046 768737472 :: 4003840 4004 64061440
52050956 52050 832815296 :: 4004864 4004 64077824
I'm sure there is a reasonable explanation why the first too loops had shorter elapsed clock cycles than most and why all other loops toggle between two lengths of clock cycles.
Code:
unsigned long us, ms, ck;
unsigned long _us, _ms, _ck;
unsigned long __us, __ms, __ck;
void setup() {
Serial.begin(9600);
}
boolean firstloop=1;
void loop() {
delay(4000);
if (firstloop) {
Serial.print("clocks for 1us:");
ck=microsecondsToClockCycles(1);
Serial.println(ck,DEC);
firstloop--;
Serial.println("runtime us, ms, ck :: elapsed tme us, ms ck");
}
_us=us;
_ms=ms;
_ck=ck;
us=micros(); // us since program start
ms=millis();
//ms=us/1000;
ck=microsecondsToClockCycles(us);
Serial.print(us,DEC);
Serial.print("\t");
Serial.print(ms,DEC);
Serial.print("\t");
Serial.print(ck,DEC);
Serial.print("\t::\t");
__us = us - _us;
__ms = ms - _ms;
__ck = ck - _ck;
Serial.print(__us,DEC);
Serial.print("\t");
Serial.print(__ms,DEC);
Serial.print("\t");
Serial.println(__ck,DEC);
}
Sidenote:
if you remove the 4 second delay you will start to see the effects of the Serial.print() much more clearly. Note, here 2 runs are compared. I've only included 4 samples near each other from their respective logs.
Run 1:
5000604 5000 80009664 :: 2516 2 40256
6001424 6001 96022784 :: 2520 3 40320
7002184 7002 112034944 :: 2600 3 41600
8001292 8001 128020672 :: 2600 3 41600
Run 2:
5002460 5002 80039360 :: 2524 3 40384
6000728 6000 96011648 :: 2520 2 40320
7001452 7001 112023232 :: 2600 3 41600
8000552 8000 128008832 :: 2604 3 41664
The elapsed time increases over total run time. After a second has elapsed the clocks increase on average from 40k to 44k. This happens consistently a few milliseconds after 1 second and the elapsed clocks remains around 44k for at least the next 10 seconds (I havent tested it further). This is why monitoring is useful or needed. Perhaps the decreased efficiency has to do with configuration or bugs in serial? Or perhaps the code is not using memory properly and has a leak that effects performance, etc.
