diff options
| -rw-r--r-- | .claude/skills/etm-trace/SKILL.md | 199 | ||||
| -rw-r--r-- | .claude/skills/etm-trace/boards.md | 134 | ||||
| -rw-r--r-- | .claude/skills/etm-trace/scripts/etm_capture.py | 567 | ||||
| -rw-r--r-- | .claude/skills/etm-trace/scripts/etm_profile.py | 428 |
4 files changed, 1328 insertions, 0 deletions
diff --git a/.claude/skills/etm-trace/SKILL.md b/.claude/skills/etm-trace/SKILL.md new file mode 100644 index 000000000..8affe13ec --- /dev/null +++ b/.claude/skills/etm-trace/SKILL.md @@ -0,0 +1,199 @@ +--- +name: etm-trace +description: Use when you need instruction-level execution data from real hardware via a SEGGER J-Trace — cycle-accurate hot-function profiling, on-target code coverage, or raw instruction history (e.g. what ran right before a fault/hang) — beyond what logs, GDB, or DWT PC-sampling can answer. Covers unattended (headless) capture and analysis on ETM-capable TinyUSB boards. +--- + +# etm-trace — unattended ETM instruction trace via J-Trace + Ozone + +Streams full instruction (ETM) trace from a board wired to a SEGGER J-Trace, +headlessly: no GUI, scripted end to end. Produces hot-function profile, code +coverage, and optionally the raw instruction history. + +| Skill | Answers | +|--------------------|----------------------------------------------------------------------------| +| `usbmon` | what the host actually exchanged (URBs) | +| `usb-target-debug` | what the device did (logs, driver state, sampled PCs) | +| `usb-sniffer` | what crossed the wire | +| **`etm-trace`** | **exactly which instructions executed, when** (profile, coverage, history) | + +Use `usb-target-debug`'s DWT PC-sampling for a quick statistical profile; use +this skill for exact counts, coverage, or instruction-by-instruction history. + +## Requirements + +- J-Trace on USB (`lsusb -d 1366:1020`) wired to the board's trace header; + select it by J-Link USB **nickname** (this rig: `jtrace`) — never commit + serials. +- `ozone` on PATH (≥ V3.38 for the automation socket) and `xvfb-run`. +- Firmware built with **`-DTRACE_ETM=1`** (BSP trace-pin + trace-clock init). +- Boards with a reference `hw/bsp/*/boards/<board>/ozone/*.jdebug` work out of + the box (`ls` that glob for the list); others fall back to `JLINK_DEVICE` + from `board.cmake` + default trace config. Verified boards: `boards.md` in + this skill directory. + +## Rig discipline + +- One probe, one client: quit interactive Ozone/JLinkExe/GDB on the probe + first. Kill only processes you started — if it's held by someone else's + session (check `fuser /dev/bus/usb/<bus>/<dev>`), surface it and ask. The + capture script uses automation port **19201**, never an interactive Ozone's + 19200. +- Hold the board lock (see the `hil` skill): + `python3 test/hil/board_lock.py hold <board> --reason "etm capture"`. +- Committed `hw/bsp/**/ozone/*.jdebug` are the maintainer's interactive + projects — automation never opens them (Ozone rewrites project files); the + script generates a throwaway project. +- The default capture reflashes and resets the target (`--attach` doesn't). + +## Capture and analyze + +```bash +# 1. Build with trace support: +cd examples && cmake -B cmake-build-<board> -DBOARD=<board> -G Ninja \ + -DCMAKE_BUILD_TYPE=MinSizeRel -DTRACE_ETM=1 . \ + && cmake --build cmake-build-<board> --target <example> + +# 2. Capture (all options + defaults: etm_capture.py --help): +python3 .claude/skills/etm-trace/scripts/etm_capture.py \ + --board <board> --probe jtrace --duration-ms 10000 --out <dir> + +# 3. Analyze (hot functions, coverage, hottest lines, optimization hints): +python3 .claude/skills/etm-trace/scripts/etm_profile.py <dir> --elf <elf> +``` + +Every capture — TinyUSB firmware or vendor demo — goes through +`etm_capture.py`; extend it when a board needs something new, never +hand-roll Ozone drivers. + +Choosing capture flags (semantics in `--help`): +- fresh-boot profile/coverage: defaults (flash + reset + trace from startup) +- narrowing debug on a LIVE target: `--attach` — no reflash/reset (flashed + firmware must match `--elf` and be TRACE_ETM-built) +- raw history: `--trace-csv` (~80 MB/1M instructions) — when sequence/timing + matters, e.g. feeding `--isr` +- stream dies (overflow/unknown-packet): `--no-timestamps`, then reduce the + core clock (`boards.md`); marginal wiring: sweep `--trace-timing`, + isolate lines with `--trace-width`. "capture OK" requires nonzero profile + totals — silence (no trace at all) fails with its own error +- deeper data: `--profile-lines-csv` (hottest lines), `--profile-insts-csv` + (branch bias), `--sample "expr,.."` (data sampling), `--power` (probe-powered + targets only), `--os-plugin` (RTOS timeline), `--trace-only` (experimental, + see Warnings) +- non-TinyUSB targets: `--device` + `--elf`, plus `--jlink-script` when the + firmware doesn't init the trace pins + +First trace on a board — or after any rewiring — is a bring-up, not a plain +capture: follow "Adding a new board" below (vendor example first). + +Analyzer: `--isr ENTRY[,BODY..]` gives ISR min/median/avg/worst from a +`--trace-csv` capture with timestamps (fast-enumerating boards need a short +no-eviction run); `--exclude REGEX` drops idle/poll loops from the load +ranking. + +Outputs in `<dir>`: `code_profile.txt` (run/fetch counts + coverage); on +request `itrace.csv`, `profile_lines.csv`, `profile_insts.csv`, `samples.csv`, +`power.csv`; `session.log` / `ozone_console.log` / `jlink.log` as evidence. + +## Reading results + +- **Load %** = share of instruction **fetches** — Ozone has no per-function + time; time comes only from itrace timestamps (`--isr`, time-share table). +- ISR timing: sub-µs values are approximate (interpolated timestamps — hence + the SysTick calibration); instruction counts are exact. Time-share ≫ + instruction-share = stalled/waiting (e.g. slave-mode FIFO at wire pace). +- "Fully covered" needs both branch directions — 100% is not expected from an + idle run. +- itrace timestamps scale by `VAR_TRACE_CORE_CLOCK` (from the board reference; + `--core-clock` overrides): ordering is exact, absolute times approximate. +- A ms+ "largest gap" or `Trace overflow detected` beyond the startup burst = + lost packets — reduce the core clock or trace a quieter phase. +- One `Invalid trace timestamp` line at `Debug.Halt` is a normal decoder + artifact. +- `Unknown trace data packet … Trace collection stopped!` = stream dead from + that point (the script exits non-zero): retry with `--no-timestamps`, then + reduce the core clock. + +## Timing + +- Capture ≈ `--duration-ms` + 15 s overhead; add ~5 s per 1M instructions with + `--trace-csv`. Bash timeout: duration + 120000 ms. +- Analyzer: < 5 s for a 2M-row itrace.csv. + +## Warnings + +- **Trace starts at `trace_etm_init()`**, not at reset: earlier `board_init()` + code shows as never-executed and Ozone logs `No trace clock present` — both + expected. Trace-from-reset needs a SEGGER J-Link script (`.pex`) instead of + firmware init. +- Never commit capture output (`itrace.csv` can exceed 100 MB) — keep `--out` + in scratchpad/`/tmp`; `*.jdebug.user` files stay untracked. +- The automation socket can't evaluate symbolic constants (`EXPORT_AS_CSV`): + the scripts send numeric/plain commands only — keep it that way when + extending them (UM08025 §6.7). +- Without `xvfb-run`, Ozone opens on `DISPLAY` and steals keyboard focus. + Ozone has no `--help`/`--version` — any such probe opens the GUI; check + with `which ozone` only. +- **`--trace-only` is experimental**: ETM start/stop comparators are scarce + and erratic — low-rate handler windows may silently not record, adjacent + instructions leak in, timestamps are invalid across gaps, and the profile + becomes share-of-traced-stream. Use only for instruction-exact inventories + of high-rate symbols; for ISR timing use full trace + `--isr`. + +## Adding a new board + +Bring-up ladder — each step gates the next: + +1. **Docs before hardware** (calibre library first, then vendor site): board + manual, schematics, MCU reference manual. Establish the trace clock + source and max — chip side and probe side (J-Trace PRO Cortex-M tops out + at a 150 MHz trace clock) — the pins carrying TRACE_CLK/D0-D3 (read the board's + debug-connector table — boards often route trace on alternate pins), and + required rework (jumpers, solder bridges, 0 Ω resistors to add/remove). + Hunt shared-net hazards: PHYs or other active drivers on trace nets, + boot straps, connector stubs. +2. **Confirm with the user before any hardware change**: present the rework + findings as **[ACTION]** items and wait — the user solders/jumpers, you + verify afterward. +3. **Vendor example before TinyUSB**: fetch SEGGER's trace example for the + same/similar MCU + (<https://www.segger.com/products/debug-probes/j-trace/technology/tested-devices/>) + and run it with `--device <MCU> --elf <demo ELF> --jlink-script + <demo .pex>`. Streaming proves the physical path — and only that: demo + firmware often runs reset-default clocks (the RA6M5 one traces at a few + MHz), so its success says nothing about your target's trace rate. The + example may target a different board (the LPC4357 one is tested on a + Keil MCB4300), so silence isn't final proof — but its J-Link + script/config is often borrowable. +4. **TinyUSB support**: `trace_etm_init()` in the family BSP — mux trace + pins AFTER the final core-clock switch, enable the trace clock, enable + any funnel between ETM and TPIU; committed `ozone/*.jdebug` reference, + plus a `.JLinkScript` declaring off-ROM-table CSTF/TMC/TPIU (addresses + from the vendor demo's script); build with `TRACE_ETM=1`, validate with + `--board <board>`. +5. **Still silent or corrupt?** In order: chip-side register audit (pinmux, + TPIU, ETM, DEMCR — and EVERY funnel in the path; an unprogrammed funnel + reads register-perfect and eats the stream), physically re-seat both + connector ends, then SEGGER's procedure (UM08001): find a stable + `--trace-timing` at `--trace-width 1`, step up to 2, then 4 (sampling + default is +2 ns) — then search the + MCU vendor's application notes and community forums for the chip's trace + recipe: more than one board's fix lived only in a forum thread. +6. **Board note**: add the table row (core clock, TRACECLK pin + max, + width, timing, physical setup, TODO for anything left unvalidated) plus + a caveat bullet — both in `boards.md`. + +## Per-board notes + +Every validated board has a row (config: core clock, TRACECLK, width, timing, +physical setup, TODO) and a caveat entry in `boards.md` (same directory) — +**read a board's row and caveat before capturing on it**; new validations add +both. Timing semantics and clock columns are explained at the top of that file. + +## References + +- Ozone manual (UM08025, automation socket §6.7, project commands §7): + <https://www.segger.com/downloads/jlink/UM08025_Ozone.pdf> — V3.50, same as + the installed Ozone (web is rev 1 vs the local copy's rev 0; the local PDF + under /opt/SEGGER/Ozone_V350/Doc remains the offline fallback). +- J-Link / J-Trace manual (UM08001, trace ch. 10, timing troubleshooting): + <https://kb.segger.com/UM08001_J-Link_/_J-Trace_User_Guide> diff --git a/.claude/skills/etm-trace/boards.md b/.claude/skills/etm-trace/boards.md new file mode 100644 index 000000000..dd628ea80 --- /dev/null +++ b/.claude/skills/etm-trace/boards.md @@ -0,0 +1,134 @@ +# etm-trace — per-board reference + +Validated boards: trace config table + hard-won caveats. Read the row AND the +caveat for a board before capturing on it; add a row + caveat when a new board +is validated (jdebug reference, board.cmake/board.h clock selection and this +file must agree). + +"Core (trace build)" is the CPU clock a `TRACE_ETM=1` build runs — where it +differs from the stock clock, board.h selects it automatically. Timing +"0 (unset)" = the reference sets no SetTraceTiming and Ozone then sends +`TraceSampleAdjust TD = 0`; J-Link's own +2 ns default (UM08001) applies only +outside Ozone-driven captures. Explicit values live in the committed +reference. + +| Board | Core (trace build) | TRACECLK pin | Width | Timing | Physical setup | TODO | +|--------------------|----------------------|-----------------------|-------|---------|-------------------------------|---------------------------------------------| +| stm32h743eval | 400 MHz | 50 MHz (PLL1R, fixed) | 4 | +100 ps | — | — | +| stm32n657nucleo | 300 MHz | 18.75 MHz (cpu/16) | 4 | 0 (unset) | none — CN1 MIPI20; JP2=1 | — | +| stm32h7s3nucleo | 300 MHz | 50 MHz (cpu/3/2) | 2 | 0 (unset) | none — native CN1 MIPI20 | remove SB11/SB12 → width 4 @ 600 MHz | +| stm32h563nucleo | 100 MHz | follows core | 1 | +5 ns | remove SB8/9/64/68/70/71/78 | retest width 4 / 250 MHz after SB removal | +| metro_m7_1011 | 500 MHz | 66 MHz (root/2) | 4 | +50 ps | custom rev A ETM-header rework | — | +| mcb1800 | 120 MHz | 60 MHz (CCLK/2) | 4 | 0 (unset) | fit J5 DBG_EN | — | +| ea4088_quickstart | 120 MHz | 120 MHz | 4 | 0 (unset) | J7 (fully wired) | — | +| nrf52840dk | 64 MHz | 16 MHz (hw cap) | 4 | 0 (unset) | solder P25, SW7 → Alt | — | +| nrf5340dk (M33) | 64 MHz | 16 MHz (TAD, forced) | 4 | +3 ns | mount P25; cut SB27/SB28 | — | +| mimxrt1170_evkb | 996 MHz | 25 MHz (root/2) | 1 | 0 | populate 0 Ω R1881-R1886; J58 | verify/reflow R1882-R1884 → width 4 | +| ra6m5_ek (M33) | 200 MHz | 25 MHz (TRCLK/4 /2) | 4 | 0 (unset) | J9 closed; native J20 trace | — | +| ra8m1_ek (M85) | 480 MHz | 60 MHz (TRCLK/4 /2) | 4 | 0 (unset) | J9 closed + Table 7 jumpers | — | +| raspberry_pi_pico2 (RP2350 M33) | 48 MHz | 24 MHz (clk_sys/2) | 4 | 0 (unset) | fly-wire GPIO1-5 → MIPI20 (map in jdebug) | 72-80 MHz per seating (re-qualify); >80 needs V3 probe + trace board | +| same54_xplained (E54 M4F) | 120 MHz | 60 MHz (CPU/2) | 4 | 0 (unset) | none — populated 20-pin ETM header | — | +| SEGGER H7/F407 ref | demo defaults | demo | 4 | demo | probe-powered: add `--power` | — | + +Board caveats (beyond the table): + +- **stm32h743eval**: startup-burst overflow at 400 MHz is normal (reduce + PLLN in board.h for overflow-free capture); timestamp ref 200 MHz. +- **stm32n657nucleo** (M55, flashless): **JP2 (BOOT1) must be 1** — the app + is a RAM image the debugger loads (Development boot); in flash boot theb + bootROM parks the chip un-attachable ("Can not attach to CPU"). SEGGER's + KB says BOOT0/BOOT1 = 0/0 for their example — that is flash boot and it + does NOT attach; the board manual's Table 11 is right. 600 MHz core kills + the stream in the startup burst (timestamp flux, not overflow) — TRACE_ETM + builds run 300 MHz; at 600 use `--no-timestamps`. No J-Link script needed: + N6 trace components are ROM-table-discoverable. +- **stm32h7s3nucleo**: width 4 is clean at idle but SB11/SB12 (default ON) + stub D2/D3 onto Zio CN8 and the stream dies under IRQ-heavy USB traffic — + remove them to try width 4 / 600 MHz. `--attach` while a USB host is + actively polling the device wedges its USB session (needs target reset). +- **stm32h563nucleo**: width 4 or 250 MHz corrupts. H5 hangs its debug AP if + trace CoreSight is touched unclocked — handled by the committed + `AfterTargetConnect` hook; un-attachable after a killed session → + power-cycle. +- **metro_m7_1011** (RT1011): a custom Adafruit rev with a hand-added 2x10 + ETM header (KiCad schematic in the calibre library). No SEGGER RT1011 + example exists — the committed .jdebug (tuned +50 ps) is the known-good + reference. BOARD_BootClockRUN sets the 132 MHz trace root but leaves it + gated; `trace_etm_init` ungates it. The first Ozone run after a fresh + flash can fail to reach main — transient, retry once. +- **mcb1800**: a bad ribbon mating yields register-perfect silence — re-seat + BOTH ribbon ends first; SWD working proves nothing about the trace lines. + `--isr USB0_IRQHandler,dcd_int_handler`. +- **nrf5340dk**: the interface MCU's UART1 flow control rides the trace + pins — it actively drives CTS onto P0.10/TRACEDATA1 (dead line, any + timing) and loads P0.11/TRACEDATA0: cut SB27/SB28 (or flip SW7 to FC-off). + SB57's SWO stub can stay — harmless at the +3 ns sample point. TRACE_ETM + builds force the TAD port to 16 MHz (SystemInit's 64 MHz is marginal). +- **ea4088_quickstart**: FS enumeration ends < 100 ms — for `--isr` use + `--duration-ms 150`. Boot-ROM address warning (0x1FFF1FF0) is normal. +- **mimxrt1170_evkb**: width 4 fails (D1-D3 path under investigation). + `trace_etm_init` fixes the JTAG_nTRST/DMIC_DATA1 pad, pins CSTRACE to + 50 MHz (stock 132 MHz corrupts — the 100M PHY drives the CLK net) and + enables the CM7 platform trace-funnel port, which J-Link doesn't program: + without it everything reads register-perfect yet zero data arrives. + FlexSPI apps: ROM bootloader must set SP/PC — the committed reset/download + hooks handle this. Startup-burst overflow at 996 MHz is normal. +- **ra6m5_ek**: TRCKCR div-2 (100 MHz TRCLK = 50 MHz pin, the chip max) is + unusable on this board — swept widths 1/4 across -2..+4 ns, all dead; + TRACE_ETM builds use div-4 (25 MHz pin). The TCLK pin runs TRCLK/2. 50 MHz SWD TIF + caused intermittent "Failed to initialize DAP" — the reference runs 4 MHz. + ISR entry: `--isr tusb_int_handler,dcd_int_handler` (FSP's + usbfs_interrupt_handler symbol never actually executes). +- **ra8m1_ek**: **J9 must be closed** (holds the on-board J-Link OB in + reset — open = SWD contention, intermittent "Failed to initialize DAP", + even an apparent brick recoverable only by power-cycle/J16 boot mode). + J-Link's RA8 support enables trace from reset; the committed JLinkScript's + empty `OnTraceStart` suppresses that so the firmware enables the trace + clock after the FSP clock switch — without it the MOCO→PLL step desyncs + the decoder at t≈0.05 s every run. Runs both chip maxima (120 MHz TRCLK, + 60 MHz pin) clean. `ReadIntoTraceCache 0x0 0x10000` in the download hook + covers runtime chip-ROM execution. ISR entry: `tusb_int_handler`. +- **raspberry_pi_pico2** (RP2350): TRACECLK is a fixed clk_sys/2, no divider + (DDR data, like every ARM TPIU pin port). **Measured cliff on this rig:** + 80 MHz core (40 MHz TRACECLK) traces idle code but dies under dense data; + 88 MHz+ dies instantly at any width/global-timing/TIF/pad setting. Cause + not pinned down: the same V2 probe samples 66 MHz TRACECLK (132 Msample/s) + on metro_m7_1011, so it is NOT a plain probe sample-rate ceiling. The + cliff at >40 MHz TRACECLK (84+ MHz core) survived a full sweep - global + AND per-pin `--trace-timing`, pad drive 2/4/8/12 mA + slew, width 4/2/1, + TIF 1-25 MHz, newer J-Link library - all flat, so it is V3-probe / real- + trace-board territory (SEGGER's Pico 2 KB requires J-Trace PRO **V3.0+** + and recommends a proper trace board; community reports fly-wires fail at + 75 MHz for everyone, PCBs work). Separately, fly-wire seating quality + sets the width-4 DENSE-data ceiling (48-72 MHz observed across seatings): + after ANY rewiring re-qualify with idle blinky at the target clock, then + cdc_msc x3. Random unknown-packet deaths KB into a clean stream = one + marginal wire; `--trace-width` 1 vs 2 vs 4 bisects which (width 1 = + CLK+D0 only; D1 = GPIO3->MIPI20 pin 16 has gone marginal twice on this + rig). Width-1 is a full-quality fallback: complete cdc_msc profiles at up + to 80 MHz core even when width 4 is broken. + **Never set a custom JLinkScript** — it + replaces J-Link's built-in RP2350 device script, which both declares the + trace component map (funnel/TPIU/ETM are not in the ROM table → "Required + trace components for pin trace not found", 0 fetches) and re-arms the whole + chip-side path via `OnTraceStart` at every resume. Firmware therefore does + no trace setup; TRACE_ETM builds only (a) pin clk_sys to 72 MHz from crt0 + (board.cmake) — the fly-wire ceiling: 96/150 MHz kill the stream in the + startup burst at any sample timing (and at 150 MHz the saturated probe + stops answering halts, "CPU could not be halted"); any post-arm clock + change steps TRACECLK mid-stream and kills the decoder — and (b) + clear TIMER0/1 DBGPAUSE (family.c): debug sessions leave cores + halted-at-reset and the default DBGPAUSE freezes the µs timer, so every + `sleep_ms()` spins forever (looks like a dead board; watchdog-scratch + breadcrumbs survive warm resets but not POR when diagnosing). UART console + is TX-only (GPIO1 = TRACECLK). Empty reset/download hooks: the bootrom + must run the IMAGE_DEF. If the chip ends up wedged/un-attachable: + J-Link `erase` + reset drops it into BOOTSEL (2e8a:000f) for picotool. +- **same54_xplained**: the CM4 trace unit is clocked from **GCLK channel 47 + (GCLK_CM4_TRACE)** — with it disabled the pins mux fine, TPIU/ETM arm + fine, and the port stays perfectly silent (zero fetches, no errors); + `trace_etm_init` feeds it GCLK0. Pins PC24-28 mux to function H. The + populated 20-pin header runs chip-max 60 MHz TRACECLK width 4 with no + timing adjustment - the connector-vs-flywire contrast board. +- **SEGGER ref boards**: run their own demo (ladder step 3 flags); `--isr` + degrades gracefully without a live SysTick. diff --git a/.claude/skills/etm-trace/scripts/etm_capture.py b/.claude/skills/etm-trace/scripts/etm_capture.py new file mode 100644 index 000000000..6468be12d --- /dev/null +++ b/.claude/skills/etm-trace/scripts/etm_capture.py @@ -0,0 +1,567 @@ +#!/usr/bin/env python3 +"""Capture streaming ETM instruction trace unattended via J-Trace + Ozone. + +Generates a throwaway Ozone project (never touches the committed +hw/bsp/**/ozone/*.jdebug), launches Ozone on a virtual display (xvfb-run), +drives the whole session over Ozone's automation TCP socket (UM08025 §6.7): +connect -> flash -> run for --duration-ms under streaming trace -> halt -> +export. Outputs in --out: + code_profile.txt hot functions (run/fetch counts) + code coverage + itrace.csv raw instruction history (only with --trace-csv) + ozone_console.log, jlink.log, ozone_gui.log session evidence + +Requires firmware built with -DTRACE_ETM=1 and the board wired to a J-Trace. +Analyze results with etm_profile.py in this directory. +""" + +import argparse +import glob +import os +import re +import shutil +import signal +import socket +import string +import subprocess +import sys +import tempfile +import time + +REPO_ROOT = os.path.abspath(os.path.join(os.path.dirname(__file__), *[".."] * 4)) + +# Throwaway Ozone project. SP/PC-from-vector-table hooks match the committed +# reference projects (Cortex-M generic). $$(InstallDir) -> literal $(InstallDir). +PROJECT_TEMPLATE = string.Template("""\ +/* Auto-generated by etm_capture.py (etm-trace skill) - throwaway, do not commit. */ +void OnProjectLoad (void) { + Project.SetDevice ("$device"); + Project.SetHostIF ("USB", "$probe"); + Project.SetTargetIF ("SWD"); + Project.SetTIFSpeed ("$tif_speed"); + Project.SetTraceSource ("Trace Pins"); + Project.SetTracePortWidth ($port_width); +$timing_line$core_clock_line$timestamps_line$hss_line$power_lines Edit.SysVar (VAR_TRACE_MAX_INST_CNT, $max_inst); + Edit.Preference (PREF_TIMESTAMP_FORMAT, TIMESTAMP_FORMAT_TIME); + Project.AddSvdFile ("$$(InstallDir)/Config/Peripherals/ARMv7M.svd"); + Project.SetConsoleLogFile ("$outdir/ozone_console.log"); + Project.SetJLinkLogFile ("$outdir/jlink.log"); +$os_plugin_line File.Open ("$elf"); +} +$jlink_script_hook + +$reset_hook + +$download_hook +$user_funcs""") + +# Cortex-M generic SP/PC-from-vector-table init. A committed board reference +# overrides these verbatim (e.g. RT1176 apps in FlexSPI NOR need the ROM +# bootloader to do SP/PC init, plus a JTAG_nTRST pad fix). +DEFAULT_HOOK = """\ +void %s (void) { + unsigned int SP; + unsigned int PC; + unsigned int VectorTableAddr; + VectorTableAddr = Elf.GetBaseAddr(); + if (VectorTableAddr == 0xFFFFFFFF) { + Util.Log("etm_capture: failed to get program base"); + } else { + SP = Target.ReadU32(VectorTableAddr); + Target.SetReg("SP", SP); + PC = Target.ReadU32(VectorTableAddr + 4); + Target.SetReg("PC", PC); + } +}""" + +# Symbolic constants (TP_OP_*, EXPORT_*) only evaluate in project-script +# context, never over the automation socket - so these live in generated user +# functions invoked via Script.Exec (UM08025 SS6.7, SS7.9.9.1). +TRACEPOINT_FUNC = """\ + +void SetupTracepoints (void) { +%s} +""" + +LINES_CSV_FUNC = """\ + +void ExportLinesCsv (void) { + Export.CodeProfile ("%s", EXPORT_AS_CSV | EXPORT_CSV_LINES | EXPORT_FILE_PATHS, ""); +} +""" + +INSTS_CSV_FUNC = """\ + +void ExportInstsCsv (void) { + Export.CodeProfile ("%s", EXPORT_AS_CSV | EXPORT_CSV_INSTS | EXPORT_FILE_PATHS, ""); +} +""" + + +JLINK_SCRIPT_HOOK = """\ + +void BeforeTargetConnect (void) { + Project.SetJLinkScript ("%s"); +} +""" + + +def resolve_board(board): + """Board config from its committed ozone reference project, else board.cmake/mk.""" + cfg = {"device": None, "tif_speed": "4 MHz", "timing": None, "port_width": 4, + "core_clock": None, "ref": None} + jdebugs = sorted(glob.glob(f"{REPO_ROOT}/hw/bsp/*/boards/{board}/ozone/*.jdebug")) + if jdebugs: + cfg["ref"] = jdebugs[0] + text = open(jdebugs[0]).read() + # config regexes must not match //-commented lines + cfgtext = re.sub(r"^\s*//.*$", "", text, flags=re.M) + # inherit every user function verbatim except OnProjectLoad, which the + # template owns (e.g. STM32H5's AfterTargetConnect must clock the trace + # CoreSight domain; RT1176 replaces the SP/PC reset/download hooks for + # ROM-bootloader boot; Nordic hooks call a _SetupTarget helper that + # must ride along or hook execution fails at runtime) + extra = [] + for m in re.finditer(r"^void (\w+)\s*\(void\)\s*\{.*?^\}", text, + re.M | re.S): + name, block = m.group(1), m.group(0) + if name == "OnProjectLoad": + continue + elif name == "AfterTargetReset": + cfg["reset_hook"] = block + elif name == "AfterTargetDownload": + cfg["download_hook"] = block + else: + extra.append(block) + if extra: + cfg["connect_hook"] = "\n\n".join(extra) + "\n" + for key, pat in (("device", r'Project\.SetDevice\s*\(\s*"([^"]+)"'), + ("tif_speed", r'Project\.SetTIFSpeed\s*\(\s*"([^"]+)"'), + ("timing", r'Project\.SetTraceTiming\s*\(([-\d\s,]+)\)'), + ("port_width", r'Project\.SetTracePortWidth\s*\(\s*(\d+)'), + ("core_clock", r'VAR_TRACE_CORE_CLOCK\s*,\s*(\d+)')): + m = re.search(pat, cfgtext) + if m: + cfg[key] = m.group(1).strip() + # inherit a J-Link script (e.g. RT1176 must declare its off-ROM-table + # TPIU/funnel); relative paths resolve against the reference's dir + m = re.search(r'Project\.SetJLinkScript\s*\(\s*"([^"]+)"', cfgtext) + if m: + # $(ProjectDir) = the reference's own directory + rel = m.group(1).replace("$(ProjectDir)", ".") + cfg["jlink_script"] = os.path.normpath(os.path.join( + os.path.dirname(jdebugs[0]), rel)) + else: + for path in glob.glob(f"{REPO_ROOT}/hw/bsp/*/boards/{board}/board.cmake"): + m = re.search(r'JLINK_DEVICE\s+([^\s)]+)\s*\)', open(path).read()) + if m: + cfg["device"] = m.group(1) + cfg["ref"] = path + break + if not cfg["device"]: + sys.exit(f"error: cannot resolve J-Link device for board '{board}' " + f"(no hw/bsp/*/boards/{board}/ozone/*.jdebug or board.cmake)") + return cfg + + +def trace_only_points(elf, syms_arg): + """Tracepoint lines for --trace-only: start trace at each symbol's entry, + stop at each return instruction inside it (pop ...pc / bx lr, via objdump). + Hardware comparators are scarce (ETM-M7) - keep the symbol list short.""" + lines = "" + nm = subprocess.run(["arm-none-eabi-nm", "-S", "--defined-only", elf], + capture_output=True, text=True).stdout + for want in [s.strip() for s in syms_arg.split(",") if s.strip()]: + m = re.search(rf"^([0-9a-f]+) ([0-9a-f]+) [TtWw] {re.escape(want)}$", + nm, re.M) + if not m: + sys.exit(f"error: --trace-only symbol '{want}' not in ELF") + lo, sz = int(m.group(1), 16) & ~1, int(m.group(2), 16) + lines += f' Trace.SetPoint (TP_OP_START_TRACE, "{want}");\n' + dis = subprocess.run( + ["arm-none-eabi-objdump", "-d", f"--start-address={lo:#x}", + f"--stop-address={lo + sz:#x}", elf], + capture_output=True, text=True).stdout + exits = re.findall( + r"^\s*([0-9a-f]+):.*?(?:(?:pop|ldmia[.\w]*\s+sp!,)[^\n]*\bpc\b|bx\s+lr)", + dis, re.M | re.I) + if not exits: + sys.exit(f"error: no return instruction found in '{want}'") + for addr in exits: + lines += f' Trace.SetPoint (TP_OP_STOP_TRACE, "0x{int(addr, 16):08X}");\n' + return lines + + +def resolve_probe(probe): + """Ozone's SetHostIF needs a serial - with several probes connected a + nickname makes it block on a selection dialog. JLinkExe DOES resolve + nicknames, so borrow its banner to map nickname -> serial. The serial only + ever lands in the throwaway project file, never in committed files.""" + if not probe or probe.isdigit(): + return probe + r = subprocess.run(["JLinkExe", "-USB", probe, "-nogui", "1"], + input="qc\n", capture_output=True, text=True, timeout=30) + m = re.search(r"S/N:\s*(\d+)", r.stdout) + if not m: + sys.exit(f"error: cannot resolve probe nickname '{probe}' to a serial " + f"(JLinkExe -USB {probe} found no emulator)") + return m.group(1) + + +def gen_project(cfg, args, outdir): + timing = "" + if args.trace_timing is not None: + d = [int(v) for v in str(args.trace_timing).split(",")] + if len(d) not in (1, 4): + sys.exit("error: --trace-timing takes one value or d0,d1,d2,d3") + d = d * 4 if len(d) == 1 else d + timing = (" Project.SetTraceTiming " + f"({d[0]}, {d[1]}, {d[2]}, {d[3]});\n") + elif cfg["timing"]: + timing = f" Project.SetTraceTiming ({cfg['timing']});\n" + core_clock = args.core_clock or cfg["core_clock"] + clk_line = f" Edit.SysVar (VAR_TRACE_CORE_CLOCK, {core_clock});\n" if core_clock else "" + ts_line = (" Edit.SysVar (VAR_TRACE_TIMESTAMPS_ENABLED, 0);\n" + if args.no_timestamps else "") + user_funcs = "" + if cfg.get("connect_hook"): + user_funcs += "\n" + cfg["connect_hook"] + if args.trace_only: + user_funcs += TRACEPOINT_FUNC % trace_only_points( + os.path.abspath(args.elf), args.trace_only) + if args.profile_lines_csv: + user_funcs += LINES_CSV_FUNC % os.path.join(outdir, "profile_lines.csv") + if args.profile_insts_csv: + user_funcs += INSTS_CSV_FUNC % os.path.join(outdir, "profile_insts.csv") + if args.os_plugin and not glob.glob( + f"/opt/SEGGER/Ozone*/Plugins/OS/{args.os_plugin}.js"): + sys.exit(f"error: RTOS plugin '{args.os_plugin}' not in " + f"/opt/SEGGER/Ozone*/Plugins/OS (e.g. FreeRTOSPlugin_CM7)") + os_plugin = (f' Project.SetOSPlugin ("{args.os_plugin}");\n' + if args.os_plugin else "") + if args.attach: + # attach to the running target: no download, no reset - trace a window + # mid-run (firmware must match the ELF and have trace pins enabled) + os_plugin += " Debug.SetConnectMode (CM_ATTACH_HALT);\n" + # HSS sampling rate belongs in OnProjectLoad (persistent) per UM08025 4.6.2; + # setting it mid-session over the socket is rejected. + hss = (f" Edit.SysVar (VAR_HSS_SPEED, {args.sample_hz});\n" + if args.sample else "") + power = (" Edit.SysVar (VAR_TARGET_POWER_ON, 1);\n" + f" Edit.SysVar (VAR_POWER_SAMPLING_SPEED, {args.power_hz});\n" + if args.power else "") + jlink_script = args.jlink_script or cfg.get("jlink_script") + jls_hook = (JLINK_SCRIPT_HOOK % os.path.abspath(jlink_script) + if jlink_script else "") + proj = os.path.join(outdir, "etm_capture.jdebug") + if args.trace_width: + cfg["port_width"] = args.trace_width + with open(proj, "w") as f: + f.write(PROJECT_TEMPLATE.substitute( + device=cfg["device"], probe=resolve_probe(args.probe), + tif_speed=cfg["tif_speed"], + port_width=cfg["port_width"], timing_line=timing, core_clock_line=clk_line, + timestamps_line=ts_line, max_inst=args.max_inst, outdir=outdir, + elf=os.path.abspath(args.elf), user_funcs=user_funcs, + os_plugin_line=os_plugin, hss_line=hss, power_lines=power, + jlink_script_hook=jls_hook, + reset_hook=cfg.get("reset_hook", DEFAULT_HOOK % "AfterTargetReset"), + download_hook=cfg.get("download_hook", + DEFAULT_HOOK % "AfterTargetDownload"))) + return proj + + +class OzoneSession: + """Drive Ozone via its automation TCP socket (one connection at a time).""" + + def __init__(self, port, logf): + self.port = port + self.logf = logf + self.sock = None + + def log(self, msg): + line = f"[{time.strftime('%H:%M:%S')}] {msg}" + print(line, flush=True) + self.logf.write(line + "\n") + self.logf.flush() + + def connect(self, timeout_s): + deadline = time.time() + timeout_s + while time.time() < deadline: + try: + self.sock = socket.create_connection(("127.0.0.1", self.port), timeout=5) + self.sock.settimeout(0.5) + self.log(f"connected to Ozone automation socket :{self.port}") + return + except OSError: + time.sleep(1) + raise TimeoutError(f"Ozone automation socket :{self.port} not reachable " + f"after {timeout_s}s (see ozone_gui.log)") + + def drain(self, wait_s=1.0): + buf = b"" + end = time.time() + wait_s + while time.time() < end: + try: + chunk = self.sock.recv(65536) + if not chunk: + break + buf += chunk + end = time.time() + 0.5 # keep reading while data flows + except socket.timeout: + pass + text = buf.decode(errors="replace") + for ln in text.splitlines(): + self.log(f" ozone> {ln}") + return text + + def send(self, cmd, wait_s=1.0): + self.log(f"cmd: {cmd}") + self.sock.sendall((cmd + "\n").encode()) + return self.drain(wait_s) + + def wait_echo(self, cmd, timeout_s): + """Send cmd; wait until Ozone echoes its execution (echo comes after the + command completed, e.g. a large Export). Returns all received text.""" + name = cmd.split("(")[0].strip() + text = self.send(cmd, 1.0) + deadline = time.time() + timeout_s + while name + " (" not in text and name + "(" not in text: + if time.time() > deadline: + raise TimeoutError(f"no echo for '{name}' after {timeout_s}s") + text += self.drain(1.0) + return text + + def is_halted(self, timeout_s): + """Poll Debug.IsHalted until it returns 1; parse the '// returns 0xN' echo.""" + deadline = time.time() + timeout_s + while time.time() < deadline: + text = self.send("Debug.IsHalted", 1.0) + end2 = time.time() + 4.0 + while "Debug.IsHalted" not in text and time.time() < end2: + text += self.drain(1.0) + m = re.findall(r"Debug\.IsHalted\s*\(\);\s*//\s*returns\s*0x(\d+)", text) + if m and m[-1] == "1": + return True + time.sleep(1) + return False + + +def main(): + p = argparse.ArgumentParser(description=__doc__, + formatter_class=argparse.RawDescriptionHelpFormatter) + p.add_argument("--board", help="TinyUSB board name, e.g. stm32h743eval") + p.add_argument("--device", help="J-Link device name for non-TinyUSB targets " + "(e.g. STM32F407VE for a SEGGER trace reference board); " + "requires --elf, bypasses hw/bsp board resolution") + p.add_argument("--tif-speed", default="4 MHz", + help="SWD speed for --device targets (default '4 MHz')") + p.add_argument("--jlink-script", + help="J-Link script file (.pex/.JLinkScript) for trace-pin " + "init when the firmware doesn't do it (SEGGER per-MCU " + "examples); wired into BeforeTargetConnect") + p.add_argument("--power", action="store_true", + help="power the target from the probe and record a power " + "profile (power.csv); probe power is switched off after " + "the session. Target must be wired for probe power!") + p.add_argument("--power-hz", type=int, default=10000, + help="power sampling frequency in Hz (default 10000)") + p.add_argument("--elf", help="firmware ELF built with -DTRACE_ETM=1 " + "(default: examples/cmake-build-<board>/device/cdc_msc/cdc_msc.elf)") + p.add_argument("--duration-ms", type=int, default=10000, help="traced run time") + p.add_argument("--out", help="output dir (default: mkdtemp under /tmp)") + p.add_argument("--port", type=int, default=19201, + help="automation socket port (19200 = interactive Ozone default; keep 19201)") + p.add_argument("--probe", default="", + help="J-Link USB nickname or serial ('' = sole connected probe)") + p.add_argument("--trace-csv", action="store_true", + help="also export raw instruction history (itrace.csv, can be >100 MB)") + p.add_argument("--max-inst", type=int, default=10000000, + help="VAR_TRACE_MAX_INST_CNT: instruction-trace window/export depth") + p.add_argument("--core-clock", type=int, + help="CPU Hz for timestamp conversion (default: board reference value)") + p.add_argument("--trace-timing", + help="trace sample delay in ps (-5000..5000, overrides the " + "board reference; sweep this when the stream dies with " + "unknown-packet errors). One value for all 4 pins, or " + "'d0,d1,d2,d3' to de-skew individual lines (boards can " + "have per-line RC delays, e.g. strap pulls on muxed pads)") + p.add_argument("--trace-width", type=int, choices=(1, 2, 4), + help="trace port width override (fewer pins = tolerant of a " + "single bad line, at reduced bandwidth)") + p.add_argument("--no-timestamps", action="store_true", + help="disable trace timestamps (less trace bandwidth -> fewer " + "overflows/decode errors; itrace.csv loses its time column)") + p.add_argument("--trace-only", + help="comma-separated symbols: trace ONLY these functions via " + "hardware tracepoints (e.g. an ISR + SysTick_Handler for " + "calibration); needs few symbols (scarce comparators)") + p.add_argument("--profile-lines-csv", action="store_true", + help="also export per-source-line profile/coverage counters " + "(profile_lines.csv)") + p.add_argument("--profile-insts-csv", action="store_true", + help="also export per-instruction counters (profile_insts.csv, " + "enables branch-bias analysis in etm_profile.py)") + p.add_argument("--attach", action="store_true", + help="attach to the RUNNING target instead of flash+reset: " + "capture a window mid-run (narrowing debug). The flashed " + "firmware must match --elf and have been built with " + "TRACE_ETM=1") + p.add_argument("--sample", + help="comma-separated C expressions to sample periodically " + "during the run (samples.csv, e.g. 'system_ticks')") + p.add_argument("--sample-hz", type=int, default=1000, + help="data sampling frequency in Hz (default 1000)") + p.add_argument("--os-plugin", + help="Ozone RTOS-awareness plugin for task/ISR-attributed " + "timeline, e.g. FreeRTOSPlugin_CM7 (see " + "/opt/SEGGER/Ozone*/Plugins/OS)") + args = p.parse_args() + + if not args.board and not args.device: + sys.exit("error: need --board (TinyUSB) or --device + --elf (other targets)") + if args.device and not args.elf: + sys.exit("error: --device requires --elf") + if args.max_inst > 10000000: + # >10M yielded a silently EMPTY Export.Trace on Ozone V3.50 + print("warning: --max-inst clamped to 10000000 (larger values produce " + "an empty instruction-trace export)", file=sys.stderr) + args.max_inst = 10000000 + if not args.elf: + args.elf = (f"{REPO_ROOT}/examples/cmake-build-{args.board}" + f"/device/cdc_msc/cdc_msc.elf") + if not os.path.isfile(args.elf): + sys.exit(f"error: ELF not found: {args.elf}\n" + f"build it with -DTRACE_ETM=1 (see the etm-trace skill) or pass --elf") + + if args.trace_only: + print("warning: --trace-only is EXPERIMENTAL - on some targets windows " + "for low-rate handlers fail to record, and timestamps are invalid " + "across trace gaps (instruction counts remain exact). For ISR " + "timing prefer a full --trace-csv capture + etm_profile.py --isr.", + file=sys.stderr) + if args.device: + cfg = {"device": args.device, "tif_speed": args.tif_speed, "timing": None, + "port_width": 4, "core_clock": None, "ref": "--device"} + else: + cfg = resolve_board(args.board) + outdir = os.path.abspath(args.out) if args.out else tempfile.mkdtemp( + prefix=f"etm-{args.board or args.device}-") + os.makedirs(outdir, exist_ok=True) + proj = gen_project(cfg, args, outdir) + + ozone_bin = shutil.which("ozone") or shutil.which("Ozone") + if not ozone_bin: + sys.exit("error: ozone not on PATH (install SEGGER Ozone)") + cmd = [ozone_bin, "-project", proj, "-port", str(args.port)] + if shutil.which("xvfb-run"): + cmd = ["xvfb-run", "-a"] + cmd + elif os.environ.get("DISPLAY"): + print("warning: xvfb-run not found - Ozone window will appear on " + f"DISPLAY={os.environ['DISPLAY']} and may steal keyboard focus", + file=sys.stderr) + else: + sys.exit("error: no DISPLAY and no xvfb-run; install xvfb") + + gui_log = open(os.path.join(outdir, "ozone_gui.log"), "w") + ses_logf = open(os.path.join(outdir, "session.log"), "w") + ses = OzoneSession(args.port, ses_logf) + ses.log(f"board={args.board} device={cfg['device']} ref={cfg['ref']}") + ses.log(f"elf={args.elf}") + ses.log(f"out={outdir}") + proc = subprocess.Popen(cmd, stdout=gui_log, stderr=gui_log, + start_new_session=True) + profile_out = os.path.join(outdir, "code_profile.txt") + itrace_out = os.path.join(outdir, "itrace.csv") + ok = False + try: + ses.connect(20) + ses.drain(3) # version banner + ses.send("Debug.Start", 5) + if not ses.is_halted(90): + raise TimeoutError("Debug.Start did not reach the startup completion " + "point (connect/flash failed? see jlink.log)") + ses.log("startup complete (halted at main)") + if args.trace_only: + ses.wait_echo('Script.Exec ("SetupTracepoints")', 15) + ses.send('Window.Show ("Code Profile")', 2) + if args.trace_csv: + ses.send('Window.Show ("Instruction Trace")', 2) + if args.sample: + ses.send('Window.Show ("Data Sampling")', 2) + for expr in args.sample.split(","): + ses.send(f'Window.Add ("Data Sampling", "{expr.strip()}")', 2) + ses.send("Coverage.ExcludeNOPs()", 2) + + ses.log(f"=== traced run: {args.duration_ms} ms ===") + ses.send("Debug.Continue", 1) + time.sleep(args.duration_ms / 1000.0) + ses.send("Debug.Halt", 3) + if not ses.is_halted(30): + raise TimeoutError("target did not halt") + ses.send("Window.WaitForUpdateComplete(120000)", 5) + + ses.wait_echo(f'Export.CodeProfile ("{profile_out}", 0, "")', 60) + if args.profile_lines_csv: + ses.wait_echo('Script.Exec ("ExportLinesCsv")', 60) + if args.profile_insts_csv: + ses.wait_echo('Script.Exec ("ExportInstsCsv")', 120) + if args.trace_csv: + ses.wait_echo(f'Export.Trace ("{itrace_out}", 0)', 300) + if args.sample: + ses.wait_echo(f'Export.DataGraphs ("{outdir}/samples.csv")', 60) + if args.power: + ses.wait_echo(f'Export.PowerGraphs ("{outdir}/power.csv")', 60) + ses.send("Debug.Stop", 5) + ses.send("File.Exit", 2) + ok = True + finally: + for _ in range(15): + if proc.poll() is not None: + break + time.sleep(1) + if proc.poll() is None: + ses.log("killing leftover Ozone process group") + os.killpg(proc.pid, signal.SIGKILL) + if args.power: + # guarantee probe power is off, whatever happened above + sel = ["-USB", args.probe] if args.probe else [] + r = subprocess.run(["JLinkExe", *sel, "-nogui", "1"], + input="power off\nqc\n", capture_output=True, + text=True, timeout=30) + ses.log("probe power off " + + ("issued" if r.returncode == 0 else f"FAILED rc={r.returncode}")) + + if not (os.path.isfile(profile_out) and os.path.getsize(profile_out) > 0 + and "Code Profile Report" in open(profile_out, errors="replace").read(200)): + sys.exit(f"error: capture ran but {profile_out} is missing/empty - " + f"check {outdir}/session.log and ozone_console.log") + if args.trace_csv and not (os.path.isfile(itrace_out) + and os.path.getsize(itrace_out) > 0): + sys.exit(f"error: --trace-csv requested but {itrace_out} is missing/empty") + if args.power and not os.path.getsize(os.path.join(outdir, "power.csv")): + sys.exit("error: --power requested but power.csv is missing/empty") + if "Trace collection stopped!" in open(os.path.join(outdir, "session.log"), + errors="replace").read(): + sys.exit("error: trace stream died mid-run (unknown trace data packet) - " + "the profile only covers up to that point. Retry with " + "--no-timestamps, or reduce the core clock (see SKILL.md).") + prof = open(profile_out, errors="replace").read() + m = re.search(r"^\s*Total\s*\|[\d ]*\|\s*([\d ]+)$", prof, re.M) + if not m or int(m.group(1).replace(" ", "") or 0) == 0: + sys.exit("error: session completed but NO trace data was collected " + "(profile totals are zero) - trace signal not reaching the " + "probe: check wiring/connector, trace pinmux, sample timing.") + if not ok: + sys.exit("error: session did not complete cleanly (see session.log)") + + print(f"\ncapture OK: {outdir}") + print(f" code_profile.txt ({os.path.getsize(profile_out)} bytes)") + if args.trace_csv: + print(f" itrace.csv ({os.path.getsize(itrace_out)} bytes)") + print(f"analyze: python3 {os.path.dirname(os.path.abspath(__file__))}" + f"/etm_profile.py {outdir} --elf {args.elf}") + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/.claude/skills/etm-trace/scripts/etm_profile.py b/.claude/skills/etm-trace/scripts/etm_profile.py new file mode 100644 index 000000000..c5ddf27a7 --- /dev/null +++ b/.claude/skills/etm-trace/scripts/etm_profile.py @@ -0,0 +1,428 @@ +#!/usr/bin/env python3 +"""Analyze an etm_capture.py output dir: hot functions, coverage, itrace digest, +ISR episode timing, and optimization hints. + +Input: code_profile.txt (Ozone Export.CodeProfile text report), and optionally + itrace.csv (Export.Trace raw instruction history) with --elf for + address->function mapping (arm-none-eabi-nm). +Output: markdown report on stdout. + +--isr SYM[,SYM..] episode timing for an interrupt handler: first symbol is the + entry anchor (its first instruction marks each ISR entry), all symbols + form the body address set. Example: --isr OTG_HS_IRQHandler,dcd_int_handler + Durations are calibrated against SysTick_Handler beats (1 ms apart), so + the itrace must be captured with timestamps enabled. +""" + +import argparse +import bisect +import csv +import os +import re +import statistics +import subprocess +import sys + + +def parse_profile(path): + """Parse the two report sections. Function rows are indented 2 spaces under + a non-indented module row; columns are '|'-separated.""" + lines = open(path, errors="replace").read().splitlines() + try: + cov_start = lines.index("Code Coverage Summary") + prof_start = lines.index("Code Profile Summary") + except ValueError: + sys.exit(f"error: {path} is not an Ozone code-profile text report") + + def rows(section): + module = None + for ln in section: + if "|" not in ln: + continue + cells = ln.split("|") + name = cells[0].rstrip() + if (not name or name.startswith("Module/Function") + or set(name.strip()) <= {"-", "+"}): + continue + if not name.startswith(" "): + module = name.strip() + continue + yield module, name.strip(), cells[1:] + + def num(s): + s = s.strip().replace(" ", "") + return int(s) if s else 0 + + cov_pat = re.compile(r"^\s*([\d ]+)/\s*([\d ]+)\s+([\d.]+)%") + funcs, totals = {}, {} + for module, name, cells in rows(lines[prof_start:]): + run, fetch = (num(cells[0]) if cells else 0), (num(cells[1]) if len(cells) > 1 else 0) + if name == "Total": + totals["run"], totals["fetch"] = run, fetch + elif name == "[Unaccounted]": + totals["unaccounted"] = fetch + else: + funcs[name] = {"module": module, "run": run, "fetch": fetch} + for module, name, cells in rows(lines[cov_start:prof_start]): + m_src = cov_pat.match(cells[0]) if cells else None + m_inst = cov_pat.match(cells[1]) if len(cells) > 1 else None + if name == "Total" and m_inst: + totals["src_cov"] = num(m_src.group(1)), num(m_src.group(2)) + totals["inst_cov"] = num(m_inst.group(1)), num(m_inst.group(2)) + elif name in funcs and m_inst: + funcs[name]["inst_pct"] = float(m_inst.group(3)) + return funcs, totals + + +def load_symbols(elf): + """Sorted (addr, size, name) from nm; for mapping itrace addresses.""" + nm = "arm-none-eabi-nm" + out = subprocess.run([nm, "-S", "--defined-only", "-C", elf], + capture_output=True, text=True) + if out.returncode != 0: + sys.exit(f"error: {nm} failed on {elf}: {out.stderr.strip()}") + syms = [] + for ln in out.stdout.splitlines(): + parts = ln.split(maxsplit=3) + if len(parts) == 4 and parts[2].lower() in ("t", "w"): + syms.append((int(parts[0], 16) & ~1, int(parts[1], 16), parts[3])) + elif len(parts) == 3 and parts[1].lower() in ("t", "w"): + # sizeless symbol (e.g. weak asm stub): assume a 2-byte body + syms.append((int(parts[0], 16) & ~1, 2, parts[2])) + return sorted(syms) + + +def addr_to_func(syms, addr): + i = bisect.bisect_right(syms, (addr, 1 << 62, "")) - 1 + if i >= 0 and syms[i][0] <= addr < syms[i][0] + syms[i][1]: + return syms[i][2] + return None + + +def sym_ranges(syms, names): + """(lo, hi) address ranges for the named symbols (base name match); + None if any symbol is missing (caller degrades gracefully).""" + out = [] + for want in names: + for a, sz, n in syms: + if n == want or n.split("(")[0] == want: + out.append((a, a + sz)) + break + else: + print(f"note: symbol '{want}' not found in ELF") + return None + return out + + +def iter_itrace(path): + """Yield (t_raw, addr) chronologically-reversed (file order: newest first). + Also returns the timestamp unit from the header via generator .send? No - + caller reads unit separately with itrace_unit().""" + with open(path, newline="", errors="replace") as f: + rd = csv.reader(f) + next(rd, None) + for row in rd: + if not row or row[0] == "PC" or len(row) < 2: + continue + try: + yield float(row[0]), int(row[1], 16) + except ValueError: + continue + + +def itrace_unit(path): + hdr = open(path, errors="replace").readline() + m = re.search(r"Timestamp\[([^\]]+)\]", hdr) + return m.group(1) if m else "?" + + +def time_by_func(path, syms): + """Per-function raw-time and instruction attribution from the itrace. + Rows are newest-first; the gap to the next (older) row is attributed to the + older instruction's function. Outlier gaps (trace-block boundaries) are + capped so one discontinuity cannot skew a function. Shares are scale-free.""" + sample = [] + t_prev = None + for t, _ in iter_itrace(path): + if t_prev is not None and t_prev - t > 0: + sample.append(t_prev - t) + if len(sample) >= 200000: + break + t_prev = t + cap = 10000 * statistics.median(sample) if sample else float("inf") + t_prev = None + tf, cf = {}, {} + n = 0 + for t, a in iter_itrace(path): + n += 1 + fn = addr_to_func(syms, a) + if fn: + cf[fn] = cf.get(fn, 0) + 1 + if t_prev is not None: + d = t_prev - t + if 0 < d < cap and fn: + tf[fn] = tf.get(fn, 0) + d + t_prev = t + return tf, cf, n + + +def isr_report(itrace, elf, isr_arg, top): + syms = load_symbols(elf) + names = [s.strip() for s in isr_arg.split(",") if s.strip()] + body = sym_ranges(syms, names) + tick = sym_ranges(syms, ["SysTick_Handler"]) + if not body or not tick: + print("\n## ISR timing: skipped (missing symbols above - needs the ISR " + "symbol(s) and SysTick_Handler for calibration)") + return + entry = body[0][0] + unit = itrace_unit(itrace) + + usb_rows, tick_rows, tmin, tmax = [], [], None, None + for t, a in iter_itrace(itrace): + tmin = t if tmin is None else min(tmin, t) + tmax = t if tmax is None else max(tmax, t) + if any(lo <= a < hi for lo, hi in body): + usb_rows.append((t, a)) + # independent, not elif: when the ISR under test IS SysTick_Handler, + # its rows must still feed the calibration + if any(lo <= a < hi for lo, hi in tick): + tick_rows.append((t, a)) + usb_rows.reverse() + tick_rows.reverse() + if len(tick_rows) < 20: + print(f"\n## ISR timing: not enough SysTick beats for calibration " + f"({len(tick_rows)} rows) - capture with timestamps enabled") + return + + # rough raw-units-per-1ms from the large mode of consecutive tick deltas + deltas = [b[0] - a[0] for a, b in zip(tick_rows, tick_rows[1:])] + big = [d for d in deltas if d > max(deltas) / 10] + raw_ms = statistics.median(big) + gap = 0.03 * raw_ms # 30 us in raw units + edge = 0.05 * raw_ms + + def episodes(rows, g): + out, cur = [], [] + for t, a in rows: + if cur and t - cur[-1][0] > g: + out.append(cur) + cur = [] + cur.append((t, a)) + if cur: + out.append(cur) + return out + + starts = [e[0][0] for e in episodes(tick_rows, 0.1 * raw_ms)] + + def local_scale(t): + i = bisect.bisect_left(starts, t) + if 0 < i < len(starts): + sp = starts[i] - starts[i - 1] + if 0 < sp < 3 * raw_ms: + return 1e-3 / sp + return 1e-3 / raw_ms + + eps = [] + for cluster in episodes(usb_rows, gap): + cur = None + for t, a in cluster: + if a == entry: + if cur: + eps.append(cur) + cur = [(t, a)] + elif cur: + cur.append((t, a)) + if cur: + eps.append(cur) + eps = [e for e in eps if e[0][0] - tmin > edge and tmax - e[-1][0] > edge + and len(e) >= 10] + print(f"\n## ISR timing: {names[0]} (+{len(names) - 1} body syms), " + f"unit '{unit}', {len(starts)} SysTick beats") + if not eps: + print("- no complete episodes in window (wrong symbols? window missed " + "the traffic phase?)") + return + stats = sorted(((e[-1][0] - e[0][0]) * local_scale(e[0][0]), len(e), e[0][0]) + for e in eps) + cal = [s[0] for s in stats] + print(f"- episodes: {len(cal)} | fastest {min(cal) * 1e6:.2f} us, " + f"median {statistics.median(cal) * 1e6:.2f} us, " + f"avg {statistics.mean(cal) * 1e6:.2f} us, " + f"worst {max(cal) * 1e6:.2f} us") + insts = [s[1] for s in stats] + print(f"- instructions/episode: min {min(insts)}, avg " + f"{statistics.mean(insts):.0f}, max {max(insts)}") + print("- worst episodes (duration, instructions, raw start):") + for c, n, t0 in stats[-5:][::-1]: + print(f" - {c * 1e6:8.2f} us {n:5d} instr t={t0:.6f}") + print("- caveats: timestamps are interpolated between packets (sub-us " + "values are approximate); episodes may merge if trace overflow " + "dropped an entry") + + +def short(name): + return re.sub(r"\(.*\)$", "()", name) + + +def branch_bias(insts_csv, funcs, top): + """One-sided conditional branches in executed functions (profile_insts.csv): + a conditional fetched N times but taken/executed 0 or N times = a branch + that never varied -> hot always-true assert, dead path, or an invariant + that could hoist out of a loop (UM08025 SS5.19).""" + def n(v): + v = (v or "").replace(" ", "") + return int(v) if v.lstrip("-").isdigit() else 0 + biased = [] + with open(insts_csv, newline="", errors="replace") as f: + for r in csv.DictReader(f): + if (r.get("Is Conditional") or "0").strip() != "1": + continue + fetched = n(r.get("Times Fetched")) + executed = n(r.get("Times Executed")) + if fetched < 1000: # only hot conditionals matter + continue + if executed == 0 or executed == fetched: + biased.append((fetched, r.get("Function", "?"), + r.get("Address", ""), r.get("AsmCode", "").strip(), + "always-taken" if executed == fetched else "never-taken")) + if not biased: + return + biased.sort(reverse=True) + print(f"\n## One-sided hot branches (profile_insts.csv)\n") + print("Conditionals that never varied - candidates to hoist/remove " + "(UM08025 §5.19):") + for fetched, fn, addr, asm, kind in biased[:top]: + print(f"- `{short(fn)}` @{addr} {kind} ({fetched:,}x): `{asm[:50]}`") + + +def suggestions(funcs, totals, tshare, cshare, exclude): + """Rule-based optimization hints (after UM08025 §5.19).""" + print("\n## Optimization hints") + total_fetch = totals.get("fetch") or 1 + ex = [n for n in funcs if exclude and re.search(exclude, n)] + ex_fetch = sum(funcs[n]["fetch"] for n in ex) + if ex: + print(f"- excluded from load ranking (--exclude): {len(ex)} functions, " + f"{100.0 * ex_fetch / total_fetch:.1f}% of fetches") + rest = {n: v for n, v in funcs.items() if n not in ex} + rt = sum(v["fetch"] for v in rest.values()) or 1 + hot = sorted(rest.items(), key=lambda kv: -kv[1]["fetch"])[:5] + print("- top load after exclusion: " + ", ".join( + f"`{short(n)}` {100.0 * v['fetch'] / rt:.1f}%" for n, v in hot)) + polls = [(n, v) for n, v in rest.items() + if v["fetch"] / total_fetch > 0.02 and v["run"] + and v["fetch"] / v["run"] < 40] + if polls: + print("- busy-poll candidates (>2% load, <40 instr/entry - called in a " + "tight loop; consider event-driven or rate-limiting):") + for n, v in sorted(polls, key=lambda kv: -kv[1]["fetch"]): + print(f" - `{short(n)}`: {v['run']:,} calls, " + f"{v['fetch'] / v['run']:.0f} instr/call, " + f"{100.0 * v['fetch'] / total_fetch:.1f}% load") + if tshare: + stalls = [] + for n, ts in tshare.items(): + cs = cshare.get(n, 0) + if ts > 0.01 and cs and ts / cs > 4: + stalls.append((n, ts, ts / cs)) + if stalls: + print("- stall/wait-dominated (time share >> instruction share - " + "waiting on hardware, consider DMA/IRQ instead of polling):") + for n, ts, ratio in sorted(stalls, key=lambda x: -x[1])[:5]: + print(f" - `{short(n)}`: {100 * ts:.1f}% of time, " + f"{ratio:.0f}x its instruction share") + + +def main(): + p = argparse.ArgumentParser(description=__doc__, + formatter_class=argparse.RawDescriptionHelpFormatter) + p.add_argument("capture_dir", help="etm_capture.py output dir") + p.add_argument("--top", type=int, default=10, help="table size") + p.add_argument("--elf", help="firmware ELF, enables itrace analyses") + p.add_argument("--isr", help="entry[,body..] symbols for ISR episode timing") + p.add_argument("--exclude", help="regex of functions to exclude from the " + "optimization load ranking (e.g. the idle poll loop)") + args = p.parse_args() + + profile = os.path.join(args.capture_dir, "code_profile.txt") + itrace = os.path.join(args.capture_dir, "itrace.csv") + funcs, totals = parse_profile(profile) + total_fetch = totals.get("fetch") or 1 + hot = sorted(funcs.items(), key=lambda kv: kv[1]["fetch"], reverse=True)[:args.top] + + print(f"# ETM profile: {args.capture_dir}\n") + print(f"## Top {args.top} hottest functions (instruction-fetch share)\n") + print("| # | Function | Module | Run Count | Fetch Count | Load % |") + print("|---|----------|--------|-----------|-------------|--------|") + for i, (name, v) in enumerate(hot, 1): + print(f"| {i} | `{short(name)}` | {v['module']} | {v['run']:,} " + f"| {v['fetch']:,} | {100.0 * v['fetch'] / total_fetch:.2f}% |") + print(f"\nTotal fetches {totals.get('fetch', 0):,} " + f"(runs {totals.get('run', 0):,}, unaccounted {totals.get('unaccounted', 0):,})\n") + + ic, sc = totals.get("inst_cov"), totals.get("src_cov") + print("## Coverage (NOPs excluded)\n") + if ic: + print(f"- instructions fully executed: {ic[0]:,} / {ic[1]:,} " + f"({100.0 * ic[0] / ic[1]:.1f}%)") + if sc: + print(f"- source lines fully covered: {sc[0]:,} / {sc[1]:,} " + f"({100.0 * sc[0] / sc[1]:.1f}%)") + partial = [n for n, v in funcs.items() + if v["fetch"] > 0 and 0 < v.get("inst_pct", 100) < 100] + print(f"- executed but only partially covered: {len(partial)} functions") + dead = sorted(n for n, v in funcs.items() + if v["fetch"] == 0 and "(always inlined)" not in n) + print(f"- never-executed out-of-line functions: {len(dead)}") + by_mod = {} + for n in dead: + by_mod.setdefault(funcs[n]["module"], []).append(short(n)) + for mod in sorted(by_mod, key=str): + print(f" - {mod}: {', '.join('`%s`' % f for f in by_mod[mod])}") + + tshare, cshare = {}, {} + if os.path.isfile(itrace) and args.elf: + syms = load_symbols(args.elf) + tf, cf, n = time_by_func(itrace, syms) + tt, tc = sum(tf.values()) or 1, sum(cf.values()) or 1 + tshare = {k: v / tt for k, v in tf.items()} + cshare = {k: v / tc for k, v in cf.items()} + unit = itrace_unit(itrace) + print(f"\n## Instruction history (itrace.csv, unit '{unit}')\n") + print(f"- {n:,} instructions; top {args.top} by TIME share " + f"(vs instruction share):") + for name, ts in sorted(tshare.items(), key=lambda kv: -kv[1])[:args.top]: + print(f" - `{short(name)}`: {100 * ts:.1f}% time, " + f"{100 * cshare.get(name, 0):.1f}% instructions") + + lines_csv = os.path.join(args.capture_dir, "profile_lines.csv") + if os.path.isfile(lines_csv): + def n(v): # Ozone groups thousands with spaces + v = (v or "").replace(" ", "") + return int(v) if v.isdigit() else 0 + with open(lines_csv, newline="", errors="replace") as f: + rows = [r for r in csv.DictReader(f) + if r.get("File") and n(r.get("Instructions Fetched")) > 0] + rows.sort(key=lambda r: -n(r["Instructions Fetched"])) + print(f"\n## Hottest source lines (profile_lines.csv)\n") + for r in rows[:args.top]: + src = (r.get("Content") or "").strip() + print(f"- {os.path.basename(r['File'])}:{r['Line']} " + f"{n(r['Instructions Fetched']):,} fetches `{src[:60]}`") + + insts_csv = os.path.join(args.capture_dir, "profile_insts.csv") + if os.path.isfile(insts_csv): + branch_bias(insts_csv, funcs, args.top) + + if args.isr: + if not (os.path.isfile(itrace) and args.elf): + sys.exit("error: --isr needs itrace.csv (--trace-csv capture) and --elf") + isr_report(itrace, args.elf, args.isr, args.top) + + suggestions(funcs, totals, tshare, cshare, args.exclude) + return 0 + + +if __name__ == "__main__": + sys.exit(main()) |