# QMK XAP Debugging and Tracing Subsystem

## Motivation

The existing CONSOLE and [debbugging facilities](https://github.com/qmk/qmk_firmware/blob/master/tmk_core/common/debug.h) in QMK allow printf-style debugging messages using raw USB HID reports. Currently granular control over Matrix changes, send USB reports, mouse(keys), scan rates, log and error messages. This is fine for simple test cases but has its limits for more complex use cases.

## Goals / Implementation

* Completely replace CONSOLE and current debug facilities as XAP subsystem.
* Sinks/Sources independent of USB for usage with split or BT keyboards that don't have an active USB connection. Could also be handy for Keyboards that fail in early init were USB is not active but USART is.
* SWD with SWO or Concurrent access over background memory access available on some cortex-m cores.
* JTAG
* BT
* USART
* Granular logging levels *(encoded as flag in message type?)*:
* **debug** *(matrix changes)*
* **error** *(spilt comms errors)*
* **info** *(matrix scan rate)*
* **trace** *(profiling events, cause-reaction tracking see below)*
* Maybe this should be its own type with context information like:
* event id (matrix scan, debounce, rgb matrix task, split transport),
* event start and end flag
* cycle accurate time stamp for profiling
* **warn** *(maybe if power negotiation failed for higher currents but we choose to ignore it?)*
* Cycle accurate time stamps for profiling functions, hot-paths. Has to be platform dependent and optimized for fast as possible retrieval (ChibiOS chSysGetRealtimeCounterX())
* On ARM with DWT e.g. M3/M4/M7 cores [DWT_CYCCNT counters](https://developer.arm.com/documentation/ddi0439/b/BABJFFGJ)
* On ARM without DWT e.g. M0/M0+ cores use the SysTick Timer
* On [RV MCYCLE counter](https://www.five-embeddev.com/riscv-isa-manual/latest/machine.html#hardware-performance-monitor)
* On AVR use [hand rolled AVR-Tick-Counter?](https://github.com/malcom/AVR-Tick-Counter)
* (Optional?) Formatting of log messages on the host instead of doing it with printf on the keyboard. [SEGGER RTT](https://wiki.segger.com/RTT) or [defmt](https://github.com/knurling-rs/defmt) as inspiration.
* Log/Tracing message queue implemented as in memory ring buffer for fast nearly non-blocking access.
* Tracing could work like this *(see prototype output below)*:
1. Start tracing events for e.g. 5s.
2. Write tracing events to buffer (just event id, start/stop and time stamp).
3. Stop tracing events.
4. Transfer buffer to host which could be time consuming.
* Associate QMK events with key press/release or other events
* **Example use-case:** The key-press at col x and row x at time stamp xxx, interrupted the tapping timer which had the value of xxx and triggered the tapping key xxx. This resulted in a USB report to be send at xxx with the following content xxxxxxxx.
* Maybe allow plotting of event graphs at runtime
* Provide default debug reports, that can be retrieved for investigating issues *(info.json compressed and embedded in firmware?)*
* Debouncing type, enabled QMK subsystems etc.
* TBC.
* Provide default profiling test cases:
* latency measurements as shown by [Michael Stapelberg](https://michael.stapelberg.ch/posts/2021-05-08-keyboard-input-latency-qmk-kinesis/)
* Performance under heavy usage or idle.
* How often does the system sleep / wake up? This is relevant once QMK is optimized for power usage in BT applications.
* Where is the most time spend in QMK e.g. have default trace points for every task in keyboard.c that can be enabled when compiling.
* TBC.

## Thoughts

* Cross cutting concerns between QMK subsystem and QMK Debugging / Tracing e.g. Matrix scan rates, negotiated USB power limit, USB polling rates are nice to display in regular usage so where should these go? On the other hand latency measurements, tracing events and error messages are clearly debugging territory.
* As this will be scattered across all of QMK, will this interfere with a possible libQMK rewrite or how can this be made adaptable?

## Tracing prototype

First mvp tracing prototype. It just logs into a memory buffer until it is full and outputs the content once every second via the QMK console.

Example output *(these are actual real numbers in cycles)*

Matrix Scan Local        : 423
Serial Transaction       : 2497
Serial Transaction       : 2475
Split Transport Complete : 6863
Matrix Scan Complete     : 7433
Matrix Task              : 7984
RGB Matrix Task          : 568
OLED Task                : 284
Keyboard Loop Complete   : 9307

### Usage

e.g. in `keyboard.c` add:

#ifdef RGB_MATRIX_ENABLE
    START_TRACE(TRACE_RGB_MATRIX_TASK);
    rgb_matrix_task();
    STOP_TRACE(TRACE_RGB_MATRIX_TASK);
    PRINT_TRACE_EVENTS;
#endif

**debug.h**

#if !defined(NO_TRACE)

// clang-format off

typedef enum { 
    TRACE_KEYBOARD_LOOP,
    TRACE_MATRIX_SCAN,
    TRACE_MATRIX_SCAN_LOCAL,
    TRACE_MATRIX_TASK,
    TRACE_SPLIT_TRANSPORT,
    TRACE_SERIAL_TRANSACTION,
    TRACE_ACTION_EXEC_TICK,
    TRACE_ACTION_EXEC,
    TRACE_RGB_MATRIX_TASK,
    TRACE_OLED_TASK,
    TRACE_CUSTOM,
    TRACE_NUM
} trace_event_t;

typedef struct {
    cycle_timer_t time;
    trace_event_t id;
} trace_t;

// clang-format on

trace_t trace_start(trace_event_t id);
void    trace_stop(trace_t event);
void    trace_print_events(void);

#    define START_TRACE(ID) trace_t ID##_event = trace_start(ID);
#    define STOP_TRACE(ID)           \
        do {                         \
            trace_stop(ID##_event); \
        } while (0)
#    define PRINT_TRACE_EVENTS trace_print_events();

#else
#    define trace_start
#    define trace_stop
#    define trace_print_events
#    define START_TRACE(ID)
#    define STOP_TRACE(ID)
#    define PRINT_TRACE_EVENTS

#endif

**debug.c**

#if !defined(NO_TRACE)

#define TRACE_BUFFER_SIZE 100

uint_fast8_t trace_buffer_head;
trace_t      trace_buffer[TRACE_BUFFER_SIZE];

const char *const trace_event_names[TRACE_NUM] = {
    [TRACE_KEYBOARD_LOOP] = "Keyboard Loop Complete",
    [TRACE_MATRIX_SCAN] = "Matrix Scan Complete",
    [TRACE_MATRIX_SCAN_LOCAL] = "Matrix Scan Local",
    [TRACE_MATRIX_TASK] = "Matrix Task Complete",
    [TRACE_ACTION_EXEC] = "Action Exec Keypr.",
    [TRACE_ACTION_EXEC_TICK] = "Action Exec Tick",
    [TRACE_SPLIT_TRANSPORT] = "Split Transport",
    [TRACE_SERIAL_TRANSACTION] = "Serial Transaction",
    [TRACE_RGB_MATRIX_TASK] = "RGB Matrix Task",
    [TRACE_OLED_TASK] = "OLED Task",
    [TRACE_CUSTOM] = "Custom Trace"
};

inline trace_t trace_start(trace_event_t id) { return (trace_t){.id = id, .time = timer_read_cycles()}; }

inline void trace_stop(trace_t event) {
    event.time = timer_read_cycles() - event.time;
    if (trace_buffer_head < TRACE_BUFFER_SIZE) {
        trace_buffer[trace_buffer_head] = event;
        trace_buffer_head++;
    }
}

inline void trace_print_events(void) {
    static uint32_t trace_timer = 0;

    uint32_t timer_now = timer_read32();
    if (TIMER_DIFF_32(timer_now, trace_timer) < 1000) {
        return;
    }

    trace_timer            = timer_now;
    trace_t* current_event = trace_buffer;

    for (uint_fast8_t tail = 0; tail < trace_buffer_head; tail++) {
        xprintf("%-25s: %d\n", trace_event_names[current_event->id], current_event->time);
        if(current_event->id == TRACE_KEYBOARD_LOOP){
            println("");
        }
        current_event++;
    }

    trace_buffer_head = 0;
}

#endif

**timer.h**

#if defined(__riscv__)
typedef uint64_t cycle_timer_t;
#else
typedef uint32_t cycle_timer_t;
#endif

cycle_timer_t timer_read_cycles(void);

**timer.c (chibios)**

inline cycle_timer_t timer_read_cycles() { return chSysGetRealtimeCounterX(); }