Логирование и трассировка в прошивке

Каналы вывода

Блокирующий вывод через UART — самый медленный вариант: на 115 200 бод кадр 8N1 занимает 86,8 мкс, и строка из 40 символов идёт 40 · 86,8 мкс ≈ 3,5 мс. Всё это время процессор крутится в ожидании флага «регистр данных пуст». В программе с циклом управления на 1 кГц одна такая строка съедает три с половиной периода. Посчитать время кадра для других скоростей и форматов помогает инструмент «Кадр UART».

printf через UART

AVR и avr-libc

В avr-libc printf пишет в поток stdout, а поток связывают с функцией вывода символа макросом FDEV_SETUP_STREAM — без выделения памяти через malloc:

#include <stdio.h>
#include <avr/io.h>

static int uart_putchar(char c, FILE *stream)
{
    if (c == '\n')
        uart_putchar('\r', stream);          /* terminals expect CR LF */
    loop_until_bit_is_set(UCSR0A, UDRE0);
    UDR0 = (uint8_t)c;
    return 0;
}

static FILE uart_out = FDEV_SETUP_STREAM(uart_putchar, NULL, _FDEV_SETUP_WRITE);

int main(void)
{
    uart_init();
    stdout = &uart_out;
    printf("boot, MCUSR=%02x\n", mcusr_mirror);
    for (;;) { }
}

По умолчанию компонуется сокращённая версия vfprintf без чисел с плавающей точкой; полную подключают ключами -Wl,-u,vfprintf -lprintf_flt -lm, минимальную — -Wl,-u,vfprintf -lprintf_min. Разница во флеш-памяти — килобайты, поэтому чаще печатают целые: милливольты вместо вольт. Подробно настройка UART и printf для ATmega328P разобрана в уроке «UART и printf», а принимать вывод на компьютере удобно в последовательном терминале.

Функция выше ждёт освобождения передатчика. Чтобы printf не тормозил программу, uart_putchar кладёт символ в кольцевой буфер передачи и включает прерывание по пустому регистру данных — как это сделать, показано в статье о кольцевом буфере для UART. Тогда цена вывода — время форматирования и копирования, а передача идёт в фоне. Если буфер переполнен, приходится выбирать: ждать (и тормозить) или терять строки; для журнала обычно лучше терять и считать потери.

STM32 и newlib

Библиотека newlib, которая идёт с arm-none-eabi-gcc, выводит в любой файл, включая stdout, через системный вызов write (документация newlib, System Calls). В проектах STM32CubeIDE файл syscalls.c уже содержит слабую функцию _write, которая для каждого символа вызывает __io_putchar(). Остаётся определить её:

#include <stdio.h>
#include "stm32f1xx.h"

int __io_putchar(int ch)
{
    while (!(USART1->SR & USART_SR_TXE)) { }   /* blocking: simplest, slowest */
    USART1->DR = (uint8_t)ch;
    return ch;
}

void log_init(void)
{
    setvbuf(stdout, NULL, _IONBF, 0);          /* no buffering: characters go out at once */
}

Вызов setvbuf(stdout, NULL, _IONBF, 0) (C11, 7.21.5.6) отключает буферизацию stdout. Без него символы могут копиться в буфере библиотеки и выйти пачкой позже — или не выйти вовсе перед зависанием, ради которого печать и добавляли.

ITM и SWO

У ядер Cortex-M3, M4 и M7 есть модуль ITM (Instrumentation Trace Macrocell): набор портов-стимулов — до 256, их число кратно восьми (ARMv7-M ARM, C1.7). Запись в порт превращается в пакет трассировки, который блок TPIU выводит наружу — в недорогих отладочных схемах через однопроводной вывод SWO (Serial Wire Output). Отладчик принимает пакеты и показывает их как текст. В руководстве по Cortex-M0 (DUI 0497A) ITM не упоминается вовсе — для таких ядер остаются UART и RTT.

Со стороны прошивки всё сводится к функции CMSIS ITM_SendChar():

/* CMSIS 6, core_cm3.h (abridged) */
__STATIC_INLINE uint32_t ITM_SendChar(uint32_t ch)
{
    if (((ITM->TCR & ITM_TCR_ITMENA_Msk) != 0UL) &&   /* ITM enabled */
        ((ITM->TER & 1UL) != 0UL))                    /* port 0 enabled */
    {
        while (ITM->PORT[0U].u32 == 0UL) { __NOP(); } /* wait until the port is ready */
        ITM->PORT[0U].u8 = (uint8_t)ch;
    }
    return ch;
}

Если ITM не включён — отладчик не подключён или не настроил трассировку, — функция сразу возвращается, и вывод ничего не стоит. Архитектура требует, чтобы запись в порт выключенного или отсутствующего ITM не вызывала ошибку шины (ARMv7-M ARM, C1.1). Поэтому вызовы ITM можно оставлять и в сборке, которая работает без отладчика. Перенаправить на ITM printf из newlib — значит переопределить _write:

int _write(int file, char *ptr, int len)
{
    (void)file;
    for (int i = 0; i < len; i++)
        ITM_SendChar((uint32_t)(uint8_t)ptr[i]);
    return len;
}

Настройка SWO

Блоки ITM и TPIU обычно настраивает отладчик — STM32CubeIDE, OpenOCD или J-Link — по заданной в нём частоте ядра и скорости SWO. Прошивке достаточно не мешать. Но знать, что настраивается, полезно, чтобы понять, почему вывод не работает:

• Разрешение трассировки: бит TRCENA (бит 24) регистра DEMCR включает блоки DWT и ITM (ARMv7-M ARM, C1.6.5). В CMSIS 6 это DCB->DEMCR |= DCB_DEMCR_TRCENA_Msk; старое имя CoreDebug->DEMCR с CoreDebug_DEMCR_TRCENA_Msk оставлено как синоним.
• Скорость: частота SWO = TRACECLKIN / (PRESCALER + 1), где PRESCALER — значение регистра TPIU_ACPR по адресу 0xE0040010 (Cortex-M3 TRM, 11.3.1). У STM32F1 TRACECLKIN подключён к HCLK (RM0008, 31.17.8). При HCLK = 72 МГц и PRESCALER = 35 получаем 72 / 36 = 2 Мбит/с.
• Протокол: регистр TPIU_SPPR выбирает асинхронный SWO с кодом NRZ (значение 2) или с манчестерским кодом (1) (ARMv7-M ARM, C1.10.5).
• Включение ITM и порта: бит ITMENA регистра ITM_TCR разрешает ITM в целом, а бит 0 регистра ITM_TER — порт 0, в который пишет ITM_SendChar(); без них функция CMSIS молча ничего не выводит (ARMv7-M ARM, C1.7.4 и C1.7.6).
• Форматтер TPIU: в режиме SWO бит EnFCont (бит 1) регистра TPIU_FFCR по адресу 0xE0040304 включает форматтер, а сброшенный — пропускает его, и на выход идут только пакеты ITM и DWT; значение после сброса — 0x102, бит установлен. Когда по SWO нужны только ITM и DWT, форматтер обходят, сбрасывая этот бит; включение и выключение форматтера на ходу на мгновение портит данные (Cortex-M3 TRM, 11.3.3).
• Вывод: у STM32F103 SWO — это PB3, общий с JTDO. Асинхронная трасса работает только с отладочным портом SW-DP, то есть с отладкой по SWD, а не по JTAG (RM0008, 31.3). В регистре DBGMCU_CR биты TRACE_IOEN = 1 и TRACE_MODE = 00 назначают вывод под асинхронную трассу.

Из того, что TRACECLKIN равен HCLK, следует частая проблема: прошивка переключает тактирование с HSI на PLL, а отладчик настроил SWO под одну частоту — и после переключения в окне вывода мусор. Частоту ядра в настройках отладчика задают ту, на которой программа работает после инициализации, а вывод до переключения тактирования не используют. RM0008 отдельно предупреждает об этом в 31.17.8. Подробнее о выводе — в глоссарии: SWO.

SEGGER RTT

RTT (Real Time Transfer) — механизм SEGGER для обмена с отладчиком J-Link через память. В ОЗУ микроконтроллера лежит управляющий блок: он начинается с идентификатора, по которому отладчик находит его в памяти, и содержит описатели кольцевых буферов. Буферы «вверх» передают данные от прошивки к компьютеру, «вниз» — обратно. У буфера вверх указатель записи меняет только прошивка, а указатель чтения — только отладчик, у буфера вниз — наоборот. Это ровно схема «один писатель, один читатель» из статьи о кольцевом буфере, где второй стороной выступает отладчик, читающий память по SWD, пока процессор работает.

#include "SEGGER_RTT.h"

void report(int32_t temp_mc)
{
    SEGGER_RTT_WriteString(0, "boot\n");
    SEGGER_RTT_printf(0, "temp=%d mC\n", temp_mc);
}

Что важно знать (по документации SEGGER):

• Цена: около 500 байт кода, 24 байта идентификатора и по 24 байта на канал в ОЗУ плюс сами буферы. Строка выводится примерно за микросекунду — по сути, это копирование в память.
• Канал 0 создаётся при компиляции, его размер задаёт BUFFER_SIZE_UP; остальные каналы настраивают функциями SEGGER_RTT_ConfigUpBuffer() и SEGGER_RTT_ConfigDownBuffer().
• Режим при заполненном буфере: блокирующий (ждать, пока отладчик заберёт данные — без отладчика программа встанет), без блокировки с пропуском всей записи или с обрезкой. Для журнала, который остаётся в рабочей прошивке, выбирают неблокирующий режим.
• Поиск блока: отладчик ищет идентификатор в заданном диапазоне ОЗУ; при большом ОЗУ поиск занимает время, и адрес блока можно указать явно.

Ограничение RTT — отладчик: нужен J-Link или совместимое с RTT средство. Зато не нужны ни свободный UART, ни вывод SWO: SEGGER указывает, что фоновое чтение памяти работает на ядрах Cortex-M, где к памяти всегда есть доступ через AHB-AP, а значит, и на ядрах без ITM.

Уровни журнала

Отладочные строки занимают флеш-память — каждая строка формата хранится целиком — и время. Поэтому сообщения делят по уровням, а лишние уровни отсекают при компиляции: тогда в рабочей сборке их нет ни в коде, ни во флеш-памяти.

/* log.h */
#ifndef LOG_H
#define LOG_H

#include <stdint.h>
#include <stdio.h>

enum { LOG_LVL_NONE, LOG_LVL_ERROR, LOG_LVL_WARN, LOG_LVL_INFO, LOG_LVL_DEBUG };

#ifndef LOG_LEVEL
#define LOG_LEVEL LOG_LVL_INFO               /* override with -DLOG_LEVEL=... */
#endif

uint32_t log_timestamp(void);                /* milliseconds or cycles */

#define LOG_AT(lvl, tag, ...)                                           \
    do {                                                                \
        if ((lvl) <= LOG_LEVEL) {                                       \
            printf("%lu %s %s:%d: ", (unsigned long)log_timestamp(),    \
                   (tag), __FILE__, __LINE__);                          \
            printf(__VA_ARGS__);                                        \
            putchar('\n');                                              \
        }                                                               \
    } while (0)

#define LOG_E(...) LOG_AT(LOG_LVL_ERROR, "E", __VA_ARGS__)
#define LOG_W(...) LOG_AT(LOG_LVL_WARN,  "W", __VA_ARGS__)
#define LOG_I(...) LOG_AT(LOG_LVL_INFO,  "I", __VA_ARGS__)
#define LOG_D(...) LOG_AT(LOG_LVL_DEBUG, "D", __VA_ARGS__)

#endif

Условие (lvl) <= LOG_LEVEL — константное выражение, и при LOG_LEVEL = LOG_LVL_INFO компилятор выбросит вызовы LOG_D вместе со строками форматов. Макрос принимает формат и аргументы через __VA_ARGS__ (C11, 6.10.3), поэтому работает и с одной строкой без аргументов: LOG_I("boot"). Обёртка do { … } while (0) делает макрос одним оператором, и он безопасен в if без фигурных скобок. __FILE__ даёт полный путь к файлу, который тоже занимает флеш-память; в больших проектах вместо него передают короткий тег модуля.

Хорошие правила для текста сообщений: одно событие — одна строка; числа, а не слова («adc=1873», а не «значение нормальное»); ключи и единицы в строке («t=23500 mC»), чтобы журнал можно было разбирать скриптом.

Метки времени: счётчик тактов DWT

Без времени журнал отвечает на вопрос «что», но не «когда» и «как долго». Миллисекунды от SysTick подходят для событий, а для измерения длительности функций нужен счётчик тактов DWT — 32-битный регистр DWT->CYCCNT, который увеличивается каждый такт ядра:

#include "stm32f4xx.h"

void cycles_init(void)
{
    CoreDebug->DEMCR |= CoreDebug_DEMCR_TRCENA_Msk;   /* DCB->DEMCR in CMSIS 6 */
    DWT->CYCCNT = 0;
    DWT->CTRL |= DWT_CTRL_CYCCNTENA_Msk;
}

static inline uint32_t cycles_now(void)
{
    return DWT->CYCCNT;
}

void measure_process_frame(void)       /* usage: time one call */
{
    uint32_t t0 = cycles_now();
    process_frame();
    uint32_t dt = cycles_now() - t0;   /* unsigned difference survives a wrap */
    LOG_D("process_frame: %lu cycles", (unsigned long)dt);
}

На 72 МГц счётчик переполняется через 2^32 / 72 000 000 ≈ 59,7 с, и беззнаковая разность остаётся правильной, пока измеряемый интервал короче. Счётчик тактов есть не во всех реализациях: архитектура допускает упрощённый DWT без него (ARMv7-M ARM, C1.1), а в руководстве по Cortex-M0 (DUI 0497A) блока DWT нет вовсе. Подробнее — в глоссарии: счётчик тактов DWT. Тем же способом стоит измерить и сам вывод: сколько тактов занимает LOG_I с форматированием — часто это сюрприз.

Логирование и прерывания

Форматированная печать в обработчике прерывания — плохая идея по трём причинам. Она долгая: форматирование числа занимает сотни и тысячи тактов, а блокирующий вывод — миллисекунды. Она нереентерабельна: если основной цикл был внутри printf, когда пришло прерывание, второй вызов испортит общее состояние библиотеки. И она меняет тайминг ровно там, где он важнее всего. Подробно о нереентерабельных функциях — в статье о прерываниях и общих данных.

Вместо этого обработчик кладёт в очередь короткую запись — код события, время, одно-два числа, — а основной цикл форматирует и выводит:

#include <stdint.h>

typedef struct {
    uint32_t t;                  /* cycles or ms */
    uint16_t code;               /* event id */
    uint16_t arg;
} log_event_t;

#define LOG_Q_SIZE 32u           /* power of two */
static log_event_t log_q[LOG_Q_SIZE];
static volatile uint8_t log_head, log_tail;
static volatile uint16_t log_lost;

void log_event_isr(uint16_t code, uint16_t arg)      /* the only producer: one ISR priority */
{
    uint8_t head = log_head;
    if ((uint8_t)(head - log_tail) >= LOG_Q_SIZE) {
        log_lost++;
        return;
    }
    log_q[head & (LOG_Q_SIZE - 1u)] = (log_event_t){ cycles_now(), code, arg };
    __asm__ __volatile__ ("" ::: "memory");          /* entry before the index */
    log_head = (uint8_t)(head + 1u);
}

Основной цикл забирает записи тем же способом, что и байты из кольцевого буфера, и печатает их не спеша. Если писать в очередь могут обработчики разных приоритетов, они вытесняют друг друга, и запись выполняют при запрещённых прерываниях. Развитие этой идеи — двоичный журнал: в прошивке хранится только номер сообщения и аргументы, а строки форматов остаются на компьютере, который и собирает из них текст. Такой журнал на порядок экономнее и по флеш-памяти, и по времени.

Журнал в рабочей прошивке

Журнал полезен не только при разработке. В рабочей сборке оставляют уровни ERROR и WARN и счётчики событий — потерянные байты UART, ошибки CRC, перезапуски по сторожевому таймеру. Последние записи перед сбоем стоит держать в кольцевом буфере в секции .noinit: после сброса они сохранятся, и программа отправит их при следующем подключении. Так же хранят регистры HardFault — пример в статье о переполнении стека и ошибках памяти.

Типичные ошибки

• Блокирующий printf в цикле управления — тайминг меняется, ошибка «пропадает» при включении печати и возвращается без неё.
• printf в обработчике прерывания — долгий обработчик и порча состояния библиотеки при вложенном вызове.
• Буферизация stdout — последние строки перед зависанием не выводятся; setvbuf(stdout, NULL, _IONBF, 0) или явный fflush.
• Частота ядра в настройках SWO не та — мусор вместо текста после переключения тактирования.
• SWO при отладке по JTAG — у STM32F1 асинхронная трасса работает только с SWD.
• RTT в блокирующем режиме без отладчика — программа останавливается на первой заполненной записи.
• float в printf на AVR без -lprintf_flt — вместо числа печатается знак вопроса.
• Отладочные строки в рабочей сборке — флеш-память занята форматами, которые никто не прочитает; уровни отсекают при компиляции.