Mr. Integral
Embedded notes/Building and Running Firmware/Debugging and Measurement

UNIT 06 · LESSON 6 OF 6

Measuring Timing Without Disturbing It

How do you time code precisely while disturbing it as little as possible?

INTERACTIVEThe cost of looking
The time taken by the measured code and by the measurement itselfone pass through the loopmeasurementprintf over a UART: 2.08 ms (24 characters × 10 bits ÷ 115 200 baud, if printf waitsfor the UART)added to 50 µs of real work: 41.7× extraThe loop now runs at the speed of the UART. Timing-dependent bugs change or disappear:the measurement has become the behaviour.
The time taken by the measured code and by the measurement itselfone pass through the loopmeasurementprintf over a UART: 2.08 ms (24 characters × 10 bits÷ 115 200 baud, if printf waits for the UART)added to 50 µs of real work: 41.7× extraThe loop now runs at the speed of the UART.Timing-dependent bugs change or disappear: themeasurement has become the behaviour.

Try this

Method
UART baud rate
printf over a UART: 2.08 ms overhead on 50 µs of work.

Every measurement method adds work to the code it measures. A blocking printf costs the transmission time of its characters (10 bits each for 8N1 framing); a pin toggle or a counter read costs a few cycles. The cycle counts here are illustrative; measure your own by timing an empty region.

What you will be able to do
  • Estimate the overhead of a blocking printf, a GPIO marker and a counter read, and compare it with the code being measured.
  • Explain the probe effect and why timing bugs can disappear when you add instrumentation.
  • Enable and read a cycle counter on an Armv7-M core, and choose an alternative on a Cortex-M0+.
  • Compute a counter’s wrap time and decide whether an interval can be measured with it.
  • Correct a measurement for its own overhead by timing an empty region.
Before you start
  • Logic analysers and oscilloscopes (lesson 5).
  • Clocks and execution time (unit 3, lesson 6); unsigned wrap-around (unit 2, lesson 2).
Steps in this lesson
  1. Every measurement costs time
  2. Counters: cycles and timers
  3. Worked example: timing a 50 µs filter
  4. Common misconceptions

The puzzle

A control loop must finish in 100 µs. You add a printf of the elapsed time at the end, and the loop starts missing its deadline, or a bug that appeared once an hour vanishes as soon as the print is in. Measuring changed the thing being measured. How do you time code precisely while disturbing it as little as possible?

STEP 1

Every measurement costs time

Instrumentation is code, and it runs inside the thing you are measuring. How much it costs decides whether the measurement is honest:

↑ This step uses the figure at the top of the page.

  • printf over a UART costs the transmission time of its characters if it waits for the UART: with 8N1 framing each character is 10 bits, so at 115 200 baud a 24-character line takes about 2 ms. Buffered or interrupt-driven output moves the cost elsewhere but does not remove it.
  • Semihosting is worse: each call is a trap instruction that stops the core while the debugger services it on the host, and without a debugger attached the BKPT escalates to a HardFault and the program crashes.
  • A GPIO marker, one pin write before and one after, costs a few cycles; a logic analyser or scope measures the pulse (lesson 5).
  • A counter read costs a load and a subtraction and gives the answer inside the program.

The probe effect is the name for measurements that change behaviour. Timing bugs, races between an interrupt and the main loop, are especially sensitive: add 2 ms of printing and the race window moves. Prefer instruments whose cost is a few cycles, and keep them in the build that has the bug.

STEP 2

Counters: cycles and timers

Armv7-M cores (Cortex-M3, M4, M7) usually have a 32-bit cycle counter, DWT->CYCCNT, counting core clock cycles. It is off after reset; enable trace in DEMCR and then the counter:

DCB->DEMCR |= DCB_DEMCR_TRCENA_Msk;   /* CoreDebug->DEMCR in older CMSIS */
DWT->CYCCNT = 0;
DWT->CTRL  |= DWT_CTRL_CYCCNTENA_Msk;

uint32_t t0 = DWT->CYCCNT;
filter_step();
uint32_t cycles = DWT->CYCCNT - t0;               /* correct across one wrap */

Some implementations leave it out (DWT_CTRL.NOCYCCNT reads 1), and on some Cortex-M7 parts DWT writes are ignored until the lock access register is unlocked (DWT->LAR = 0xC5ACCE55). Armv6-M cores (Cortex-M0, M0+) have no cycle counter at all. There, use SysTick (24 bits, counting down, so elapsed = (then − now) & 0xFFFFFF with the reload at 0xFFFFFF; an RTOS usually sets a shorter reload for its tick) or a peripheral timer. The RP2040, for example, has a 64-bit timer that counts microseconds; the SDK reads its two halves in a retry loop so a carry between them cannot be missed.

INTERACTIVEWhen does the counter wrap?
A counter’s width and frequency, its wrap time and whether an interval can be measured with itcounter32 bits at 125 MHzwraps every34.4 sinterval10 swhole periods lost0The unsigned difference modulo 2³² gives the right answer: the interval is shorterthan one wrap period.
A counter’s width and frequency, its wrap time and whether an interval can be measured with itcounter32 bits at 125 MHzwraps every34.4 sinterval10 swhole periods lost0The unsigned difference modulo 2³² gives the rightanswer: the interval is shorter than one wrapperiod.
Counter
Core clock (SysTick, cycle counter)
32-bit counter wraps every 34.4 s; a 10 s interval is measured correctly.

A free-running counter of n bits at f Hz wraps after 2ⁿ/f seconds. Subtracting two readings as unsigned n-bit numbers gives the right interval if, and only if, the interval is shorter than one wrap period. Counters shown: a 24-bit SysTick (reload 0xFFFFFF, clocked by the core; it counts down, so elapsed = (then − now) & 0xFFFFFF), a 32-bit cycle counter (DWT CYCCNT on Armv7-M; the Cortex-M0+ has none) and the RP2040’s 64-bit microsecond timer.

A counter of n bits at frequency f wraps every

twrap=2nft_{\text{wrap}} = \frac{2^{n}}{f}

Subtracting two readings as unsigned n-bit numbers gives the right answer whenever the interval is shorter than one wrap period, even if the counter passed through zero in between, because unsigned arithmetic is modulo 2ⁿ (unit 2, lesson 2). An interval of one wrap period or longer comes out silently short by whole periods. For a 24-bit counter the subtraction must also be masked to 24 bits.

STEP 3

Worked example: timing a 50 µs filter

The filter runs every millisecond on a Cortex-M4 at 168 MHz.

With printf of a 24-character line at 115 200 baud, blocking:

t=24×10115 200≈2.08 mst = \frac{24 \times 10}{115\,200} \approx 2.08\ \text{ms}

The loop now takes 2.13 ms and misses every 1 ms deadline; the measurement has become the behaviour.

With the cycle counter: an empty region measures 6 cycles and the filter reads 8 406 cycles, so the filter takes 8 400 cycles:

t=8400168×106 Hz=50 μst = \frac{8400}{168 \times 10^6\ \text{Hz}} = 50\ \mu\text{s}

The counter wraps every 2³²/168 MHz ≈ 25.6 s, far longer than the interval, so the unsigned subtraction is safe. Printing the result once per second, outside the loop, costs nothing in the loop itself.

MYTHS AND FACTS

Common misconceptions

printf is fine, it is only one line

At 115 200 baud a line costs milliseconds, often far more than the code being timed.

Every Cortex-M has a cycle counter

Armv6-M cores do not, and some Armv7-M implementations leave it out.

Counter wrap breaks timing

Unsigned subtraction handles passing through zero; only intervals of one wrap period or longer need care.

One measurement is the answer

Caches, wait states and interrupts spread the results; look at the minimum, typical and maximum.

If the bug disappears with instrumentation, it is fixed

It has moved: the instrumentation changed the timing.

Check yourself

Answer in your head, then open the card.

How long does a blocking printf of 40 characters take at 9600 baud?

40 × 10 / 9600 ≈ 41.7 ms.

SysTick is used as a free-running 24-bit counter at 48 MHz. What is the longest interval it can measure with one subtraction?

2²⁴ / 48 MHz ≈ 0.35 s (minus one tick), assuming the reload is 0xFFFFFF: any interval of one wrap period or more comes out short by whole periods.

The cycle counter reads 1 000 cycles for an empty region on the first pass and 6 on later passes. Why?

The first pass fetched the measuring code and data from flash or missed in the cache; later passes ran from the cache or prefetch buffer. Discard the first pass or report it separately.

A race between an interrupt and the main loop disappears when you add a printf. What do you use instead?

A GPIO marker toggled in the interrupt and in the main loop, captured on a logic analyser: a few cycles of overhead instead of milliseconds, so the timing of the race is barely changed.

Sources (4)
  1. Arm, CMSIS 6, CMSIS/Core/Include/core_cm4.h and core_cm0plus.h — DWT CYCCNT at offset 0x004 (“Cycle Count Register”), DWT_CTRL CYCCNTENA (bit 0) and NOCYCCNT (bit 25), DCB DEMCR TRCENA (bit 24, trace enable); the ITM for trace output; core_cm0plus.h defines no DWT or CYCCNT; SysTick LOAD and VAL are 24-bit (SysTick_LOAD_RELOAD_Msk 0xFFFFFF)
  2. Raspberry Pi Ltd, pico-sdk 1.5.1, src/rp2_common/hardware_timer/include/hardware/timer.h — “single 64-bit counter, incrementing once per microsecond” with a “latching two-stage read of counter, for race-free read over 32 bit bus” (the SDK’s time_us_64() in timer.c reads the raw high and low halves in a retry loop instead); time_us_32() returns the low 32 bits (timerawl); alarms match the low 32 bits, “~72 minutes” ahead at most
  3. Arm, Semihosting for AArch32 and AArch64 (abi-aa, semihosting/semihosting.rst) — semihosting calls are trap instructions (on M-profile BKPT #0xAB, 0xBEAB) that “the debug agent then handles”; SYS_WRITEC (0x03) and SYS_WRITE0 (0x04) print through the host
  4. OpenOCD, src/target/cortex_m.h — DWT_CTRL at 0xE0001000 and DEMCR TRCENA (bit 24), as used by the debug server; halting and resuming go through DHCSR