diff --git a/.vscode/settings.json b/.vscode/settings.json index 5d34c73..ed94211 100644 --- a/.vscode/settings.json +++ b/.vscode/settings.json @@ -31,7 +31,12 @@ "rmii_config.h": "c", "conn.h": "c", "ssi.h": "c", - "flash.h": "c" + "flash.h": "c", + "printf.h": "c", + "stdlib.h": "c", + "pico.h": "c", + "platform.h": "c", + "error.h": "c" }, "cortex-debug.variableUseNaturalFormat": false, "cortex-debug.registerUseNaturalFormat": false diff --git a/CMakeLists.txt b/CMakeLists.txt index 9adaab3..d569384 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -30,6 +30,8 @@ add_executable(pico-debug gdb.c gdb.h breakpoint.c breakpoint.h + prof.c + cmdline.c cmdline.h utils.c utils.h @@ -102,8 +104,11 @@ target_compile_definitions(pico-debug PRIVATE CMD_CDC=2 CMD_TCP=3335 + PROF_CDC=0 + PROF_TCP=0 + # Debug on CDC2 - # DEBUG_CDC=2 + DEBUG_CDC=2 DEBUG_BUF=1 ) diff --git a/PROFILING.md b/PROFILING.md new file mode 100644 index 0000000..9ceadc0 --- /dev/null +++ b/PROFILING.md @@ -0,0 +1,55 @@ +# Profiling RP2040 Code + +This branch of `pico_debug` has a profiler interface instead of gdb on CDC port 0. +(In the future it should be possible for the two to coexist, but that's not done yet.) +Wifi support is forcibly disabled as well. + +This will only work with code compiled with `-fno-omit-frame-pointer`, because +interpreting the ARM unwind tables is too expensive at runtime (and plus not implemented +because it's super annoying). I may experiment with that in the future -- the unwind tables can be downloaded to the debug probe and evaluated over SWD -- but this is good enough for most +use cases, even though it does make the `r7` register unavailable and thus does have a performance impact. + +The front end is based on [`samply`](https://github.com/mstange/samply). Check out the `pico` +branch and build (`cargo build`). + +## Setup + +Build this code and flash it to a Pico that's connected to your target in a "Picoprobe" setup. +If you're targeting another rp2040-based device, you may need to modify some hardcoded values +in `prof.c` (memory and flash regions). This will be runtime configurable in the future. + +Install `samply` (`pico` branch). + +You'll need your code compiled with `-fno-omit-frame-pointer` (`add_compile_options(-fno-omit-frame-pointer)`), and then you'll need to have the `program.elf` binary available. You should also download the [bootloader binary for your chip revision](https://github.com/raspberrypi/pico-bootrom/releases) for more complete symbols. + +## Running + +Connect the picoprobe to your computer via USB. Connecting to CDC port 3 with a terminal emulator +should give you a `pico_debug>` prompt (you don't need to do anything here, but a good verification +that things are working). + +Run: +``` +samply --pico /dev/tty.usbXXXX1 --pico-bootloader b2.elf --pico-reset --rate 50 program.elf +``` + +the target will reset and sampling will start. Omit `--pico-reset` to profile an already-running device. Press `^C` when done to open the profiler front-end. (Note: `program.elf` should already be flashed onto the target pico. This program does not download the program, but it will do that in the future.) + +`--rate` takes an argument in Hz (not ms). Note that the default for `samply` is 1ms, which is too fast for this. (It will work, but your code won't run anywhere near full speed!) + +## Internals + +This uses the SWD protocol (the bulk of the code in this repo comes from https://github.com/essele/pico_debug -- a very fast rp2040 debug interface) to halt each core at a given sampling interval, and then read `pc`, `lr`, `fp`, and walk the frame pointer hierarchy back. + +In my measurements, it takes around 500µs to halt, sample (with shallow frame depth), and resume a core. It could be down to 300µs, but there's some weirdness with SWD I need to investigate where the cores aren't actually getting unhalted until I read their status. This isn't amazing, but is completely workable for a 20ms or so sampling interval. + +The protocol itself is simple. When a connection is made to CDC port 0, there are a few commands that can be sent: + + * `r` -- reset both cores + * `0xa0` `0xvvvv` `0xff` -- start sampling + * `v` is the sampling interval, in ms (little endian) + * `f` is flags: `1 << 0` sample core 0 only instead of both cores + * `0xa1` -- stop sampling + +When sampling is running, a stream of data will be received with the samples. See `prof.c` for the (simple) format. + diff --git a/adi.c b/adi.c index 1de2420..96cc25e 100644 --- a/adi.c +++ b/adi.c @@ -1259,11 +1259,20 @@ int check_cores() { } - - -int dp_init() { +int dp_force_init() { CHECK_OK(dp_initialise()); CHECK_OK(core_select(0)); return SWD_OK; } +int dp_init() { + static bool initialized = false; + if (!initialized) { + int rv = dp_force_init(); + if (rv == SWD_OK) { + initialized = true; + } + return rv; + } + return SWD_OK; +} diff --git a/id_usb.c b/id_usb.c index 9fd1712..f7aeef4 100644 --- a/id_usb.c +++ b/id_usb.c @@ -38,6 +38,10 @@ #define USBD_CDC_2_EP_OUT (0x04) #define USBD_CDC_2_EP_IN (0x86) +#define USBD_CDC_3_EP_CMD (0x87) +#define USBD_CDC_3_EP_OUT (0x08) +#define USBD_CDC_3_EP_IN (0x89) + #define USBD_CDC_CMD_MAX_SIZE (8) #define USBD_CDC_IN_OUT_MAX_SIZE (64) @@ -48,6 +52,7 @@ #define USBD_STR_CDC0 (0x04) #define USBD_STR_CDC1 (0x05) #define USBD_STR_CDC2 (0x06) +#define USBD_STR_CDC3 (0x07) // // Officially, according to the USB specs, we shoul duse TUSB_CLASS_MISC, SUBCLASS_COMMON, and PROTOCOL_IAD @@ -85,6 +90,8 @@ enum ITF_NUM_CDC_1_DATA, ITF_NUM_CDC_2, ITF_NUM_CDC_2_DATA, + ITF_NUM_CDC_3, + ITF_NUM_CDC_3_DATA, ITF_NUM_TOTAL }; @@ -104,6 +111,9 @@ uint8_t const usbd_desc_cfg[] = TUD_CDC_DESCRIPTOR(ITF_NUM_CDC_2, USBD_STR_CDC2, USBD_CDC_2_EP_CMD, USBD_CDC_CMD_MAX_SIZE, USBD_CDC_2_EP_OUT, USBD_CDC_2_EP_IN, USBD_CDC_IN_OUT_MAX_SIZE), + + TUD_CDC_DESCRIPTOR(ITF_NUM_CDC_3, USBD_STR_CDC3, USBD_CDC_3_EP_CMD, + USBD_CDC_CMD_MAX_SIZE, USBD_CDC_3_EP_OUT, USBD_CDC_3_EP_IN, USBD_CDC_IN_OUT_MAX_SIZE), }; @@ -159,7 +169,7 @@ const uint16_t *tud_descriptor_string_cb(uint8_t index, __unused uint16_t langid break; case USBD_STR_SERIAL: - len = string_to_descriptor("11223344", desc_str); + len = string_to_descriptor("pdebug", desc_str); break; case USBD_STR_CDC0: @@ -174,6 +184,10 @@ const uint16_t *tud_descriptor_string_cb(uint8_t index, __unused uint16_t langid len = string_to_descriptor("debug-debug", desc_str); break; + case USBD_STR_CDC3: + len = string_to_descriptor("debug-prof", desc_str); + break; + default: return NULL; } diff --git a/main.c b/main.c index e81e0f2..e3b136e 100644 --- a/main.c +++ b/main.c @@ -46,6 +46,7 @@ void main_poll() { debug_poll(); } +void prof_init(); int main() { // Take us to 150Mhz (for future rmii support) @@ -70,15 +71,15 @@ int main() { dbg_uart_init(); // Create the GDB server task.. - gdb_init(); + //gdb_init(); + + prof_init(); // See if we have enough information to start the wifi... // This is horrible here, needs to be a separate func/file with wifi/net related stuff. - if (*cf->main->wifi.ssid && *cf->main->wifi.creds) { - cyw43_arch_wifi_connect_async(cf->main->wifi.ssid, cf->main->wifi.creds, CYW43_AUTH_WPA2_AES_PSK); - } - - + //if (*cf->main->wifi.ssid && *cf->main->wifi.creds) { + // cyw43_arch_wifi_connect_async(cf->main->wifi.ssid, cf->main->wifi.creds, CYW43_AUTH_WPA2_AES_PSK); + //} // And start the scheduler... leos_init(main_poll); diff --git a/modules/lerp_io/include/lerp/io.h b/modules/lerp_io/include/lerp/io.h index 8c1dbd7..52e7bb9 100644 --- a/modules/lerp_io/include/lerp/io.h +++ b/modules/lerp_io/include/lerp/io.h @@ -44,7 +44,9 @@ struct io *io_init(int cdc_port, int tcp_port, int buf_size); void io_poll(); int io_get_byte(struct io *io); +int io_get_byte_nb(struct io *io); int io_put_byte(struct io *io, uint8_t ch); +int io_put_bytes(struct io *io, uint8_t *data, int len); int io_put_hexbyte(struct io *io, uint8_t b); int io_printf(struct io *io, char *format, ...); int io_aprintf(struct io *io, char *format, va_list args); diff --git a/modules/lerp_io/io.c b/modules/lerp_io/io.c index 387c8d5..0e6117f 100644 --- a/modules/lerp_io/io.c +++ b/modules/lerp_io/io.c @@ -337,6 +337,14 @@ int io_is_connected(struct io *io) { return io->usb_is_connected || (io->pcb != NULL); } +int io_get_byte_nb(struct io *io) { + if (circ_is_empty(io->input)) { + return 0; + } + + return circ_get_byte(io->input); +} + int io_get_byte(struct io *io) { int reason; @@ -369,6 +377,19 @@ int io_put_byte(struct io *io, uint8_t ch) { return 0; } +int io_put_bytes(struct io *io, uint8_t *data, int len) { + int reason; + + if (circ_is_full(io->output)) { + io->waiting_on_output = current_task(); + reason = task_block(); + if (reason < 0) return reason; + } + //debug_putch(ch); + circ_add_bytes(io->output, data, len); + return 0; +} + int io_read_flush(struct io *io) { if (io->usb_is_connected) tud_cdc_n_read_flush(io->cdc_port); circ_clean(io->input); @@ -489,6 +510,8 @@ struct io *io_init(int cdc_port, int tcp_port, int buf_size) { struct io *io = malloc(sizeof(struct io)); if (!io) return NULL; + tcp_port = 0; + io->cdc_port = cdc_port; io->tcp_port = tcp_port; io->pcb = NULL; diff --git a/prof.c b/prof.c new file mode 100644 index 0000000..5cf704d --- /dev/null +++ b/prof.c @@ -0,0 +1,398 @@ +#include "pico/stdlib.h" +#include "pico/printf.h" +#include "pico/bootrom.h" +#include +#include +#include +#include +#include + +#include "gdb.h" +#include "swd.h" +#include "adi.h" +#include "lerp/io.h" +#include "lerp/task.h" +#include "utils.h" +#include "flash.h" +#include "breakpoint.h" + +#include "lerp/debug.h" +#include "lerp/io.h" + +#define START_SAMPLING_CMD 0xa0 +#define STOP_SAMPLING_CMD 0xa1 +#define SAMPLE_CMD 0xb0 + +#define FLAG_CORES_MASK (1) +#define FLAG_BOTH_CORES (0 << 0) +#define FLAG_ONE_CORE (1 << 0) + +// Number of bytes the actual address is before the content of the LR +// register. Because on ARM LR points to the instruction to be executed +// on return, we want to point to the actual branch -- which will be either +// 2 or 4 bytes before. We don't know which one (Thumb insn could be either), +// but setting it to 2 bytes back will cause the profiler to figure out the right +// instruction. +#define LR_OFFSET 2 + +// These are correct for Pico. The Flash in particular +// will differ based on what size flash chips are installed +#define FLASH_LO 0x10000000 +#define FLASH_HI 0x10200000 +#define MEM_LO 0x20000000 +#define MEM_HI 0x20042000 + +struct io *prof_io = NULL; + +// gcc says that on thumb, reg 7 is used as the frame pointer register? +#define REG_THUMB_FP 7 +#define REG_ARM_FP 11 +#define REG_LR 14 +// this is technically DebugReturnAddress, but it's effectively accurate +// (next instruction to be executed after return from debug) +#define REG_PC 15 + +// from adi.c +int core_update_status(); + +// code can be executed from flash or RAM +static bool valid_pc(uint32_t addr) { + if (addr >= FLASH_LO && addr < FLASH_HI) + return true; + if (addr >= MEM_LO && addr < MEM_HI) + return true; + return false; +} + +// but frame pointers can only be on the stack, in ram +static bool valid_mem(uint32_t addr) { + if (addr >= MEM_LO && addr < MEM_HI) + return true; + + return false; +} + +static void reset_halt() { + core_select(0); + core_reset_halt(); + core_select(1); + core_reset_halt(); + core_select(0); +} + +static int was_connected = 0; +static int profiling_active = 0; +static int profiling_interval_ms = 100; + +static int max_cores = 2; + +#define MAX_FRAMES 64 +#define NUM_RESERVED_FRAMES 2 +static uint32_t frame_buf[MAX_FRAMES]; + +static int prof_task_io(); +static int sample_core(int core_num, uint32_t* frame_buf, int max_frames, uint32_t* timestamp, uint32_t* us_out); +static int write_frames(int core_num, uint32_t timestamp, uint32_t* frame_buf, int num_frames); + +static inline void dump_sampling_time_stats_real(); + +// convenient for avg shift +// must be a power of 2 +#define US_COST_POW2 5 +#define US_COST_LEN (1<<(US_COST_POW2)) +static int us_cost_data[US_COST_LEN]; +static int us_cost_next = 0; + +// helpers to time how long each sample sequence takes +#if true +#define dump_sampling_time_stats() do { } while(0) +#define record_sampling_time_stats(x) do { } while(0) +#else +#define dump_sampling_time_stats dump_sampling_time_stats_real +static inline void record_sampling_time_stats(uint32_t elapsed) { + us_cost_data[us_cost_next++] = elapsed; +} +#endif + +// +// The main profiler task loop +// +void prof_task() { + int rc; + + if (!prof_task_io()) { + return; + } + + if (profiling_active) { + int frame_cnt; + uint32_t timestamp = 0; + uint32_t elapsed; + + for (int core = 0; core < max_cores; core++) { + frame_cnt = sample_core(core, + frame_buf+NUM_RESERVED_FRAMES, + MAX_FRAMES-NUM_RESERVED_FRAMES, + ×tamp, &elapsed); + + if (frame_cnt > 0) { + write_frames(core, timestamp, frame_buf, frame_cnt); + } + + record_sampling_time_stats(elapsed); + } + + dump_sampling_time_stats(); + } + + task_sleep_ms(profiling_interval_ms); +} + +void dump_sampling_time_stats_real() { + if (us_cost_next == US_COST_LEN) { + uint64_t total_us = 0; + uint32_t min_us = UINT32_MAX, max_us = 0; + + for (int i = 0; i < US_COST_LEN; i++) { + uint32_t us = us_cost_data[i]; + min_us = us < min_us ? us : min_us; + max_us = us > max_us ? us : max_us; + total_us += max_us; + } + + uint32_t avg_us = (uint32_t) (total_us >> US_COST_POW2); + + debug_printf("Sampling time: min: %d max: %d avg: %d us\r\n", min_us, max_us, avg_us); + + us_cost_next = 0; + } +} + +int prof_task_io() { + if (!io_is_connected(prof_io)) { + task_sleep_ms(profiling_interval_ms); + return false; + } + + if (!was_connected) { + // This is the first time a connection happened + if (dp_init() != SWD_OK) { + debug_printf("unable to connect to target, trying again...\r\n"); + task_sleep_ms(250); + return false; + } + + debug_printf("SWD initialized for profiler\r\n"); + was_connected = 1; + } + + int ch = 0; + while ((ch = io_get_byte_nb(prof_io)) > 0) { + // TODO -- move this into cmdline + switch (ch) { + // these are hacks + case 'r': + reset_halt(); + profiling_active = false; + break; + case 'g': + core_select(1); + core_unhalt(); + core_select(0); + core_unhalt(); + profiling_active = true; + break; + case 'q': + reset_usb_boot(0, 0); + case ' ': + profiling_active = !profiling_active; + break; + case '1': + profiling_active = !profiling_active; + max_cores = 1; + break; + + // these are the actual commands + case START_SAMPLING_CMD: { + profiling_active = false; + + int byte2 = io_get_byte_nb(prof_io); + int byte3 = io_get_byte_nb(prof_io); + int byte4 = io_get_byte_nb(prof_io); + if (byte2 < 0 || byte3 < 0 || byte4 < 0) { + debug_printf("got error reading start command bytes: %d %d %d\r\n", byte2, byte3, byte4); + break; + } + + uint32_t sampling_interval = (byte3 << 8) | byte2; + uint32_t flags = byte4; + + if (sampling_interval == 0) { + debug_printf("got 0 sampling interval\r\n"); + break; + } + + profiling_interval_ms = sampling_interval; + if ((flags & FLAG_CORES_MASK) == FLAG_ONE_CORE) { + max_cores = 1; + } else { + max_cores = 2; + } + + debug_printf("Profiling started: %d ms interval, %d cores\r\n", sampling_interval, max_cores); + profiling_active = true; + break; + } + case STOP_SAMPLING_CMD: { + profiling_active = false; + break; + } + } + } + + return true; +} + +// +// sampling function +// +int sample_core( + int core_num, + uint32_t* frame_buf, + int max_frames, + uint32_t* sample_time, + uint32_t* us_out) +{ + int rc; + + uint32_t tstart = time_us_32(); + + core_select(core_num); + core_halt(); + + uint32_t pc, lr, fp; + uint32_t fplr, fpsp, fpfp; + + rc = reg_read(REG_LR, &lr); + rc |= reg_read(REG_PC, &pc); + rc |= reg_read(REG_THUMB_FP, &fp); + if (rc != SWD_OK) { + debug_printf("SWD NOT OK -- CORE(s) HALTED\r\n"); + return -1; + } + + int framenum = 0; + + // always trust PC + frame_buf[framenum++] = pc; + +#if false + if (core_num == 1) { + if (valid_mem(fp)) { + mem_read32(fp-4, &fplr); + mem_read32(fp-12, &fpfp); + } else { + fplr = 0; + fpfp = 0; + } + debug_printf("core %d: pc=0x%08x lr=0x%08x fplr=0x%08x fp=0x%08x fpfp=0x%08x @ %u\r\n", core_num, pc, lr, fplr, fp, fpfp, tstart); + } +#endif + + if (!valid_mem(fp) || !valid_mem(fp-12)) { + //debug_printf("core %d: 0x%08x is not a valid FP address\r\n", core_num, fp); + + // YOLO lr and give up + frame_buf[framenum++] = lr - LR_OFFSET; + goto FINISH; + } + + // Now just trust the frame pointers. + while (valid_mem(fp) && valid_mem(fp-12) && framenum < max_frames) { + mem_read32(fp-4, &fplr); + //mem_read32(fp-8, &fpsp); + mem_read32(fp-12, &fpfp); + + if (fp == fpfp) { + // don't get stuck in a loop. also, if fp points back to itself, then + // we don't want to include this LR + break; + } + + //debug_printf("core %d: %d: fp=0x%08x fplr=0x%08x fpsp=0x%08x fpfp=0x%08x\r\n", core_num, framenum, fp, fplr, fpsp, fpfp); + if (!valid_pc(fplr)) { + //debug_printf("fplr 0x%08x is not valid!\r\n", fplr); + break; + } + + frame_buf[framenum++] = fplr - LR_OFFSET; + fp = fpfp; + } + +FINISH: + core_select(core_num); + core_unhalt(); + + // Note: without this, the core remains halted. Unclear why this is needed, + // someone with more SWD experience will know. + rc = core_update_status(); + if (rc != SWD_OK) { + debug_printf("core_update_status failed: %d\r\n", rc); + } + + *sample_time = tstart; + *us_out = time_us_32() - tstart; + + //if (core_num == 1) { debug_printf("core %d: pc: 0x%08x lr: 0x%08x final fp: 0x%08x\r\n", pc, lr, fp); } + + return framenum; +} + +// +// data writing function +// +int write_frames(int core_num, uint32_t timestamp, uint32_t* frame_buf, int num_frames) { + uint32_t header = 0; + header |= (SAMPLE_CMD | core_num) << 24; // 0xb0 | core_num = sample indicator + header |= num_frames & 0xfff; // num frames to follow + + // 0 slot is reserved for this purpose + frame_buf[0] = header; + frame_buf[1] = timestamp; + + // TODO -- this blocks, I think we'd rather drop samples? +#if true + io_put_bytes(prof_io, (uint8_t*) frame_buf, sizeof(uint32_t) * (num_frames + NUM_RESERVED_FRAMES)); + +#if false + if (core_num == 1) { + debug_printf("core[%d]: write: 0x%08x 0x%08x 0x%08x", core_num, frame_buf[0], frame_buf[1], frame_buf[2]); + for (int i = 1; i < num_frames; i++) + debug_printf(" 0x%08x", frame_buf[NUM_RESERVED_FRAMES+i]); + debug_printf("\r\n"); + } +#endif +#else + uint32_t *fb = frame_buf+NUM_RESERVED_FRAMES; + io_printf(prof_io, "core %d pc 0x%08x lr 0x%08x next 0x%08x\r\n", core_num, fb[0], fb[1], fb[2]); +#endif + + return 0; +} + +DEFINE_TASK(prof, 1024); + +void func_prof(void *arg) { + // Initialise the IO mechanism for the profiler; CDC only + prof_io = io_init(PROF_CDC, 0, 4096); + + debug_printf("PROF initialized\r\n"); + + while (1) { + prof_task(); + } +} + +void prof_init() { + CREATE_TASK(prof, func_prof, NULL); +} \ No newline at end of file