Mfcttrf

I wrote a simple loop to test the processor speed on my Arduino Uno. The numbers I'm getting are much worse than the 16MHz advertised, by a factor of ~5. Trying to figure out what I'm missing.

long counter = 0;
int sum = 0;
uint32_t t = 0;

void setup() 
 Serial.begin(9600);
 t = micros();


void loop() 
 sum += counter;

 if (counter == 10000) 
 float usecsPerIteration = (micros() - t) / (counter * 1.0);
 Serial.print(usecsPerIteration);
 Serial.println(" microseconds per iteration");

 // Print result to avoid loop getting optimized away
 Serial.println(sum);
 

 ++counter;

The output is:

3.77 microseconds per iteration

Here's how I'm estimating clock rate from this. The body of the loop involves two additions and an equality check. Even if we assume that these simple operations take 10 clock cycles, the implied clock rate is still just (1 iter / 3.77 us) * (1e6 us / sec) * (10 cycles / iter) = 2.65 MHz.

What am I missing?

As Michael says there is a lot more going on than you think.

Firstly there are interrupts triggering which can slow things down (used to calculate milllis()).

Secondly you vastly under estimate the number of instructions that are being called. For a start the loop is being called from a for(;;) loop in main():

 for (;;) {
 loop();
 572: 0e 94 73 00 call 0xe6 ; 0xe6 <loop>
 if (serialEventRun) serialEventRun();
 576: 20 97 sbiw r28, 0x00 ; 0
 578: e1 f3 breq .-8 ; 0x572 <main+0x10>
 57a: 0e 94 1d 01 call 0x23a ; 0x23a <_Z14serialEventRunv>
 57e: f9 cf rjmp .-14 ; 0x572 <main+0x10>

Then for the call to loop() the registers used get pushed to the stack, then your code executed, and the registers popped off again before returning. This is the code for loop when disassembled:

000000e6 <loop>:
 // Save the registers to the stack
 e6: cf 92 push r12
 e8: df 92 push r13
 ea: ef 92 push r14
 ec: ff 92 push r15

 // Add to the sum
 ee: 40 91 44 01 lds r20, 0x0144 ; 0x800144 <counter>
 f2: 50 91 45 01 lds r21, 0x0145 ; 0x800145 <counter+0x1>
 f6: 60 91 46 01 lds r22, 0x0146 ; 0x800146 <counter+0x2>
 fa: 70 91 47 01 lds r23, 0x0147 ; 0x800147 <counter+0x3>
 fe: 80 91 42 01 lds r24, 0x0142 ; 0x800142 <sum>
 102: 90 91 43 01 lds r25, 0x0143 ; 0x800143 <sum+0x1>
 106: 84 0f add r24, r20
 108: 95 1f adc r25, r21
 10a: 90 93 43 01 sts 0x0143, r25 ; 0x800143 <sum+0x1>
 10e: 80 93 42 01 sts 0x0142, r24 ; 0x800142 <sum>

 // Check the value to see if it's time to print
 112: 40 31 cpi r20, 0x10 ; 16
 114: 57 42 sbci r21, 0x27 ; 39
 116: 61 05 cpc r22, r1
 118: 71 05 cpc r23, r1
 11a: d1 f5 brne .+116 ; 0x190 <loop+0xaa>

 // From here on is the "IF" section
 11c: 0e 94 f5 04 call 0x9ea ; 0x9ea <micros>
 120: c0 90 3e 01 lds r12, 0x013E ; 0x80013e <__data_end>
 124: d0 90 3f 01 lds r13, 0x013F ; 0x80013f <__data_end+0x1>
 128: e0 90 40 01 lds r14, 0x0140 ; 0x800140 <__data_end+0x2>
 12c: f0 90 41 01 lds r15, 0x0141 ; 0x800141 <__data_end+0x3>
 130: 6c 19 sub r22, r12
 132: 7d 09 sbc r23, r13
 134: 8e 09 sbc r24, r14
 136: 9f 09 sbc r25, r15
 138: 0e 94 68 06 call 0xcd0 ; 0xcd0 <__floatunsisf>
 13c: 6b 01 movw r12, r22
 13e: 7c 01 movw r14, r24
 140: 60 91 44 01 lds r22, 0x0144 ; 0x800144 <counter>
 144: 70 91 45 01 lds r23, 0x0145 ; 0x800145 <counter+0x1>
 148: 80 91 46 01 lds r24, 0x0146 ; 0x800146 <counter+0x2>
 14c: 90 91 47 01 lds r25, 0x0147 ; 0x800147 <counter+0x3>
 150: 0e 94 6a 06 call 0xcd4 ; 0xcd4 <__floatsisf>
 154: 9b 01 movw r18, r22
 156: ac 01 movw r20, r24
 158: c7 01 movw r24, r14
 15a: b6 01 movw r22, r12
 15c: 0e 94 c7 05 call 0xb8e ; 0xb8e <__divsf3>
 160: ab 01 movw r20, r22
 162: bc 01 movw r22, r24
 164: 22 e0 ldi r18, 0x02 ; 2
 166: 30 e0 ldi r19, 0x00 ; 0
 168: 88 e4 ldi r24, 0x48 ; 72
 16a: 91 e0 ldi r25, 0x01 ; 1
 16c: 0e 94 a9 04 call 0x952 ; 0x952 <_ZN5Print5printEdi>
 170: 60 e0 ldi r22, 0x00 ; 0
 172: 71 e0 ldi r23, 0x01 ; 1
 174: 88 e4 ldi r24, 0x48 ; 72
 176: 91 e0 ldi r25, 0x01 ; 1
 178: 0e 94 0b 03 call 0x616 ; 0x616 <_ZN5Print7printlnEPKc>
 17c: 60 91 42 01 lds r22, 0x0142 ; 0x800142 <sum>
 180: 70 91 43 01 lds r23, 0x0143 ; 0x800143 <sum+0x1>
 184: 4a e0 ldi r20, 0x0A ; 10
 186: 50 e0 ldi r21, 0x00 ; 0
 188: 88 e4 ldi r24, 0x48 ; 72
 18a: 91 e0 ldi r25, 0x01 ; 1
 18c: 0e 94 b0 03 call 0x760 ; 0x760 <_ZN5Print7printlnEii>

 // All this is just counter++
 190: 80 91 44 01 lds r24, 0x0144 ; 0x800144 <counter>
 194: 90 91 45 01 lds r25, 0x0145 ; 0x800145 <counter+0x1>
 198: a0 91 46 01 lds r26, 0x0146 ; 0x800146 <counter+0x2>
 19c: b0 91 47 01 lds r27, 0x0147 ; 0x800147 <counter+0x3>
 1a0: 01 96 adiw r24, 0x01 ; 1
 1a2: a1 1d adc r26, r1
 1a4: b1 1d adc r27, r1
 1a6: 80 93 44 01 sts 0x0144, r24 ; 0x800144 <counter>
 1aa: 90 93 45 01 sts 0x0145, r25 ; 0x800145 <counter+0x1>
 1ae: a0 93 46 01 sts 0x0146, r26 ; 0x800146 <counter+0x2>
 1b2: b0 93 47 01 sts 0x0147, r27 ; 0x800147 <counter+0x3>

 // Get the registers back and return
 1b6: ff 90 pop r15
 1b8: ef 90 pop r14
 1ba: df 90 pop r13
 1bc: cf 90 pop r12
 1be: 08 95 ret

That's more than 10 instructions. I make it 55 clocks to run one full iteration. (counter++ alone is 19 clock cycles - nearly double your estimation for the total...)

You have to remember two important things:

• AVR is a RISC CPU - that means that seemingly simple operations can take multiple instructions to perform.


• AVR is an 8-bit CPU - that means that working with any variables bigger than 8 bits in size require far more complex code, and you work with 32-bit variables (and floats, but that's outside the timing loop section of your code).

The loop function is called within the framework of the Arduino IDE.
Beyond the code you write, also an interrupt check is done, which also cost time, and explains the difference.

The following function CAN be called after every loop call.
See Majenko's answer about the details.

/*
 SerialEvent occurs whenever a new data comes in the hardware serial RX. This
 routine is run between each time loop() runs, so using delay inside loop can
 delay response. Multiple bytes of data may be available.
*/
void serialEvent() 
 while (Serial.available()) 
 // get the new byte:
 char inChar = (char)Serial.read();
 // add it to the inputString:
 inputString += inChar;
 // if the incoming character is a newline, set a flag so the main loop can
 // do something about it:
 if (inChar == 'n') 
 stringComplete = true;
 
 

See SerialEvent for more info.

However, as Kwasmich's comment says, you can easily circumvent this by performing your test inside a while loop.