Skip to content

Lab 25: How Long Did That Take?

Time: ~40 minutes | Prerequisites: Lab 24 | Hardware: Pico 2

A stopwatch that counts clock ticks

Echo waving welcome We're about to start shaving percentages off an FFT, and microseconds are too blunt for that. Hidden in your Cortex-M33 is a counter that ticks once per CPU clock — every 6.667 nanoseconds. Let's switch it on. Time to transform!

What You'll Build

Cycle-accurate timing read straight from a hardware register, verified against a known delay, and used to measure operations far too small for ticks_us() to see.

Learning Objectives

  • Recognise when ticks_us() resolution is insufficient
  • Enable the DWT cycle counter by setting two register bits
  • Verify a counter is running before trusting it
  • Measure operations smaller than the measurement overhead
  • Handle 32-bit counter wraparound

Concepts Introduced

ID Concept
443 Millisecond Timer
444 Microsecond Timer
445 Timer Resolution
446 Counter Wraparound
447 Cycle Counter
448 DWT Unit
449 CYCCNT Register
450 DEMCR Register
451 Register Bit Manipulation
452 Cycles To Microseconds
453 Counter Verification

Background

Two registers, two bits

1
2
3
DEMCR      0xE000EDFC   bit 24 (TRCENA)     enable the trace unit
DWT_CTRL   0xE0001000   bit 0  (CYCCNTENA)  enable the cycle counter
DWT_CYCCNT 0xE0001004                       the counter itself

Fixed by ARM, identical on every Cortex-M33, reachable from MicroPython with machine.mem32 — the same technique you used in Lab 3 to read CPUID.

Verify, don't assume

On some implementations this counter only runs while a debugger is attached. A stalled counter reports 0 cycles for everything, which looks like infinitely fast code.

Check it against a known delay: sleep 100 ms, count the cycles, divide. If it doesn't come out near your clock speed, don't believe anything below it.

An instrument that reads zero looks like success

Echo warning This is the nastiest failure mode in measurement: the broken result is indistinguishable from a spectacular one. Always sanity-check a stopwatch against something whose duration you already know.

Procedure

Step 1 — See the limit of ticks_us

Part 1 times a single addition ten times. You get 1 or 2 µs — and nearly all of that is the cost of calling ticks_us twice. The measurement is bigger than the thing measured.

Step 2 — Enable and verify

  1
  2
  3
  4
  5
  6
  7
  8
  9
 10
 11
 12
 13
 14
 15
 16
 17
 18
 19
 20
 21
 22
 23
 24
 25
 26
 27
 28
 29
 30
 31
 32
 33
 34
 35
 36
 37
 38
 39
 40
 41
 42
 43
 44
 45
 46
 47
 48
 49
 50
 51
 52
 53
 54
 55
 56
 57
 58
 59
 60
 61
 62
 63
 64
 65
 66
 67
 68
 69
 70
 71
 72
 73
 74
 75
 76
 77
 78
 79
 80
 81
 82
 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
# Lab 25: How Long Did That Take?
#
# Lab 24 measured stages in microseconds and that was fine. But we are about
# to start shaving small percentages off an FFT, and ticks_us() cannot see
# differences that small.
#
# Hidden inside your Cortex-M33 is a counter that ticks once per CPU CLOCK.
# At 150 MHz that is one tick every 6.667 nanoseconds -- a thousand times
# finer than a microsecond. It lives in the DWT (Data Watchpoint and Trace)
# unit, and we can read it straight from MicroPython.

import machine
import time

# These addresses are fixed by ARM. Every Cortex-M33 has them here.
DEMCR = 0xE000EDFC          # Debug Exception and Monitor Control Register
DWT_CTRL = 0xE0001000       # DWT Control Register
DWT_CYCCNT = 0xE0001004     # the cycle counter itself

TRCENA = 1 << 24            # DEMCR bit 24: switch on the trace unit
CYCCNTENA = 1 << 0          # DWT_CTRL bit 0: switch on the counter


# =========================================================================
# PART 1 -- what ticks_us can and cannot see
# =========================================================================
print("=== PART 1: the limits of a microsecond timer ===")
print()
print("Timing something very short, ten times:")
for trial in range(10):
    t0 = time.ticks_us()
    x = 1 + 1                       # about as small as work gets
    t1 = time.ticks_us()
    print("  trial %d: %d us" % (trial, time.ticks_diff(t1, t0)))
print()
print("Mostly 1 or 2 microseconds -- and most of that is the cost of")
print("CALLING ticks_us twice, not the addition. At this scale the")
print("measurement is bigger than the thing being measured.")


# =========================================================================
# PART 2 -- switching on the cycle counter
# =========================================================================
print()
print("=== PART 2: turning on the DWT cycle counter ===")
print()
print("Two bits in two registers:")
print("  DEMCR    bit 24 (TRCENA)    -> enable the trace unit")
print("  DWT_CTRL bit 0  (CYCCNTENA) -> enable the cycle counter")
print()

print("DEMCR before : %s" % hex(machine.mem32[DEMCR]))
machine.mem32[DEMCR] = machine.mem32[DEMCR] | TRCENA
print("DEMCR after  : %s" % hex(machine.mem32[DEMCR]))

print("CTRL before  : %s" % hex(machine.mem32[DWT_CTRL]))
machine.mem32[DWT_CTRL] = machine.mem32[DWT_CTRL] | CYCCNTENA
print("CTRL after   : %s" % hex(machine.mem32[DWT_CTRL]))

print()
print("Read it twice in a row:")
a = machine.mem32[DWT_CYCCNT]
b = machine.mem32[DWT_CYCCNT]
print("  %d then %d  (moved by %d cycles)" % (a, b, b - a))
print()
print("It is counting. Those few cycles between the two reads are the cost")
print("of the reads themselves.")


# =========================================================================
# PART 3 -- VERIFY it, do not just trust it
# =========================================================================
print()
print("=== PART 3: verify before you trust ===")
print()
print("On some chips this counter only runs while a debugger is attached.")
print("A stalled counter reports 0 cycles for everything, which looks")
print("like infinitely fast code. Check it against a known delay.")
print()

t0 = time.ticks_us()
c0 = machine.mem32[DWT_CYCCNT]
time.sleep_ms(100)
c1 = machine.mem32[DWT_CYCCNT]
t1 = time.ticks_us()

cycles = (c1 - c0) & 0xFFFFFFFF
micros = time.ticks_diff(t1, t0)
mhz = cycles / micros

print("cycles counted over ~100 ms : %d" % cycles)
print("microseconds elapsed        : %d" % micros)
print("implied clock               : %.2f MHz" % mhz)
print("machine.freq() says         : %.2f MHz" % (machine.freq() / 1e6))
print()
if mhz < 1:
    print("COUNTER IS STALLED -- do not trust any timing below this line.")
else:
    print("Agrees with the real clock. The counter is trustworthy.")


# =========================================================================
# PART 4 -- now measure something small
# =========================================================================
print()
print("=== PART 4: measuring things ticks_us cannot see ===")
print()


import math


def read():
    return machine.mem32[DWT_CYCCNT]


REPS = 2000

# Measuring ONE operation is hopeless: a MicroPython function call costs
# thousands of cycles, which swamps the thing you wanted to measure. So we
# run each operation REPS times inside a single timed region, subtract the
# cost of an empty loop of the same length, and divide.
#
# This is the standard trick for measuring anything smaller than your
# measurement apparatus.

start = read()
for i in range(REPS):
    pass
empty = (read() - start) & 0xFFFFFFFF

results = []

start = read()
for i in range(REPS):
    x = 1 + 1
results.append(("integer add", (read() - start) & 0xFFFFFFFF))

start = read()
for i in range(REPS):
    x = 3.7 * 2.1
results.append(("float multiply", (read() - start) & 0xFFFFFFFF))

start = read()
for i in range(REPS):
    x = 3.7 / 2.1
results.append(("float divide", (read() - start) & 0xFFFFFFFF))

start = read()
for i in range(REPS):
    x = math.sqrt(2.0)
results.append(("math.sqrt", (read() - start) & 0xFFFFFFFF))

start = read()
for i in range(REPS):
    x = math.cos(1.0)
results.append(("math.cos", (read() - start) & 0xFFFFFFFF))

freq = machine.freq()
print("Each operation run %d times, empty loop subtracted." % REPS)
print("Empty loop costs %d cycles (%.1f per iteration).\n"
      % (empty, empty / REPS))
print("%-18s %14s %12s" % ("operation", "cycles each", "nanoseconds"))
for label, total in results:
    net = (total - empty) / REPS
    print("%-18s %14.1f %12.0f" % (label, net, net * 1e9 / freq))

print()
print("A float multiply is about %.0f cycles. The RP2350 hardware can do"
      % ((results[1][1] - empty) / REPS))
print("one in a single cycle -- so almost all of that is the interpreter")
print("fetching bytecode, boxing objects and checking types.")
print()
print("That gap is the entire subject of Modules 6 and 7.")


# =========================================================================
# PART 5 -- the 32-bit wrap
# =========================================================================
print()
print("=== PART 5: the counter wraps ===")
print()
print("CYCCNT is 32 bits, so it overflows every 2^32 cycles:")
print("  2^32 / %.0f MHz = %.1f seconds" % (freq / 1e6, 2**32 / freq))
print()
print("Subtracting with a 32-bit mask handles the wrap correctly:")
print("    elapsed = (end - start) & 0xFFFFFFFF")
print()
print("Without the mask a measurement that straddles the wrap comes out")
print("hugely negative. With it, anything shorter than %.1f seconds is fine."
      % (2**32 / freq))

1
2
3
4
5
cycles counted over ~100 ms : 14934446
implied clock               : 149.94 MHz
machine.freq() says         : 150.00 MHz

Agrees with the real clock. The counter is trustworthy.

Step 3 — Measure the unmeasurable

A single operation is still hopeless to time directly — a MicroPython function call costs thousands of cycles. The standard trick: run it many times inside one timed region, subtract an empty loop, divide.

1
2
3
4
5
operation             cycles each  nanoseconds
integer add                 123.1          820
float multiply             1097.3         7315
math.sqrt                  2156.2        14375
math.cos                   2016.6        13444

Step 4 — Absorb what that means

The RP2350's FPU multiplies two floats in one cycle. MicroPython takes 1,097.

Roughly a thousand cycles of fetching bytecode, checking types, allocating objects and unboxing values — to wrap one instruction of real work.

Cross-check it against Lab 20

Echo thinking A 512-point FFT does about 23,000 float operations. At ~1,000 cycles each that's ~23 million cycles ≈ 150 ms — which is almost exactly the 145 ms Lab 20 measured. Two independent measurements agreeing is how you know you understand a system.

Step 5 — Mind the wrap

CYCCNT is 32 bits, so it overflows every 2³²/150 MHz ≈ 28.6 seconds. Mask the subtraction and anything shorter than that is measured correctly:

1
elapsed = (end - start) & 0xFFFFFFFF

Expected Output

The four sections above. Your cycle counts will vary slightly; the ~150 MHz verification and the ~1,000-cycles-per-float-multiply result should hold.

Troubleshooting

Symptom Likely cause Fix
Counter always 0 TRCENA not set Set DEMCR bit 24 before DWT_CTRL bit 0
Implied clock ~0 Counter stalled Don't trust any timing; investigate first
Huge negative elapsed Wrap without mask & 0xFFFFFFFF
Per-op costs look enormous Overhead not subtracted Subtract the empty-loop baseline

Challenges

  1. Time your FFT. Measure Lab 20's 512-point FFT in cycles. How does it compare to 145 ms?
  2. Cost of a call. Measure an empty function call. How many float multiplies is it worth?
  3. Force a wrap. Time something longer than 28.6 seconds and watch the mask save you.

Check Your Understanding

  1. Which two bits must be set, in which registers, to start the counter?
  2. Why verify the counter instead of trusting it?
  3. Why can't you time a single float multiply directly?
  4. A float multiply takes ~1,097 cycles in MicroPython. What does the hardware need?
  5. When does the wraparound mask matter?

Now you can see the small stuff

Echo celebrating A precise instrument, verified. Next lab: four ways it will still lie to you — and how to stop it.

Next: Lab 26: Benchmarking Methodology | Previous: Lab 24