Counting CPU cycles with `DWT->CTRL` does not match expectations

[microbit-carlos]

This programme counts CPU cycles during uBit.sleep(1000), so at 64 MHz it should return around ~ 64M, however it returns ~11M: MICROBIT.hex.zip

#include "MicroBit.h"

MicroBit uBit;

static inline void start_ticks_cpu() {
    CoreDebug->DEMCR |= CoreDebug_DEMCR_TRCENA_Msk;
    DWT->CYCCNT = 0;
    DWT->CTRL |= DWT_CTRL_CYCCNTENA_Msk;
}

static inline uint32_t ticks_cpu() {
    return DWT->CYCCNT;
}

int main() {
    uBit.init();

    start_ticks_cpu();

    while (true) {
        int32_t ms_start = uBit.systemTime();
        int32_t ticks_start = ticks_cpu() & 0x7FFFFFFF;
        uBit.sleep(1000);
        int32_t ticks_end = ticks_cpu() & 0x7FFFFFFF;
        int32_t ms_end = uBit.systemTime();
        uBit.serial.printf("diff: %d (start[%d] end[%d] total_ms[%d])\n",
            ticks_end - ticks_start, ticks_start, ticks_end, ms_end - ms_start);

        if (uBit.buttonA.isPressed()) {
            uBit.radio.enable();
            uBit.serial.send("radio on\n");
            uBit.sleep(1000);
        }
        uBit.sleep(100);
    }
}

Pressing button A runs uBit.radio.enable(), which switches to the high precission crystal, which affects the result slightly, but not by much:

diff: 10985466 (start[149980986] end[160966452] total_ms[1000])
diff: 11007362 (start[162471352] end[173478714] total_ms[1000])
diff: 11039938 (start[174988106] end[186028044] total_ms[1000])
diff: 11044228 (start[187496056] end[198540284] total_ms[1000])
radio on
diff: 11208778 (start[211322670] end[222531448] total_ms[1000])
diff: 11205384 (start[224039870] end[235245254] total_ms[1000])
diff: 11149570 (start[236786282] end[247935852] total_ms[1000])
diff: 11205105 (start[249466406] end[260671511] total_ms[1000])

[microbit-carlos]

Okay, this is slightly weird, I noticed that when the micro:bit is flashed via OpenOCD it does seem to calculate the right number of cycles, but pressing the reset button .

Command to just connect and disconnect.

$ openocd -f interface/cmsis-dap.cfg -f target/nrf52.cfg -c "init; shutdown;"

Running that command half way through we can see the value correcting, and pressing the reset button goes back to 11M cycles (output edited for clarify):

diff: 11010094 (start[1102032821] end[1113042915] total_ms[1000])   ❌
diff: 11030543 (start[1114566139] end[1125596682] total_ms[1000])   ❌
diff: 11056992 (start[1127088277] end[1138145269] total_ms[1000])   ❌
diff: 11003962 (start[1139662063] end[1150666025] total_ms[1000])   ❌
                                                                    OpenOCD connect->disconnect
diff: 49241226 (start[1152185823] end[1201427049] total_ms[1000])   🟠 
diff: 63999758 (start[1208339303] end[1272339061] total_ms[1000])   ✅
diff: 63999770 (start[1279251291] end[1343251061] total_ms[1000])   ✅
diff: 63999122 (start[1350163939] end[1414163061] total_ms[1000])   ✅
diff: 64000614 (start[1421075343] end[1485075957] total_ms[1000])   ✅
                                                                    reset button pressed
diff: 11045372 (start[1555487999] end[1566533371] total_ms[1000])   ❌
diff: 11034320 (start[1568063501] end[1579097821] total_ms[1000])   ❌
diff: 11015106 (start[1580615485] end[1591630591] total_ms[1000])   ❌

[microbit-carlos]

As mentioned in https://github.com/microbit-foundation/micropython-microbit-v2/issues/179#issuecomment-2042706755, the reason the cycles count is lower is because the CPU goes to sleep with uBit.sleep() and it only counts cycles while it's running.