From 36c6671768a6d6cac94186d7b89641bf12cbf730 Mon Sep 17 00:00:00 2001 From: Jacob Dahl Date: Mon, 15 Jun 2026 17:39:08 -0600 Subject: [PATCH] feat(profiling): flag-gated ISR cycle/CPU-load harness for F051 Cortex-M0 has no DWT->CYCCNT and no ITM/SWO, so ISR cost is measured two canonical ways, both driven from one instrumentation point and gated behind PROFILE_ISR (off by default, production builds stay byte-identical): - GPIO marker (optional pin) held high while an instrumented ISR runs, for aggregate CPU load on a logic analyzer / scope. - TIM17 repurposed at PSC=0 as a 48 MHz free-running counter (1 tick per core cycle); per-ISR last/max/sum cycle counts land in prof_* arrays read over SWD or telemetry. TIM17 is otherwise unused on the F051. scripts/profile_swd.py reads those counters live through a running OpenOCD (non-halting, safe while the motor spins) and prints per-ISR CPU load, average/worst-case microseconds, and call rate. Wraps the four hot ISRs: comparator zero-cross (ADC1_COMP), 20 kHz control loop (TIM6), DShot decode (EXTI4_15), and TIM14. Cherry-pick onto a perf/feature branch to compare CPU headroom at a given eRPM. --- Inc/profiling.h | 90 +++++++++++++++++++++ Mcu/f051/Src/peripherals.c | 2 + Mcu/f051/Src/stm32f0xx_it.c | 36 ++++++++- scripts/profile_swd.py | 152 ++++++++++++++++++++++++++++++++++++ 4 files changed, 279 insertions(+), 1 deletion(-) create mode 100644 Inc/profiling.h create mode 100755 scripts/profile_swd.py diff --git a/Inc/profiling.h b/Inc/profiling.h new file mode 100644 index 000000000..ea39134c4 --- /dev/null +++ b/Inc/profiling.h @@ -0,0 +1,90 @@ +/* + * profiling.h + * + * Lightweight ISR cycle profiling for the flash-/cycle-constrained F051. + * + * Cortex-M0 has no DWT->CYCCNT and no ITM/SWO, so the two canonical ways to + * measure ISR cost are (a) a GPIO toggled around the ISR, read on a logic + * analyzer / scope, and (b) a free-running timer used as a poor-man's cycle + * counter. This header does BOTH from one instrumentation point: + * + * - GPIO marker: a pin is driven HIGH while any instrumented ISR runs, so the + * wire shows aggregate ISR (CPU) load. Optional; needs a free pad. + * - Cycle counter: TIM17 (otherwise unused on the F051) is repurposed as a + * 48 MHz free-running counter -> 1 tick == 1 core cycle. Per-ISR last/max + * cycle counts land in arrays you read over SWD (watch prof_cyc_max[]) or + * stream over telemetry. + * + * All of this compiles to nothing unless PROFILE_ISR is defined, so production + * builds are byte-for-byte identical. + * + * Caveat: a measured duration includes any higher-priority ISR that preempts + * the region. The comparator zero-cross is the highest-priority motor ISR, so + * its numbers are clean; lower-priority regions read as wall-clock (which is + * usually what you want for a "can it keep up" budget). + */ + +#ifndef PROFILING_H_ +#define PROFILING_H_ + +/* ---- turn the harness on for a measurement build ------------------------- + * Define here, per-target in targets.h, or pass -DPROFILE_ISR to make. */ +// #define PROFILE_ISR + +/* ---- optional logic-analyzer marker pin ---------------------------------- + * Point these at a pad broken out on your board (e.g. the serial-telemetry + * pin with telemetry disabled for the run). Leave undefined for counters-only + * measurement over SWD. */ +// #define PROFILE_GPIO_PORT GPIOB +// #define PROFILE_GPIO_PIN LL_GPIO_PIN_6 + +#ifdef PROFILE_ISR +#include "main.h" + +enum { + PROF_COMP_ZC = 0, /* ADC1_COMP_IRQHandler -> interruptRoutine (zero-cross) */ + PROF_20KHZ, /* TIM6_DAC_IRQHandler -> tenKhzRoutine (control) */ + PROF_DSHOT, /* EXTI4_15_IRQHandler -> processDshot (decode) */ + PROF_TIM14, /* TIM14_IRQHandler -> PeriodElapsedCallback */ + PROF_N +}; + +extern volatile uint16_t prof_cyc_last[PROF_N]; /* last duration, core cycles */ +extern volatile uint16_t prof_cyc_max[PROF_N]; /* worst case since boot */ +extern volatile uint32_t prof_cyc_sum[PROF_N]; /* running cycle total (wraps) */ +extern volatile uint32_t prof_calls[PROF_N]; /* invocation count */ + +void profiling_init(void); /* repurposes TIM17 as a 48 MHz counter + marker pin */ + +__attribute__((always_inline)) static inline uint16_t prof_enter(void) +{ +#ifdef PROFILE_GPIO_PORT + PROFILE_GPIO_PORT->BSRR = PROFILE_GPIO_PIN; /* marker high */ +#endif + return (uint16_t)TIM17->CNT; +} + +__attribute__((always_inline)) static inline void prof_exit(int i, uint16_t t0) +{ + uint16_t d = (uint16_t)((uint16_t)TIM17->CNT - t0); +#ifdef PROFILE_GPIO_PORT + PROFILE_GPIO_PORT->BRR = PROFILE_GPIO_PIN; /* marker low */ +#endif + prof_cyc_last[i] = d; + if (d > prof_cyc_max[i]) + prof_cyc_max[i] = d; + prof_cyc_sum[i] += d; + prof_calls[i]++; +} + +/* Wrap a region: PROF_ENTER(PROF_20KHZ); ...work...; PROF_EXIT(PROF_20KHZ); */ +#define PROF_ENTER(i) uint16_t _pt_##i = prof_enter() +#define PROF_EXIT(i) prof_exit((i), _pt_##i) + +#else /* !PROFILE_ISR */ +#define profiling_init() ((void)0) +#define PROF_ENTER(i) ((void)0) +#define PROF_EXIT(i) ((void)0) +#endif + +#endif /* PROFILING_H_ */ diff --git a/Mcu/f051/Src/peripherals.c b/Mcu/f051/Src/peripherals.c index 8b12fd3cb..bd8c5cfee 100644 --- a/Mcu/f051/Src/peripherals.c +++ b/Mcu/f051/Src/peripherals.c @@ -12,6 +12,7 @@ #include "ADC.h" #include "serial_telemetry.h" #include "targets.h" +#include "profiling.h" void initCorePeripherals(void) { @@ -28,6 +29,7 @@ void initCorePeripherals(void) MX_TIM6_Init(); MX_TIM17_Init(); UN_TIM_Init(); + profiling_init(); // no-op unless PROFILE_ISR is defined #ifdef USE_SERIAL_TELEMETRY telem_UART_Init(); #endif diff --git a/Mcu/f051/Src/stm32f0xx_it.c b/Mcu/f051/Src/stm32f0xx_it.c index b89a96dbd..aef19115e 100644 --- a/Mcu/f051/Src/stm32f0xx_it.c +++ b/Mcu/f051/Src/stm32f0xx_it.c @@ -27,6 +27,7 @@ #include "ADC.h" #include "targets.h" #include "common.h" +#include "profiling.h" extern void transfercomplete(); extern void PeriodElapsedCallback(); @@ -44,6 +45,31 @@ extern volatile char armed; extern volatile char out_put; /* USER CODE END EV */ +#ifdef PROFILE_ISR +volatile uint16_t prof_cyc_last[PROF_N]; +volatile uint16_t prof_cyc_max[PROF_N]; +volatile uint32_t prof_cyc_sum[PROF_N]; +volatile uint32_t prof_calls[PROF_N]; + +// Repurpose TIM17 (unused on the F051: MX_TIM17_Init never enables its counter +// and nothing reads it) as a 48 MHz free-running cycle counter, and configure +// the optional logic-analyzer marker pin. +void profiling_init(void) +{ + LL_APB1_GRP2_EnableClock(LL_APB1_GRP2_PERIPH_TIM17); + TIM17->PSC = 0; // 48 MHz -> 1 tick per core cycle + TIM17->ARR = 0xFFFF; + TIM17->EGR = TIM_EGR_UG; // latch the prescaler + TIM17->CR1 |= TIM_CR1_CEN; // free-running +#ifdef PROFILE_GPIO_PORT + LL_GPIO_SetPinMode(PROFILE_GPIO_PORT, PROFILE_GPIO_PIN, LL_GPIO_MODE_OUTPUT); + LL_GPIO_SetPinOutputType(PROFILE_GPIO_PORT, PROFILE_GPIO_PIN, LL_GPIO_OUTPUT_PUSHPULL); + LL_GPIO_SetPinSpeed(PROFILE_GPIO_PORT, PROFILE_GPIO_PIN, LL_GPIO_SPEED_FREQ_HIGH); + PROFILE_GPIO_PORT->BRR = PROFILE_GPIO_PIN; +#endif +} +#endif + uint16_t interrupt_time = 0; /******************************************************************************/ /* Cortex-M0 Processor Interruption and Exception Handlers */ @@ -194,8 +220,10 @@ void ADC1_COMP_IRQHandler(void) if (LL_EXTI_IsActiveFlag_0_31(LL_EXTI_LINE_21) != RESET) { if((INTERVAL_TIMER->CNT) > ((average_interval>>1))){ EXTI->PR = EXTI_LINE; + PROF_ENTER(PROF_COMP_ZC); interruptRoutine(); - }else{ + PROF_EXIT(PROF_COMP_ZC); + }else{ if (getCompOutputLevel() == rising){ EXTI->PR = EXTI_LINE; } @@ -210,7 +238,9 @@ void TIM6_DAC_IRQHandler(void) { if (LL_TIM_IsActiveFlag_UPDATE(TIM6) == 1) { LL_TIM_ClearFlag_UPDATE(TIM6); + PROF_ENTER(PROF_20KHZ); tenKhzRoutine(); + PROF_EXIT(PROF_20KHZ); } } @@ -220,7 +250,9 @@ void TIM6_DAC_IRQHandler(void) void TIM14_IRQHandler(void) { LL_TIM_ClearFlag_UPDATE(TIM14); + PROF_ENTER(PROF_TIM14); PeriodElapsedCallback(); + PROF_EXIT(PROF_TIM14); } /** @@ -310,7 +342,9 @@ void TIM1_BRK_UP_TRG_COM_IRQHandler(void) void EXTI4_15_IRQHandler(void) { LL_EXTI_ClearFlag_0_31(LL_EXTI_LINE_15); + PROF_ENTER(PROF_DSHOT); processDshot(); + PROF_EXIT(PROF_DSHOT); } /* USER CODE END 1 */ diff --git a/scripts/profile_swd.py b/scripts/profile_swd.py new file mode 100755 index 000000000..ed4effff6 --- /dev/null +++ b/scripts/profile_swd.py @@ -0,0 +1,152 @@ +#!/usr/bin/env python3 +""" +profile_swd.py - live readout of the PROFILE_ISR counters over SWD. + +The F051 (Cortex-M0) has no DWT/SWO, so the profiling harness (Inc/profiling.h) +times each hot ISR with TIM17 as a 48 MHz cycle counter and accumulates the +results into RAM globals. This script reads those globals through a running +OpenOCD over its Tcl RPC port and turns them into per-ISR CPU load, average and +worst-case microseconds, and call rate. + +Reads go through the debug access port and do NOT halt the core, so it is safe +to run while the motor is spinning (no commutation glitch, no watchdog reset). + +Usage: + 1. Build with PROFILE_ISR enabled and flash the board. + 2. Start OpenOCD (its Tcl port 6666 is on by default): + openocd -f Mcu/f051/openocd.cfg + (or just leave your VS Code / Cortex-Debug session running) + 3. Run this against the matching ELF: + scripts/profile_swd.py obj/AM32_ARK_4IN1_F051_2.20.elf + +Options: + --host/--port OpenOCD Tcl RPC endpoint (default 127.0.0.1:6666) + --interval seconds between samples (default 1.0) + --cpu-mhz core clock for cycle->time conversion (default 48) + --nm path to nm (default arm-none-eabi-nm) + +Requires OpenOCD >= 0.11 (for the `read_memory` command). +""" +import argparse +import re +import socket +import subprocess +import sys +import time + +# enum order in Inc/profiling.h +LABELS = ["comp_zc(ADC1_COMP)", "20khz(TIM6)", "dshot(EXTI4_15)", "tim14"] +U32 = 0xFFFFFFFF + + +class OpenOcdTcl: + """Minimal OpenOCD Tcl RPC client (commands terminated by 0x1a).""" + SEP = b"\x1a" + + def __init__(self, host, port): + self.sock = socket.create_connection((host, port), timeout=5) + + def cmd(self, command): + self.sock.sendall(command.encode() + self.SEP) + buf = bytearray() + while not buf.endswith(self.SEP): + chunk = self.sock.recv(4096) + if not chunk: + raise ConnectionError("OpenOCD closed the connection") + buf.extend(chunk) + return buf[:-1].decode(errors="replace") + + def read_words(self, addr, width, count): + # read_memory returns a space-separated list of decimal values + out = self.cmd(f"read_memory 0x{addr:08x} {width} {count}") + return [int(tok, 0) for tok in out.split()] + + def close(self): + try: + self.sock.close() + except OSError: + pass + + +def resolve_symbols(nm, elf, names): + """Return {name: (addr, size_bytes)} via `nm -S`.""" + try: + out = subprocess.check_output([nm, "-S", "--radix=d", elf], text=True) + except (OSError, subprocess.CalledProcessError) as e: + sys.exit(f"failed to run {nm} on {elf}: {e}") + syms = {} + for line in out.splitlines(): + # " " + m = re.match(r"(\d+)\s+(\d+)\s+\S\s+(\S+)", line) + if m and m.group(3) in names: + syms[m.group(3)] = (int(m.group(1)), int(m.group(2))) + missing = [n for n in names if n not in syms] + if missing: + sys.exit(f"symbols not found in {elf} (build with PROFILE_ISR?): {missing}") + return syms + + +def main(): + ap = argparse.ArgumentParser(description="Live SWD readout of PROFILE_ISR counters.") + ap.add_argument("elf", help="ELF built with PROFILE_ISR") + ap.add_argument("--host", default="127.0.0.1") + ap.add_argument("--port", type=int, default=6666) + ap.add_argument("--interval", type=float, default=1.0) + ap.add_argument("--cpu-mhz", type=float, default=48.0) + ap.add_argument("--nm", default="arm-none-eabi-nm") + args = ap.parse_args() + + cyc_per_us = args.cpu_mhz + cpu_hz = args.cpu_mhz * 1e6 + + syms = resolve_symbols(args.nm, args.elf, ["prof_cyc_max", "prof_cyc_sum", "prof_calls"]) + count = syms["prof_calls"][1] // 4 or len(LABELS) + labels = (LABELS + [f"isr{i}" for i in range(len(LABELS), count)])[:count] + + try: + ocd = OpenOcdTcl(args.host, args.port) + except OSError as e: + sys.exit(f"cannot reach OpenOCD Tcl port {args.host}:{args.port} ({e}); " + f"is OpenOCD running with `-f Mcu/f051/openocd.cfg`?") + + def sample(): + return ( + ocd.read_words(syms["prof_cyc_sum"][0], 32, count), + ocd.read_words(syms["prof_calls"][0], 32, count), + ocd.read_words(syms["prof_cyc_max"][0], 16, count), + ) + + print(f"# reading {count} ISR counters @ {args.cpu_mhz:g} MHz, every {args.interval:g}s " + f"(Ctrl-C to stop)") + prev_sum, prev_calls, _ = sample() + prev_t = time.monotonic() + try: + while True: + time.sleep(args.interval) + cur_sum, cur_calls, cur_max = sample() + now = time.monotonic() + dt = now - prev_t + + print(f"\n=== dt={dt:.2f}s ===") + print(f"{'ISR':22}{'rate(Hz)':>10}{'avg(us)':>9}{'max(us)':>9}{'CPU%':>8}") + total = 0.0 + for i in range(count): + dcalls = (cur_calls[i] - prev_calls[i]) & U32 + dsum = (cur_sum[i] - prev_sum[i]) & U32 + rate = dcalls / dt + load = 100.0 * dsum / (dt * cpu_hz) + avg_us = (dsum / dcalls) / cyc_per_us if dcalls else 0.0 + max_us = cur_max[i] / cyc_per_us + total += load + print(f"{labels[i]:22}{rate:10.0f}{avg_us:9.2f}{max_us:9.2f}{load:8.1f}") + print(f"{'TOTAL (instrumented)':22}{'':>10}{'':>9}{'':>9}{total:8.1f}") + + prev_sum, prev_calls, prev_t = cur_sum, cur_calls, now + except KeyboardInterrupt: + print("\nstopped") + finally: + ocd.close() + + +if __name__ == "__main__": + main()