35г. Журнал на приборе: уровни, кольцевой буфер и двоичные записи вместо printf

Текстовый вывод в справочнике уже разобран: printf в порт (16.6), ITM и SWO (раздел 21), RTT (21а), цена printf в байтах (74.4). Раздел 35в сохранил слепок отказа, раздел 112 принял журнал на сервере. Не хватает середины — самого журнала на приборе. Такого, чтобы писать в него можно было из прерывания, чтобы строки не занимали флеш-память и чтобы выключенные сообщения не стоили ничего.

Здесь — такой журнал целиком: 776 байт кода на Cortex‑M3. Уровней четыре; лишние отсекаются при сборке. Запись — это слова в кольцевом буфере в ОЗУ: номер сообщения, время и сырые аргументы; на неё уходит от 60 до 93 команд. Строки формата в прошивку не попадают. Они остаются на компьютере, в словаре, который строит скрипт на Python. Фоновый цикл выдаёт записи в линию кадрами COBS с CRC‑16, декодер на компьютере превращает их обратно в строки. Всё показано прогоном: 5000 случайных сообщений сверены с настоящим printf, поток портили и рвали, кольцо переполняли, прошивку гоняли в QEMU и сравнили с snprintf по размеру, байтам в линии и числу команд.

Идея известна по открытому проекту Trice (github.com/rokath/trice). Его исходники не использовались: весь код раздела свой.

Опоры: раздел 194 — кадр COBS и CRC‑16/XMODEM, здесь тот же алгоритм; раздел 127 — макросы ##, __LINE__ и _Static_assert; раздел 21а — кольцо и счёт команд в QEMU. Опыты на компьютере — образ stm-sys:1 (gcc 12.2.0, Python 3.11.2): тот же файл журнала собран для ПК и прогнан против декодера. Опыты для Cortex‑M — образ stm-arm:1: arm-none-eabi-gcc 12.2.1 с ключом -Os, newlib-nano, QEMU 7.2.22 (stm32vldiscovery для F1 и netduinoplus2 для F4), gdb 13.1. Тот же код собран armclang 6.24.

Как это называется в документации

Оригинал	Перевод
log level	уровень журнала
compile-time filtering	отсечение при сборке
ring buffer	кольцевой буфер
deferred logging	отложенная выдача: записать сейчас, вывести потом
binary (dictionary-based) logging	двоичный журнал со словарём
format string	строка формата
message ID	номер сообщения
drop newest / drop oldest	терять новые / терять старые
frame delimiter	разделитель кадров
sequence counter	счётчик кадров

35г.1 Что уходит в прибор, а что остаётся на компьютере

В программе вызов журнала выглядит как printf с уровнем:

    case 1:
        DLOG_D("adc ch %u raw %u", (unsigned)a & 15u, (unsigned)b & 4095u);
        break;
    case 2:
        DLOG_W("temp %d.%u C over limit %d", a / 10, (unsigned)(a < 0 ? -a : a) % 10u, b);
        break;
    case 3:
        DLOG_E("i2c nack addr 0x%02x reg 0x%02x try %u", (unsigned)a & 0x7Fu, (unsigned)b & 0xFFu, (unsigned)c & 7u);
        break;

printf сделал бы три вещи на приборе: разобрал строку формата, перевёл числа в текст и вывел символы. Всё это — работа, которую можно отложить и отдать компьютеру. Строка формата известна уже при сборке. Значит, в прибор достаточно передать её номер и аргументы как есть, по четыре байта.

Запись в кольце — слова по 32 бита: заголовок, время и аргументы. Заголовок устроен так:

/* Заголовок записи в кольце — одно слово. Младшие 16 бит уходят в линию как есть. */
#define DLOG_ID(h)    ((h) & 0x3FFFu)            /* биты 13:0  — номер сообщения */
#define DLOG_LVL(h)   (((h) >> 14) & 3u)         /* биты 15:14 — уровень */
#define DLOG_NARG(h)  (((h) >> 16) & 7u)         /* биты 18:16 — число аргументов */
#define DLOG_LOST(h)  ((h) >> 19)                /* биты 31:19 — сколько записей потеряно перед этой */
#define DLOG_LOST_MAX 0x1FFFu                    /* 8191 значит «не меньше 8191» */
#define DLOG_ID_LOST  0u                         /* служебные номера: метка потери … */
#define DLOG_ID_START 1u                         /* … и метка запуска с отпечатком словаря */

Номеров — 14 бит, то есть 16 384; два из них служебные. Уровень едет в линию вместе с номером, число аргументов и счётчик потерь нужны только самому прибору. В линию запись уходит кадром: номер с уровнем (2 байта), счётчик кадров (1), время (4), аргументы (по 4) и CRC‑16 (2). Это 9 + 4·n байт; COBS добавляет один байт, разделитель — ещё один. Итого 11 + 4·n байт: 11 без аргументов, 19 с двумя, 27 с четырьмя.

Вот сообщение adc ch 5 raw 1234 из прогона в QEMU — как прошивка собрала его и как выдала в UART:

frame decoded: 03 c0 02 fa 00 00 00 05 00 00 00 d2 04 00 00 f7 64 (17 bytes)
frame on line: 05 03 c0 02 fa 01 01 02 05 01 01 03 d2 04 01 03 f7 64 00 (19 bytes)

03 c0 — номер 3 и уровень 3 (D) в старших битах, 02 — третий кадр с запуска, fa 00 00 00 — время 250, дальше 5 и 1234, в конце CRC. Строки adc ch %u raw %u в кадре нет, и в образе прошивки её нет тоже. Декодер со словарём выдал начало журнала так:

0 E start, dictionary 2c9c6546 (same)
250 I state idle -> run
250 D adc ch 5 raw 1234
250 D pid e -12 i 3400 d -7 out 3388
1316 D pid e -192621 i 39532774 d 6009 out 39340153

Первое число — время, буква — уровень. Первая строка — служебная запись о запуске; о ней в 35г.4.

У такого журнала три ограничения, и все они сознательные. Аргументы — только целые до 32 бит: %d, %i, %u, %x, %X, %c с флагами и шириной. Строк %s нет: строку пришлось бы копировать в кольцо целиком. Вещественных нет: их печатают целыми с масштабом (74.4). Аргументов — не больше семи.

35г.2 Уровни: порог при сборке и порог на ходу

Уровней четыре: ошибки E, предупреждения W, сведения I, отладка D. Порогов два. Первый — при сборке: макрос DLOG_BUILD говорит, сколько уровней вообще попадает в образ. Второй — на ходу: dlog_set_level() отсекает уже собранные сообщения, не трогая прошивку.

/* Только объявление: компилятор сверяет формат с аргументами, кода и строки в образе нет. */
int dlog_fmt_check(const char *fmt, ...) __attribute__((format(printf, 1, 2)));

#define DLOG_CAT_(a, b, c) a##b##_##c
#define DLOG_CAT(a, b, c) DLOG_CAT_(a, b, c)
#define DLOG_HERE(prefix) DLOG_CAT(prefix, DLOG_FILE, __LINE__)   /* DLOG_H_app35g_27 */

#ifndef DLOG_SINK                        /* стенд подменяет приёмник, чтобы сравнить с printf */
#define DLOG_SINK(lvl, fmt, ...) dlog_put(DLOG_HERE(DLOG_H_) | ((lvl) << 14), ##__VA_ARGS__)
#endif

#define DLOG_OFF(fmt, ...) ((void)sizeof(dlog_fmt_check(fmt, ##__VA_ARGS__)))
#define DLOG_ON(lvl, fmt, ...)                                                                  \
    do {                                                                                        \
        _Static_assert(sizeof(fmt) - 1 == DLOG_HERE(DLOG_L_), "dlog_ids.h is stale: run dlog_gen.py"); \
        DLOG_OFF(fmt, ##__VA_ARGS__);                                                           \
        DLOG_SINK(lvl, fmt, ##__VA_ARGS__);                                                     \
    } while (0)

#if DLOG_BUILD > 0
#define DLOG_E(fmt, ...) DLOG_ON(DLOG_ERR, fmt, ##__VA_ARGS__)
#else
#define DLOG_E(fmt, ...) DLOG_OFF(fmt, ##__VA_ARGS__)
#endif

Макросы DLOG_W, DLOG_I, DLOG_D устроены так же, с порогами 1, 2 и 3. Вся хитрость — в DLOG_OFF. Выключенный вызов превращается в sizeof от вызова функции dlog_fmt_check. Оператор sizeof свой аргумент не вычисляет, поэтому в образ не попадает ничего: ни кода, ни строки, ни самой функции — она только объявлена. Но объявлена с атрибутом format(printf, …), и компилятор всё равно сверяет формат с аргументами. В опыте вызов DLOG_D("x %d y %d", a) дал ошибку -Werror=format и при DLOG_BUILD=4, и при DLOG_BUILD=0: выключенное сообщение не сгниёт незаметно.

Что остаётся в образе, показывает размер. Одна и та же прошивка-стенд — шестнадцать сообщений, из них двенадцать в app35g.c, — собрана для Cortex‑M3 с -Os при пяти значениях DLOG_BUILD. Рядом — она же в текстовом варианте, где каждое сообщение уходит в snprintf (35г.6):

При нуле от двенадцати вызовов в app35g.o остаются 2 байта: вся функция — одна команда возврата bx lr. Каждый включённый уровень добавляет только свои вызовы. У двоичного журнала при нуле остаётся его ядро: стенд по-прежнему зовёт dlog_init и dlog_drain.

Вместе с кодом исчезают и аргументы. Это удобно — и это ловушка:

static unsigned calls;

static unsigned next_sample(void)
{
    return ++calls;
}

void dlog_put(uint32_t hdr, ...)
{
    (void)hdr;
}

int main(void)
{
    for (int i = 0; i < 10; i++)
        DLOG_D("sample %u", next_sample());
    printf("DLOG_BUILD=%d next_sample called %u times\n", DLOG_BUILD, calls);
    return 0;
}

DLOG_BUILD=4 next_sample called 10 times
DLOG_BUILD=3 next_sample called 0 times

При DLOG_BUILD=3 уровень D выключен, и next_sample() не вызвана ни разу. В аргументы журнала нельзя класть то, без чего программа не работает.

Порог на ходу — первая проверка в dlog_put (35г.3): уровень из заголовка сравнивается с байтом L.level. В опыте на компьютере из 5000 событий при пороге DLOG_WARN в линию ушли 1716 — только E и W, и все они совпали с эталоном. Порог на ходу удобно менять командой с компьютера: прибор в поле молчит, пока его не попросят рассказать подробнее.

35г.3 Кольцо записей: запись из прерывания, переполнение, отложенная выдача

Журнал делится на две половины. Быстрая, dlog_put, только кладёт слова в кольцо; её зовут из задач и из прерываний. Медленная, dlog_drain, кодирует и выводит; её зовёт фоновый цикл, когда есть время.

static struct {
    uint32_t ring[DLOG_WORDS];
    uint32_t head;                       /* слов записано за всё время; двигает только dlog_put */
    uint32_t tail;                       /* слов прочитано или выброшено */
    uint32_t pending;                    /* записей отброшено после последней принятой */
    uint8_t level;                       /* порог на ходу */
    uint8_t drop_old;                    /* 0 — терять новые, 1 — терять старые */
    uint8_t seq;                         /* счётчик кадров в линии */
} L;

Кольцо — массив слов, а не байтов: запись всегда кратна четырём байтам и аргументы копируются без упаковки. head и tail — не индексы, а счётчики слов за всё время; индекс получается маской. Поэтому размер кольца обязан быть степенью двойки — это закреплено _Static_assert. Занято слов — просто head - tail, и переход счётчиков через 2³² ничего не ломает. Это проверено: стенд со счётчиками, стартующими с 0xFFFFFF00, выдал поток, побайтно равный обычному.

static uint32_t add_lost(uint32_t hdr, uint32_t n)
{
    uint32_t v = DLOG_LOST(hdr) + n;
    if (v > DLOG_LOST_MAX)
        v = DLOG_LOST_MAX;
    return (hdr & 0x7FFFFu) | (v << 19);
}

void dlog_put(uint32_t hdr, ...)
{
    uint32_t n = DLOG_NARG(hdr), lost = 0;
    va_list ap;
    if (DLOG_LVL(hdr) > L.level)
        return;                          /* уровень выключен на ходу */
    va_start(ap, hdr);
    uint32_t key = dlog_lock();
    while (DLOG_WORDS - (L.head - L.tail) < n + 2u) {
        if (!L.drop_old) {               /* терять новые: запись не берём, только считаем */
            L.pending++;
            goto out;
        }
        uint32_t old = L.ring[L.tail & MASK];    /* терять старые: выбросить самую старую */
        L.tail += DLOG_NARG(old) + 2u;
        lost += DLOG_LOST(old) + 1u;
    }
    if (lost)                            /* новая самая старая несёт счёт: «передо мной потеряно» */
        L.ring[L.tail & MASK] = add_lost(L.ring[L.tail & MASK], lost);
    uint32_t w = L.head;
    L.ring[w++ & MASK] = add_lost(hdr, L.pending);
    L.pending = 0;
    L.ring[w++ & MASK] = dlog_now();
    while (n--)
        L.ring[w++ & MASK] = va_arg(ap, uint32_t);
    L.head = w;                          /* запись видна читателю только целиком */
out:
    dlog_unlock(key);
    va_end(ap);
}

Писателей может быть несколько: задача и прерывание, которое её перебило. Поэтому резерв места и запись слов идут при закрытых прерываниях:

static inline uint32_t dlog_lock(void)
{
    uint32_t key;
    __asm volatile("mrs %0, primask\n"
                   "cpsid i" : "=r"(key) :: "memory");
    return key;
}

static inline void dlog_unlock(uint32_t key)
{
    __asm volatile("msr primask, %0" :: "r"(key) : "memory");
}

Это критическая секция из 124.4: запомнить PRIMASK, закрыть, в конце вернуть как было — так функцию можно звать и там, где прерывания уже закрыты. Вопрос — надолго ли. gdb посчитал команды пошагово в QEMU:

Числа одинаковы для Cortex‑M3 и Cortex‑M4. Время берётся внутри закрытого участка: иначе запись с более поздним временем могла бы лечь в кольцо раньше. Отсюда требование к dlog_now() — она должна быть короткой и не ждать ничего. head сдвигается последним действием: читатель видит запись только целиком.

Переполнение. Если фоновый цикл не успевает, кольцо заполнится. Выбора два, и он задаётся в dlog_init. Терять новые: запись не берётся, растёт счётчик pending; следующая принятая запись унесёт его в старших битах своего заголовка. Терять старые: самые старые записи выбрасываются, пока не хватит места, а их число записывается в заголовок той, что стала самой старой. В обоих случаях в линию перед записью уходит служебное сообщение lost N — потеря видна в самой ленте, на своём месте.

Опыт на компьютере: кольцо в 256 слов, 5000 событий пачками по 100 без выдачи между ними, после пачки — выдача до дна.

Счёт сходится до единицы: ни одна запись не пропала молча. Меток при потере новых больше, чем пачек: в заполненное кольцо длинная запись уже не лезет, а короткая ещё может проскочить, и серия потерь рвётся на части. Что выбирать — зависит от вопроса. Начало пачки объясняет, с чего всё началось; конец — что было перед самым отказом, и тогда журнал хорошо дополняет слепок из 35в.

Задача и прерывание вместе. Третий шаг прошивки-стенда в QEMU: задача пишет 300 сообщений и после каждого выдаёт одну запись, а SysTick тем временем пишет из прерывания.

void SysTick_Handler(void)
{
    now_ms++;
    ticks++;
    DLOG_W("tick %u from interrupt", (unsigned)ticks);
}

    DLOG_I("task and interrupt write together");
    SYST_RVR = TICK_RELOAD - 1u;
    SYST_CVR = 0;
    SYST_CSR = 7u;                               /* такт ядра, прерывание, включён */
    for (unsigned i = 0; i < TASK_STEPS; i++) {
        DLOG_I("task step %u", i);
        dlog_drain();                            /* фоновый цикл: по одной записи за проход */
    }
    SYST_CSR = 0;
    DLOG_I("done: task %u, interrupt %u",
           TASK_STEPS, (unsigned)ticks);
    drain_all();

Декодер получил все 300 шагов задачи по порядку и все записи прерывания — в прогоне их 41 — тоже по порядку, без потерь и без единого испорченного кадра. Время в ленте нигде не идёт назад. Для сравнения тот же стенд собран в текстовом варианте, где прерывание печатает строку сразу. Там 24 строки из 471 оказались разорваны: прерывание вклинилось в строку задачи.

214585 I 214586 W tick 10 from interrupt

У двоичного журнала такого быть не может: в линию пишет только фоновый цикл.

35г.4 Словарь: номера выдаёт скрипт

Остался вопрос, откуда берётся номер. Писать номера руками нельзя: их перепутают в первый же день. Макрос собирает имя из названия файла и номера строки: в файле с #define DLOG_FILE app35g вызов в строке 15 разворачивается в DLOG_H_app35g_15. А значения этих имён пишет скрипт dlog_gen.py: он обходит исходники, находит вызовы и создаёт заголовок dlog_ids.h. Начало заголовка в прогоне:

/* Создан dlog_gen.py — не править. H: номер | число аргументов << 16; L: длина формата. */
#define DLOG_DICT_CRC 0x2c9c6546u
#define DLOG_H_app35g_12 0x00002u
#define DLOG_L_app35g_12 17
#define DLOG_H_app35g_15 0x20003u
#define DLOG_L_app35g_15 16

DLOG_H — готовая половина заголовка записи: номер 3 и два аргумента. DLOG_L — длина строки формата; её сверяет _Static_assert в макросе DLOG_ON. Вторым файлом скрипт пишет словарь для компьютера:

{
 "format": 1,
 "crc": "0x2c9c6546",
 "history": [],
 "messages": [
  {"id": 0, "fmt": "lost %u", "args": 1, "used": true},
  {"id": 1, "fmt": "start, dictionary %08x", "args": 1, "used": true},
  {"id": 2, "fmt": "state idle -> run", "args": 0, "used": true},
  {"id": 3, "fmt": "adc ch %u raw %u", "args": 2, "used": true},
  {"id": 4, "fmt": "temp %d.%u C over limit %d", "args": 3, "used": true},
  {"id": 5, "fmt": "i2c nack addr 0x%02x reg 0x%02x try %u", "args": 3, "used": true},
  {"id": 6, "fmt": "motor %c speed %6d rpm", "args": 2, "used": true},
  {"id": 7, "fmt": "crc %08x len %u", "args": 2, "used": true},
  {"id": 8, "fmt": "load 100%% for %u ms", "args": 1, "used": true},
  {"id": 9, "fmt": "assert line %d: %d != %d", "args": 3, "used": true},
  {"id": 10, "fmt": "queue %-5u of %5u, delta %+d", "args": 3, "used": true},
  {"id": 11, "fmt": "pid e %d i %d d %d out %d", "args": 4, "used": true},
  {"id": 12, "fmt": "mask %#x flags %04X", "args": 2, "used": true},
  {"id": 13, "fmt": "heartbeat", "args": 0, "used": true},
  {"id": 14, "fmt": "tick %u from interrupt", "args": 1, "used": true},
  {"id": 15, "fmt": "task and interrupt write together", "args": 0, "used": true},
  {"id": 16, "fmt": "task step %u", "args": 1, "used": true},
  {"id": 17, "fmt": "done: task %u, interrupt %u", "args": 2, "used": true}
 ]
}

Сам скрипт:

import json, os, re, sys, zlib

SERVICE = ["lost %u", "start, dictionary %08x"]          # номера 0 и 1 — служебные
ID_MAX, ARGS_MAX = 0x3FFF, 7
SKIP = r'//[^\n]*|/\*.*?\*/'                             # комментарии
LIT = r'"(?:\\.|[^"\\\n])*"'                             # строка в кавычках
TOKEN = re.compile(SKIP + '|' + LIT + r"|'(?:\\.|[^'\\\n])*'|\bDLOG_[EWID]\s*\(|[()]", re.S)
FIRST = re.compile(r'(?:\s|' + SKIP + r')*(' + LIT + ')', re.S)
CONV = re.compile(r'%(?:%|[-+ #0]*[0-9]*([diuxXc]))')    # что умеет декодер
ESC = {'n': '\n', 't': '\t', '\\': '\\', '"': '"', "'": "'"}


def count_args(fmt):
    """Сколько аргументов берёт формат; неподдержанное преобразование — ошибка."""
    n = i = 0
    while (i := fmt.find('%', i)) >= 0:
        m = CONV.match(fmt, i)
        if not m:
            raise ValueError("unsupported conversion in \"%s\"" % fmt)
        n += m.group(1) is not None
        i = m.end()
    if n > ARGS_MAX:
        raise ValueError("more than %d arguments in \"%s\"" % (ARGS_MAX, fmt))
    return n


def unquote(lit):
    """Литерал C → текст: тот, что увидит sizeof."""
    def one(m):
        if m.group(1) not in ESC:
            raise ValueError("unsupported escape \\%s" % m.group(1))
        return ESC[m.group(1)]
    return re.sub(r'\\(.)', one, lit[1:-1])


def scan(path):
    """Вызовы в одном файле: [(первая строка, последняя строка, формат)] и имя DLOG_FILE."""
    text = open(path, encoding="utf-8").read()
    name = re.search(r'^[ \t]*#[ \t]*define[ \t]+DLOG_FILE[ \t]+(\w+)', text, re.M)
    line = lambda pos: text.count("\n", 0, pos) + 1
    calls, it = [], TOKEN.finditer(text)
    for m in it:
        if not m.group().startswith("DLOG_"):
            continue
        where = "%s:%d" % (os.path.basename(path), line(m.start()))
        first = FIRST.match(text, m.end())
        if not first:
            raise ValueError("%s: format must be a string literal" % where)
        depth, end = 1, None
        for t in it:                                     # до парной закрывающей скобки
            depth += {"(": 1, ")": -1}.get(t.group(), 0)
            if depth == 0:
                end = t.start()
                break
        if end is None or not name:
            raise ValueError("%s: %s" % (where, "no DLOG_FILE in this file" if end else "unbalanced brackets"))
        calls.append((line(m.start()), line(end), unquote(first.group(1))))
    return name.group(1) if name else None, calls


def fingerprint(msgs):
    """Отпечаток словаря: CRC-32 по всем парам «номер, формат»."""
    return zlib.crc32("".join("%d\t%s\n" % (m["id"], m["fmt"]) for m in msgs).encode("utf-8"))


def dump(d):
    rows = ",\n".join("  " + json.dumps(m, ensure_ascii=False) for m in d["messages"])
    return '{\n "format": 1,\n "crc": "%s",\n "history": %s,\n "messages": [\n%s\n ]\n}\n' % (
        d["crc"], json.dumps(d["history"]), rows)


def main(dict_path, header_path, sources):
    if os.path.exists(dict_path):
        d = json.load(open(dict_path, encoding="utf-8"))
    else:
        d = {"crc": None, "history": [], "messages": [
            {"id": i, "fmt": f, "args": count_args(f), "used": True} for i, f in enumerate(SERVICE)]}
    msgs = d["messages"]
    by_fmt = {m["fmt"]: m for m in msgs}
    for m in msgs[len(SERVICE):]:
        m["used"] = False                                # отметим заново те, что встретятся
    lines, taken, new, ncalls = [], {}, 0, 0
    for path in sources:
        name, calls = scan(path)
        for first, last, fmt in calls:
            ncalls += 1
            if fmt not in by_fmt:                        # новый формат — следующий свободный номер
                by_fmt[fmt] = {"id": msgs[-1]["id"] + 1, "fmt": fmt, "args": count_args(fmt), "used": True}
                msgs.append(by_fmt[fmt])
                new += 1
            m = by_fmt[fmt]
            m["used"] = True
            if m["id"] > ID_MAX:
                raise ValueError("more than %d messages" % ID_MAX)
            for ln in sorted({first, last}):             # gcc берёт __LINE__ первой строки вызова, clang — последней
                if taken.setdefault((name, ln), fmt) != fmt:
                    raise ValueError("%s:%d: two DLOG calls on one line" % (os.path.basename(path), ln))
                lines.append("#define DLOG_H_%s_%d 0x%05Xu\n#define DLOG_L_%s_%d %d\n" % (
                    name, ln, m["id"] | m["args"] << 16, name, ln, len(fmt.encode("utf-8"))))
    crc = "0x%08x" % fingerprint(msgs)
    if d["crc"] not in (None, crc):
        d["history"].append(d["crc"])                    # прошивки со старым отпечатком словарь знает
    d["crc"] = crc
    head = "/* Создан dlog_gen.py — не править. H: номер | число аргументов << 16; L: длина формата. */\n"
    for path, body in ((dict_path, dump(d)), (header_path, head + "#define DLOG_DICT_CRC %su\n" % crc + "".join(lines))):
        if not os.path.exists(path) or open(path, encoding="utf-8").read() != body:
            open(path, "w", encoding="utf-8", newline="\n").write(body)
    used = sum(m["used"] for m in msgs) - len(SERVICE)
    print("dlog_gen: %d calls in %d files; messages: %d used, %d retired, %d new; next id %d; crc %s" % (
        ncalls, len(sources), used, len(msgs) - len(SERVICE) - used, new, msgs[-1]["id"] + 1, crc))

Четыре решения в нём стоит назвать.

Номер привязан к тексту, а не к месту. Строки файла можно двигать, вызов можно перенести в другой файл — номер останется. Новый текст получает следующий свободный номер. Исчезнувший текст остаётся в словаре с пометкой "used": false, и его номер больше никому не достаётся. Словарь только растёт — поэтому его хранят вместе с исходниками, а не создают заново.

Отпечаток словаря. crc — CRC‑32 по всем парам «номер, текст». Он же попадает в прошивку константой DLOG_DICT_CRC, и прибор при запуске сообщает его первой записью. Декодер сравнивает: словарь тот же, словарь новее прошивки (старый отпечаток лежит в history) или прошивка словарю незнакома.

Что умеет декодер, то и разрешено. Формат с %s, %f или %lld скрипт не пропустит: unsupported conversion in "name %s", код выхода 1.

Две строки на вызов. Если вызов занимает несколько строк, gcc подставляет в __LINE__ первую, а armclang — последнюю: вызов в строках 3–5 дал 3 у gcc и 5 у armclang. Скрипт пишет имена для обеих строк; в прогоне это вызов в строках 79–80 файла main35g.c.

Если словарь отстал от исходников. Скрипт запускают перед компилятором на каждой сборке. Если это забыть, сборку остановит сам компилятор. В опыте в начало app35g.c добавили одну строку, не обновив заголовок: 12 ошибок вида «DLOG_L_app35g_13 undeclared». Добавили три — вызовы попали на строки соседей, и 11 раз сработал _Static_assert с текстом dlog_ids.h is stale: run dlog_gen.py. Одну дыру эта защита оставляет — о ней в «Граблях».

Следующая версия прошивки в опыте: одно сообщение удалено, у другого изменён текст, одно добавлено, и все строки файла сдвинуты. Скрипт ответил:

dlog_gen: 16 calls in 2 files; messages: 16 used, 2 retired, 2 new; next id 20; crc 0x1e493416

Все 18 прежних номеров остались на местах, два текста помечены неиспользуемыми, новые получили номера 18 и 19, старый отпечаток 0x2c9c6546 ушёл в history.

35г.5 Кадр в линии: COBS, CRC-16 и восстановление после сбоя

Выдача — вторая половина журнала. Она забирает из кольца одну запись, собирает кадр и отдаёт его функции dlog_out, которую пишет прибор.

/* CRC-16/XMODEM: полином 0x1021, начальное 0 — как в 194.4. Здесь по полбайта, с таблицей на 16 слов;
 * с ключом -DDLOG_CRC_BITWISE — побитово, как в 194.4: результат тот же, выдача кадра вдвое дольше. */
static uint16_t crc16(const uint8_t *p, uint32_t n)
{
    uint16_t c = 0;
#ifndef DLOG_CRC_BITWISE
    static const uint16_t t[16] = { 0x0000, 0x1021, 0x2042, 0x3063, 0x4084, 0x50A5, 0x60C6, 0x70E7,
                                    0x8108, 0x9129, 0xA14A, 0xB16B, 0xC18C, 0xD1AD, 0xE1CE, 0xF1EF };
    while (n--) {
        c = (uint16_t)((c << 4) ^ t[(c >> 12) ^ (*p >> 4)]);
        c = (uint16_t)((c << 4) ^ t[(c >> 12) ^ (*p++ & 15u)]);
    }
#else
    while (n--) {
        c ^= (uint16_t)(*p++ << 8);
        for (int i = 0; i < 8; i++)
            c = (c & 0x8000u) ? (uint16_t)((c << 1) ^ 0x1021u) : (uint16_t)(c << 1);
    }
#endif
    return c;
}

/* COBS: убирает нули из данных, чтобы ноль означал только «конец кадра» */
static uint32_t cobs_encode(const uint8_t *in, uint32_t n, uint8_t *out)
{
    uint32_t w = 1, code_at = 0;
    uint8_t code = 1;
    for (uint32_t i = 0; i < n; i++) {
        if (in[i] == 0) {
            out[code_at] = code;
            code_at = w++;
            code = 1;
        } else {
            out[w++] = in[i];
            if (++code == 0xFF) {
                out[code_at] = code;
                code_at = w++;
                code = 1;
            }
        }
    }
    out[code_at] = code;
    return w;
}

/* Кадр: номер и уровень (2 байта), счётчик кадров, слова w[0..nw-1] младшим байтом вперёд,
 * CRC-16 старшим байтом вперёд; всё это через COBS и ноль в конце. */
static void frame_out(uint32_t idlvl, const uint32_t *w, uint32_t nw)
{
    uint8_t raw[FRAME_MAX], enc[FRAME_MAX + 2];
    uint32_t k = 0;
    raw[k++] = (uint8_t)idlvl;
    raw[k++] = (uint8_t)(idlvl >> 8);
    raw[k++] = L.seq++;
    for (uint32_t i = 0; i < nw; i++)
        for (uint32_t sh = 0; sh < 32; sh += 8)
            raw[k++] = (uint8_t)(w[i] >> sh);
    uint16_t c = crc16(raw, k);
    raw[k++] = (uint8_t)(c >> 8);
    raw[k++] = (uint8_t)c;
    k = cobs_encode(raw, k, enc);
    enc[k++] = 0;                        /* конец кадра */
    dlog_out(enc, k);
}

int dlog_drain(void)
{
    uint32_t rec[2 + DLOG_MAXARGS], n = 0, lost;
    uint32_t key = dlog_lock();
    if (L.tail != L.head) {
        n = DLOG_NARG(L.ring[L.tail & MASK]) + 2u;
        for (uint32_t i = 0; i < n; i++)
            rec[i] = L.ring[(L.tail + i) & MASK];
        L.tail += n;
        lost = DLOG_LOST(rec[0]);
    } else {                             /* пусто; отброшенные после последней записи — сообщить сейчас */
        lost = L.pending;
        L.pending = 0;
    }
    dlog_unlock(key);                    /* дальше — без запрета прерываний */
    if (lost) {                          /* метка потери: время записи, один аргумент — счёт */
        uint32_t m[2] = { n ? rec[1] : dlog_now(), lost };
        frame_out(DLOG_ID_LOST | (DLOG_WARN << 14), m, 2);
    }
    if (n)
        frame_out(rec[0] & 0xFFFFu, rec + 1, n - 1u);
    return n || lost;                    /* 0 — выдавать было нечего */
}

Кадр — тот же, что в 194.4: данные, CRC‑16/XMODEM старшим байтом вперёд, COBS, ноль. COBS убирает нули из данных, и ноль в линии означает только одно: конец кадра. cobs_encode — та же, что в 194, отличается только тип счётчиков. Прерывания закрыты только на время копирования записи из кольца — от 30 до 58 команд; CRC, COBS и вывод идут уже с открытыми.

CRC сначала была побитовой, как в 194.4. Счёт команд показал цену: с ней выдача почти вдвое длиннее. Её заменила таблица на 16 слов — два шага на байт вместо восьми. Результат тот же: поток из 5000 сообщений с обеими версиями совпал побайтно.

Таблица стоила 56 байт кода: 1616 против 1560. В счёт входит и вывод байтов в регистр UART по опросу; в QEMU передатчик всегда свободен, ожидание линии сюда не попало.

При запуске прибор первым делом шлёт одиночный ноль и запись о запуске:

void dlog_init(uint32_t level, uint32_t drop_old)
{
    static const uint8_t zero = 0;
    L.head = L.tail = DLOG_T0;
    L.pending = 0;
    L.seq = 0;
    L.level = (uint8_t)level;
    L.drop_old = (uint8_t)drop_old;
    dlog_out(&zero, 1);                  /* закрыть то, что осталось в линии до запуска */
    dlog_put(DLOG_ID_START | (1u << 16), DLOG_DICT_CRC);
}

Ноль закрывает мусор, который мог остаться в линии от прошлой жизни; пустой кадр декодер пропускает. Запись о запуске несёт отпечаток словаря.

Что будет, если линия портит байты. Поток из 5001 кадра (96 796 байт) испортили шестью способами и отдали декодеру:

Главный столбец — последний: ни одна испорченная запись не превратилась в правдоподобную строку. Кадр либо принят и верен, либо отброшен — по невозможному коду COBS, по длине, не равной 9 + 4·n, или по CRC. Со следующего нуля приём снова в порядке.

Сколько стоит одно повреждение, показали 1200 отдельных проб на потоке из 301 кадра. Вставленный байт всегда стоил одного кадра — 400 из 400. Удалённый байт — одного кадра в 382 пробах и двух в 18: если пропал сам разделитель, два кадра слипаются и не проходят оба. Перевёрнутый бит — одного в 380 пробах и двух в 20, по той же причине.

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

35г.6 Декодер, старые прошивки и сравнение с printf

Декодер делает обратный путь: режет поток по нулям, снимает COBS, сверяет длину и CRC, по номеру находит формат и печатает.

import json, re, struct, sys

LEVELS = "EWID"
ID_LOST, ID_START = 0, 1
CONV = re.compile(r'%(?:%|([-+ #0]*)([0-9]*)([diuxXc]))')


def crc16(data):
    """CRC-16/XMODEM: полином 0x1021, начальное 0 — как в прошивке."""
    c = 0
    for b in data:
        c ^= b << 8
        for _ in range(8):
            c = ((c << 1) ^ 0x1021 if c & 0x8000 else c << 1) & 0xFFFF
    return c


def cobs_decode(enc):
    """Обратное COBS; None — если код блока выводит за конец кадра."""
    out, r = bytearray(), 0
    while r < len(enc):
        code = enc[r]
        if r + code > len(enc):
            return None
        out += enc[r + 1:r + code]
        r += code
        if code != 0xFF and r < len(enc):
            out.append(0)
    return bytes(out)


def c_format(fmt, args):
    """printf для слов по 32 бита: d i u x X c, флаги - + пробел # 0, ширина."""
    it = iter(args)

    def one(m):
        if m.group(3) is None:
            return "%"
        flags, conv, v = m.group(1), m.group(3), next(it)
        if conv in "di":
            v -= (v & 0x80000000) << 1                   # слово как число со знаком
        if conv == "c":
            return ("%" + flags.replace("0", "") + m.group(2) + "c") % chr(v & 0xFF)
        if conv in "xX" and v == 0:
            flags = flags.replace("#", "")               # в C «%#x» от нуля — просто 0
        return ("%" + flags + m.group(2) + conv.replace("u", "d")) % v
    return CONV.sub(one, fmt)


class Decoder:
    def __init__(self, dictionary):
        self.msgs = {m["id"]: m for m in dictionary["messages"]}
        self.known = {dictionary["crc"]: "same"}
        self.known.update((c, "older firmware") for c in dictionary["history"])
        self.buf = bytearray()
        self.seq = None                                  # счётчик следующего кадра; None — ещё не знаем
        self.st = dict(frames=0, empty=0, bad_cobs=0, bad_len=0, bad_crc=0, gaps=0, missed=0,
                       unknown=0, mismatch=0, device_lost=0, starts=0)

    def feed(self, data):
        """Принять кусок потока; вернуть готовые строки."""
        lines = []
        for b in data:
            if b:
                self.buf.append(b)
                continue
            frame, self.buf = bytes(self.buf), bytearray()       # ноль — конец кадра
            if not frame:
                self.st["empty"] += 1                    # два нуля подряд: пустой кадр, не ошибка
                continue
            line = self.frame(frame, lines)
            if line:
                lines.append(line)
        return lines

    def frame(self, enc, lines):
        st = self.st
        raw = cobs_decode(enc)
        if raw is None:
            st["bad_cobs"] += 1
        elif len(raw) < 9 or len(raw) > 37 or (len(raw) - 9) % 4:
            st["bad_len"] += 1
        elif crc16(raw[:-2]) != raw[-2] << 8 | raw[-1]:
            st["bad_crc"] += 1
        else:
            st["frames"] += 1
            idlvl, seq = struct.unpack_from("<HB", raw)
            t, *args = struct.unpack_from("<%dI" % ((len(raw) - 5) // 4), raw, 3)
            mid, lvl = idlvl & 0x3FFF, LEVELS[idlvl >> 14]
            if mid == ID_START and len(args) == 1:       # прибор запустился: счётчик кадров с нуля
                st["starts"] += 1
                self.seq = 0
            if self.seq is not None and seq != self.seq:
                n = (seq - self.seq) & 0xFF              # сколько кадров не дошло (по модулю 256)
                st["gaps"] += 1
                st["missed"] += n
                lines.append("-- line: %d frame(s) missing" % n)
            self.seq = (seq + 1) & 0xFF
            m = self.msgs.get(mid)
            if m is None:                                # формата нет в словаре: аргументы — как есть
                st["unknown"] += 1
                return "%u %s ?id=%u" % (t, lvl, mid) + "".join(" %08x" % a for a in args)
            if m["args"] != len(args):                   # словарь не от этой прошивки
                st["mismatch"] += 1
                return "%u %s ?id=%u wants %u args:" % (t, lvl, mid, m["args"]) + "".join(" %08x" % a for a in args)
            text = c_format(m["fmt"], args)
            if mid == ID_LOST:
                st["device_lost"] += args[0]
            if mid == ID_START:
                text += " (%s)" % self.known.get("0x%08x" % args[0], "unknown to this dictionary")
            return "%u %s %s" % (t, lvl, text)
        return None

Форматирование — своё, без printf языка C под рукой, поэтому главный опыт раздела — сверка. Стенд на компьютере каждое событие пишет дважды: в двоичный журнал и обычным printf в файл. Событий 5000, двенадцать видов сообщений, аргументы — случайные числа со знаком разрядностью от 1 до 30 бит. Декодер выдал 5000 строк, и все 5000 совпали с printf дословно — с шириной поля, нулями слева, знаком +, выравниванием влево и %#x. На последнем декодер поначалу и споткнулся бы: Python печатает %#x от нуля как 0x0, а C — как 0; в потоке таких случаев 14.

Совместимость со старой прошивкой. Приборы в поле живут дольше, чем версия прошивки. Проверены все сочетания двух версий из 35г.4:

Новый словарь читает старый журнал без единой ошибки: удалённые тексты из него никуда не делись. Старый словарь с новой прошивкой разбирает всё, что знает, а незнакомое показывает честно — номер и сырые аргументы:

10929 I ?id=18 00000044 ff55fe85 ffffb303

Разбор при этом не ломается: число аргументов декодер знает из длины кадра, а не из словаря.

Сравнение с printf. Для сравнения тот же стенд собран второй раз: ключ -include tlog35g.h подменяет приёмник, и те же вызовы DLOG_x уходят в функцию, которая собирает строку через vsnprintf из newlib-nano и сразу выводит её.

static int head(char *p, unsigned room, const char *fmt, ...)    /* начало строки — тем же vsnprintf */
{
    va_list ap;
    va_start(ap, fmt);
    int n = vsnprintf(p, room, fmt, ap);
    va_end(ap);
    return n;
}

void tlog(unsigned lvl, const char *fmt, ...)
{
    char line[96];
    va_list ap;
    if (lvl > level)
        return;
    int n = head(line, sizeof(line) - 1u, "%u %c ", (unsigned)dlog_now(), "EWID"[lvl]);
    va_start(ap, fmt);
    n += vsnprintf(line + n, sizeof(line) - 1u - (unsigned)n, fmt, ap);
    va_end(ap);
    if (n > (int)sizeof(line) - 2)
        n = (int)sizeof(line) - 2;               /* строка не влезла — обрезана */
    line[n++] = '\n';
    dlog_out((const uint8_t *)line, (uint32_t)n);
}

Обе прошивки в QEMU выдали одни и те же 203 сообщения первых двух шагов: строки декодера совпали со строками текстовой прошивки все до одной.

Размер (Cortex‑M3, -Os, все уровни включены):

Образ меньше в 3,2 раза. Ядро журнала — 776 байт: dlog_put 272, frame_out вместе с CRC и COBS 260, dlog_drain 148, dlog_init 64, таблица CRC 32. В текстовом варианте одни только _printf_i (680 байт), _svfprintf_r (556) и _printf_common (294) занимают больше. Двенадцать строк формата — это 271 байт с завершающими нулями; у двоичного журнала их место занимают двенадцать номеров. Для Cortex‑M4 картина та же: 1604 против 5116 байт кода. Платит двоичный журнал оперативной памятью: кольцо в 256 слов — это 1024 байта, вся структура — 1040. У текстового варианта data и bss вместе — 128 байт, и ещё буфер строки в 96 байт на стеке; стек самого vsnprintf здесь не измерялся.

Байты в линии (5000 сообщений на компьютере):

Выигрыш — в 1,86 раза, и он зависит от сообщения. heartbeat — 11 байт вместо 19,8 в среднем, pid e %d i %d d %d out %d — 27 вместо 49,9. А вот adc ch %u raw %u с маленькими числами — 19 байт против 27,6: аргумент в четыре байта ничего не экономит на числе из одной цифры. На скорости 115 200 бод при 10 битах на байт средний кадр занимает линию 1,7 мс, средняя строка — 3,1 мс.

Команды (gdb, пошагово; у текстового варианта — от входа в tlog до возврата, вместе с выводом):

Всего двоичный журнал тратит в 2,6–2,9 раза меньше команд. Но важнее первый столбец. Там, где сообщение возникло — в прерывании, в регуляторе, — программа платит 60–93 команды вместо 1450–3322, в 24–36 раз меньше. Остальное доделывает фоновый цикл, когда ему удобно.

Это счёт команд, а не время: QEMU такты не считает, и на плате журнал не запускался. Ожидание передатчика UART в счёт не вошло ни у одного варианта.

35г.7 Грабли

Журнал расшифрован, а текст не тот. Словарь создали заново из новых исходников вместо того, чтобы продолжить старый. Номера раздались по порядку, и два из них достались другим текстам. Старый журнал с таким словарём: 4162 строки верны, 405 декодер отметил сам — словарь ждёт другое число аргументов, — а 433 вышли правдоподобными и неверными:

16811 I fan pwm 46339%   <- printf: 16811 I load 100% for 46339 ms

Словарь — такой же исходник, как код: он лежит в хранилище версий, и dlog_gen.py его только дополняет. О подмене предупреждает первая строка журнала: unknown to this dictionary.

Текст поправили, длина та же, скрипт не запустили. raw заменили на val в adc ch %u raw %u — компилятор промолчал: имя по номеру строки на месте, длина совпала. Декодер покажет старый текст. _Static_assert ловит сдвиг строк, но не такую правку. Поэтому dlog_gen.py — шаг сборки перед компилятором, а не команда, о которой помнят.

Два вызова в одной строке. Имя собирается из номера строки, и двум вызовам досталось бы одно. Скрипт останавливается: two DLOG calls on one line.

Вместе с уровнем исчезло действие. Аргументы выключенного уровня не вычисляются (35г.2): next_sample() в опыте вызвана 0 раз вместо 10. Счётчики, чтение регистров со сбросом флага, i++ в аргументы журнала не кладут.

Текстовое сообщение из прерывания рвёт строку задачи. В текстовом варианте стенда так испорчены 24 строки из 471. Двоичный журнал выводит только из фонового цикла, а в прерывании лишь кладёт слова в кольцо.

Потери не видны. Журнал без счётчика потерь врёт молча: по ленте кажется, что между двумя записями ничего не было. Здесь счёт идёт на двух уровнях. Потерянное в приборе показывает метка lost N, потерянное в линии — счётчик кадров.

Счётчик кадров — один байт. Пропуск считается по модулю 256: если подряд пропало ровно 256 кадров, декодер этого не заметит. И потерю последнего кадра перед тишиной он не видит — пока не придёт следующий.

Фоновый цикл стоит, пока идёт кадр. dlog_out в стенде ждёт передатчик по опросу. Кадр в 19 байт на 115 200 бод — это 1,65 мс. Если цикл так ждать не может, dlog_out должна только класть байты в очередь передатчика, а отправлять их — прерывание или DMA (раздел 16).

Аргумент шире 32 бит. В кольцо ложатся слова по 32 бита. long long и double туда не попадут: скрипт не примет %lld и %f, а компилятор не примет такой аргумент под %d — -Werror=format включён не зря.

35г.8 Итоги

• Запись в журнал — номер сообщения, время и сырые аргументы словами по 32 бита; строка формата остаётся на компьютере, в словаре. В линии сообщение занимает 11 + 4·n байт.
• Уровни отсекаются при сборке макросом DLOG_BUILD: выключенный вызов — sizeof от объявленной функции, в образе от него не остаётся ничего (2 байта вместо 244 на двенадцать вызовов), а формат компилятор всё равно проверяет. Второй порог — на ходу.
• dlog_put — от 60 до 93 команд, из них при закрытых прерываниях от 43 до 76; её можно звать из прерывания. Кодирование и вывод — в dlog_drain из фонового цикла: от 442 до 1186 команд на кадр.
• Кольцо — 256 слов; при переполнении теряются новые или старые записи по выбору, и число потерянных уходит в ленту меткой lost N: в опыте 3127 + 1874 и 3137 + 1864 дают те же 5001.
• Номера выдаёт dlog_gen.py: номер привязан к тексту, словарь только растёт, удалённые тексты остаются. Новый словарь читает журнал старой прошивки: 5000 строк из 5000.
• Кадр — COBS и CRC‑16, как в 194. После порчи линии ни одной неверной строки; одно повреждение стоит одного кадра, реже — двух.
• Против vsnprintf из newlib-nano на Cortex‑M3: образ 1620 байт вместо 5124, в линии 19,4 байта на сообщение вместо 36,0, в месте вызова 60–93 команды вместо 1450–3322. Цена — 1040 байт ОЗУ под кольцо и словарь на компьютере, без которого журнал не прочесть.

Полные исходники

dlog35g.h — интерфейс журнала: уровни, макросы DLOG_E/W/I/D, запись в кольцо.

/* Раздел 35г: журнал на приборе. В кольцо в ОЗУ ложатся номер сообщения, метка времени
 * и сырые аргументы; строки формата остаются на компьютере, в словаре dlog_dict.json.
 * Номера выдаёт dlog_gen.py: он обходит исходники и пишет dlog_ids.h. */
#ifndef DLOG35G_H
#define DLOG35G_H
#include <stdint.h>
#include "dlog_ids.h"

#define DLOG_ERR   0u                    /* уровни: чем больше число, тем подробнее */
#define DLOG_WARN  1u
#define DLOG_INFO  2u
#define DLOG_DBG   3u

#ifndef DLOG_BUILD
#define DLOG_BUILD 4                     /* сколько уровней попадает в образ: 0 — ни одного, 4 — все */
#endif
#ifndef DLOG_WORDS
#define DLOG_WORDS 256u                  /* кольцо, в словах по 4 байта; степень двойки */
#endif
#define DLOG_MAXARGS 7u

/* Заголовок записи в кольце — одно слово. Младшие 16 бит уходят в линию как есть. */
#define DLOG_ID(h)    ((h) & 0x3FFFu)            /* биты 13:0  — номер сообщения */
#define DLOG_LVL(h)   (((h) >> 14) & 3u)         /* биты 15:14 — уровень */
#define DLOG_NARG(h)  (((h) >> 16) & 7u)         /* биты 18:16 — число аргументов */
#define DLOG_LOST(h)  ((h) >> 19)                /* биты 31:19 — сколько записей потеряно перед этой */
#define DLOG_LOST_MAX 0x1FFFu                    /* 8191 значит «не меньше 8191» */
#define DLOG_ID_LOST  0u                         /* служебные номера: метка потери … */
#define DLOG_ID_START 1u                         /* … и метка запуска с отпечатком словаря */

void dlog_init(uint32_t level, uint32_t drop_old);   /* drop_old: 0 — терять новые, 1 — старые */
void dlog_set_level(uint32_t level);                 /* порог на ходу: DLOG_ERR … DLOG_DBG */
void dlog_put(uint32_t hdr, ...);                    /* из задачи и из прерывания */
int dlog_drain(void);                                /* из фонового цикла: одна запись → один кадр */

uint32_t dlog_now(void);                             /* даёт прибор: метка времени */
void dlog_out(const uint8_t *p, uint32_t n);         /* даёт прибор: байты в линию */

/* Только объявление: компилятор сверяет формат с аргументами, кода и строки в образе нет. */
int dlog_fmt_check(const char *fmt, ...) __attribute__((format(printf, 1, 2)));

#define DLOG_CAT_(a, b, c) a##b##_##c
#define DLOG_CAT(a, b, c) DLOG_CAT_(a, b, c)
#define DLOG_HERE(prefix) DLOG_CAT(prefix, DLOG_FILE, __LINE__)   /* DLOG_H_app35g_27 */

#ifndef DLOG_SINK                        /* стенд подменяет приёмник, чтобы сравнить с printf */
#define DLOG_SINK(lvl, fmt, ...) dlog_put(DLOG_HERE(DLOG_H_) | ((lvl) << 14), ##__VA_ARGS__)
#endif

#define DLOG_OFF(fmt, ...) ((void)sizeof(dlog_fmt_check(fmt, ##__VA_ARGS__)))
#define DLOG_ON(lvl, fmt, ...)                                                                  \
    do {                                                                                        \
        _Static_assert(sizeof(fmt) - 1 == DLOG_HERE(DLOG_L_), "dlog_ids.h is stale: run dlog_gen.py"); \
        DLOG_OFF(fmt, ##__VA_ARGS__);                                                           \
        DLOG_SINK(lvl, fmt, ##__VA_ARGS__);                                                     \
    } while (0)

#if DLOG_BUILD > 0
#define DLOG_E(fmt, ...) DLOG_ON(DLOG_ERR, fmt, ##__VA_ARGS__)
#else
#define DLOG_E(fmt, ...) DLOG_OFF(fmt, ##__VA_ARGS__)
#endif
#if DLOG_BUILD > 1
#define DLOG_W(fmt, ...) DLOG_ON(DLOG_WARN, fmt, ##__VA_ARGS__)
#else
#define DLOG_W(fmt, ...) DLOG_OFF(fmt, ##__VA_ARGS__)
#endif
#if DLOG_BUILD > 2
#define DLOG_I(fmt, ...) DLOG_ON(DLOG_INFO, fmt, ##__VA_ARGS__)
#else
#define DLOG_I(fmt, ...) DLOG_OFF(fmt, ##__VA_ARGS__)
#endif
#if DLOG_BUILD > 3
#define DLOG_D(fmt, ...) DLOG_ON(DLOG_DBG, fmt, ##__VA_ARGS__)
#else
#define DLOG_D(fmt, ...) DLOG_OFF(fmt, ##__VA_ARGS__)
#endif

#endif

dlog35g.c — кольцо записей в ОЗУ и выдача кадрами COBS + CRC-16.

/* Раздел 35г: журнал на приборе — кольцо записей в ОЗУ и выдача кадрами COBS + CRC-16.
 * Запись (dlog_put) коротка и годится для прерывания; кодирование и линия — в dlog_drain,
 * которую зовёт фоновый цикл. Кадр тот же, что в разделе 194: данные + CRC → COBS → 0x00. */
#include <stdarg.h>
#include "dlog35g.h"

#define MASK (DLOG_WORDS - 1u)
#define FRAME_MAX (9u + 4u * DLOG_MAXARGS)       /* номер 2, счётчик 1, время 4, аргументы, CRC 2 */
#ifndef DLOG_T0
#define DLOG_T0 0u                               /* откуда стартуют счётчики слов; иное — только для опыта */
#endif

_Static_assert((DLOG_WORDS & MASK) == 0 && DLOG_WORDS >= 32, "DLOG_WORDS: power of two, at least 32");

static struct {
    uint32_t ring[DLOG_WORDS];
    uint32_t head;                       /* слов записано за всё время; двигает только dlog_put */
    uint32_t tail;                       /* слов прочитано или выброшено */
    uint32_t pending;                    /* записей отброшено после последней принятой */
    uint8_t level;                       /* порог на ходу */
    uint8_t drop_old;                    /* 0 — терять новые, 1 — терять старые */
    uint8_t seq;                         /* счётчик кадров в линии */
} L;

#if defined(__arm__)
static inline uint32_t dlog_lock(void)
{
    uint32_t key;
    __asm volatile("mrs %0, primask\n"
                   "cpsid i" : "=r"(key) :: "memory");
    return key;
}

static inline void dlog_unlock(uint32_t key)
{
    __asm volatile("msr primask, %0" :: "r"(key) : "memory");
}
#else                                    /* на компьютере писатель один */
static inline uint32_t dlog_lock(void)
{
    return 0;
}

static inline void dlog_unlock(uint32_t key)
{
    (void)key;
}
#endif

static uint32_t add_lost(uint32_t hdr, uint32_t n)
{
    uint32_t v = DLOG_LOST(hdr) + n;
    if (v > DLOG_LOST_MAX)
        v = DLOG_LOST_MAX;
    return (hdr & 0x7FFFFu) | (v << 19);
}

void dlog_put(uint32_t hdr, ...)
{
    uint32_t n = DLOG_NARG(hdr), lost = 0;
    va_list ap;
    if (DLOG_LVL(hdr) > L.level)
        return;                          /* уровень выключен на ходу */
    va_start(ap, hdr);
    uint32_t key = dlog_lock();
    while (DLOG_WORDS - (L.head - L.tail) < n + 2u) {
        if (!L.drop_old) {               /* терять новые: запись не берём, только считаем */
            L.pending++;
            goto out;
        }
        uint32_t old = L.ring[L.tail & MASK];    /* терять старые: выбросить самую старую */
        L.tail += DLOG_NARG(old) + 2u;
        lost += DLOG_LOST(old) + 1u;
    }
    if (lost)                            /* новая самая старая несёт счёт: «передо мной потеряно» */
        L.ring[L.tail & MASK] = add_lost(L.ring[L.tail & MASK], lost);
    uint32_t w = L.head;
    L.ring[w++ & MASK] = add_lost(hdr, L.pending);
    L.pending = 0;
    L.ring[w++ & MASK] = dlog_now();
    while (n--)
        L.ring[w++ & MASK] = va_arg(ap, uint32_t);
    L.head = w;                          /* запись видна читателю только целиком */
out:
    dlog_unlock(key);
    va_end(ap);
}

/* CRC-16/XMODEM: полином 0x1021, начальное 0 — как в 194.4. Здесь по полбайта, с таблицей на 16 слов;
 * с ключом -DDLOG_CRC_BITWISE — побитово, как в 194.4: результат тот же, выдача кадра вдвое дольше. */
static uint16_t crc16(const uint8_t *p, uint32_t n)
{
    uint16_t c = 0;
#ifndef DLOG_CRC_BITWISE
    static const uint16_t t[16] = { 0x0000, 0x1021, 0x2042, 0x3063, 0x4084, 0x50A5, 0x60C6, 0x70E7,
                                    0x8108, 0x9129, 0xA14A, 0xB16B, 0xC18C, 0xD1AD, 0xE1CE, 0xF1EF };
    while (n--) {
        c = (uint16_t)((c << 4) ^ t[(c >> 12) ^ (*p >> 4)]);
        c = (uint16_t)((c << 4) ^ t[(c >> 12) ^ (*p++ & 15u)]);
    }
#else
    while (n--) {
        c ^= (uint16_t)(*p++ << 8);
        for (int i = 0; i < 8; i++)
            c = (c & 0x8000u) ? (uint16_t)((c << 1) ^ 0x1021u) : (uint16_t)(c << 1);
    }
#endif
    return c;
}

/* COBS: убирает нули из данных, чтобы ноль означал только «конец кадра» */
static uint32_t cobs_encode(const uint8_t *in, uint32_t n, uint8_t *out)
{
    uint32_t w = 1, code_at = 0;
    uint8_t code = 1;
    for (uint32_t i = 0; i < n; i++) {
        if (in[i] == 0) {
            out[code_at] = code;
            code_at = w++;
            code = 1;
        } else {
            out[w++] = in[i];
            if (++code == 0xFF) {
                out[code_at] = code;
                code_at = w++;
                code = 1;
            }
        }
    }
    out[code_at] = code;
    return w;
}

/* Кадр: номер и уровень (2 байта), счётчик кадров, слова w[0..nw-1] младшим байтом вперёд,
 * CRC-16 старшим байтом вперёд; всё это через COBS и ноль в конце. */
static void frame_out(uint32_t idlvl, const uint32_t *w, uint32_t nw)
{
    uint8_t raw[FRAME_MAX], enc[FRAME_MAX + 2];
    uint32_t k = 0;
    raw[k++] = (uint8_t)idlvl;
    raw[k++] = (uint8_t)(idlvl >> 8);
    raw[k++] = L.seq++;
    for (uint32_t i = 0; i < nw; i++)
        for (uint32_t sh = 0; sh < 32; sh += 8)
            raw[k++] = (uint8_t)(w[i] >> sh);
    uint16_t c = crc16(raw, k);
    raw[k++] = (uint8_t)(c >> 8);
    raw[k++] = (uint8_t)c;
    k = cobs_encode(raw, k, enc);
    enc[k++] = 0;                        /* конец кадра */
    dlog_out(enc, k);
}

int dlog_drain(void)
{
    uint32_t rec[2 + DLOG_MAXARGS], n = 0, lost;
    uint32_t key = dlog_lock();
    if (L.tail != L.head) {
        n = DLOG_NARG(L.ring[L.tail & MASK]) + 2u;
        for (uint32_t i = 0; i < n; i++)
            rec[i] = L.ring[(L.tail + i) & MASK];
        L.tail += n;
        lost = DLOG_LOST(rec[0]);
    } else {                             /* пусто; отброшенные после последней записи — сообщить сейчас */
        lost = L.pending;
        L.pending = 0;
    }
    dlog_unlock(key);                    /* дальше — без запрета прерываний */
    if (lost) {                          /* метка потери: время записи, один аргумент — счёт */
        uint32_t m[2] = { n ? rec[1] : dlog_now(), lost };
        frame_out(DLOG_ID_LOST | (DLOG_WARN << 14), m, 2);
    }
    if (n)
        frame_out(rec[0] & 0xFFFFu, rec + 1, n - 1u);
    return n || lost;                    /* 0 — выдавать было нечего */
}

void dlog_set_level(uint32_t level)
{
    L.level = (uint8_t)level;
}

void dlog_init(uint32_t level, uint32_t drop_old)
{
    static const uint8_t zero = 0;
    L.head = L.tail = DLOG_T0;
    L.pending = 0;
    L.seq = 0;
    L.level = (uint8_t)level;
    L.drop_old = (uint8_t)drop_old;
    dlog_out(&zero, 1);                  /* закрыть то, что осталось в линии до запуска */
    dlog_put(DLOG_ID_START | (1u << 16), DLOG_DICT_CRC);
}

main35g.c — прошивка-стенд для QEMU в двух вариантах: двоичный и текстовый журнал.

/* Раздел 35г: прошивка-стенд для QEMU. Один и тот же файл собирается в двух вариантах:
 * с dlog35g.c — двоичный журнал, с tlog35g.c и ключом -include tlog35g.h — текстовый.
 * Шаг 1: три сообщения для счёта команд. Шаг 2: 200 случайных событий, время — счётчик.
 * Шаг 3: задача и прерывание SysTick пишут в журнал вперемешку. */
#define DLOG_FILE main35g
#include "dlog35g.h"
#include "app35g.h"
#include "regs35g.h"
#include "rnd35g.h"

#define TASK_STEPS 300u

static volatile uint32_t now_ms, ticks;

uint32_t dlog_now(void)
{
    return now_ms;
}

void dlog_out(const uint8_t *p, uint32_t n)      /* байты в USART1, по опросу */
{
    while (n--) {
        while (!(USART1_SR & USART_SR_TXE)) {
        }
        USART1_DR = *p++;
    }
}

void SysTick_Handler(void)
{
    now_ms++;
    ticks++;
    DLOG_W("tick %u from interrupt", (unsigned)ticks);
}

static void drain_all(void)
{
    while (dlog_drain()) {
    }
}

static void qemu_exit(void)                      /* semihosting SYS_EXIT: закрыть QEMU (раздел 35а) */
{
    register uint32_t r0 __asm("r0") = 0x18u;
    register uint32_t r1 __asm("r1") = 0x20026u;
    __asm volatile("bkpt 0xAB" : : "r"(r0), "r"(r1) : "memory");
}

int main(void)
{
    RCC_APB2ENR |= USART1_EN;
    USART1_BRR = BRR_115200;
    USART1_CR1 = (1u << 13) | (1u << 3);         /* UE, TE */
    dlog_init(DLOG_DBG, 0);

    now_ms = 250u;
    app_event(0, 0, 0, 0);                       /* ЗАМЕР: без аргументов */
    app_event(1, 5, 1234, 0);                    /* ЗАМЕР: два аргумента */
    app_event(9, -12, 3400, -7);                 /* ЗАМЕР: четыре аргумента */
    drain_all();

    for (unsigned i = 0; i < 200u; i++) {
        now_ms += 1u + rnd() % 2000u;
        unsigned kind = rnd() % APP_KINDS;
        int a = rnd_val(), b = rnd_val(), c = rnd_val();
        app_event(kind, a, b, c);
        drain_all();
    }

    DLOG_I("task and interrupt write together");
    SYST_RVR = TICK_RELOAD - 1u;
    SYST_CVR = 0;
    SYST_CSR = 7u;                               /* такт ядра, прерывание, включён */
    for (unsigned i = 0; i < TASK_STEPS; i++) {
        DLOG_I("task step %u", i);
        dlog_drain();                            /* фоновый цикл: по одной записи за проход */
    }
    SYST_CSR = 0;
    DLOG_I("done: task %u, interrupt %u",
           TASK_STEPS, (unsigned)ticks);
    drain_all();
    qemu_exit();
    for (;;) {
    }
}

tlog35g.c — вариант для сравнения: тот же прибор пишет журнал текстом через snprintf.

/* Раздел 35г: вариант для сравнения — тот же прибор пишет журнал текстом. Строка собирается
 * snprintf из newlib-nano и сразу уходит в линию; кольца и отложенной выдачи нет. */
#include <stdarg.h>
#include <stdio.h>
#include "dlog35g.h"
#include "tlog35g.h"

static uint8_t level;

static int head(char *p, unsigned room, const char *fmt, ...)    /* начало строки — тем же vsnprintf */
{
    va_list ap;
    va_start(ap, fmt);
    int n = vsnprintf(p, room, fmt, ap);
    va_end(ap);
    return n;
}

void tlog(unsigned lvl, const char *fmt, ...)
{
    char line[96];
    va_list ap;
    if (lvl > level)
        return;
    int n = head(line, sizeof(line) - 1u, "%u %c ", (unsigned)dlog_now(), "EWID"[lvl]);
    va_start(ap, fmt);
    n += vsnprintf(line + n, sizeof(line) - 1u - (unsigned)n, fmt, ap);
    va_end(ap);
    if (n > (int)sizeof(line) - 2)
        n = (int)sizeof(line) - 2;               /* строка не влезла — обрезана */
    line[n++] = '\n';
    dlog_out((const uint8_t *)line, (uint32_t)n);
}

void dlog_init(uint32_t lvl, uint32_t drop_old)
{
    (void)drop_old;
    level = (uint8_t)lvl;
}

int dlog_drain(void)
{
    return 0;                                    /* выдавать нечего: всё уже ушло */
}

void *_sbrk(int incr)                            /* куча не нужна: snprintf пишет в свой буфер */
{
    (void)incr;
    return (void *)-1;
}

app35g.c — «прибор» для опытов: двенадцать сообщений разных уровней и форматов.

/* Раздел 35г: «прибор» для опытов. Двенадцать сообщений: четыре уровня, от нуля до четырёх
 * аргументов, знаковые и беззнаковые, ширина, нули слева, символ и знак процента.
 * Один и тот же файл собирается для компьютера и для Cortex-M. */
#define DLOG_FILE app35g
#include "dlog35g.h"
#include "app35g.h"

void app_event(unsigned kind, int a, int b, int c)
{
    switch (kind % APP_KINDS) {
    case 0:
        DLOG_I("state idle -> run");
        break;
    case 1:
        DLOG_D("adc ch %u raw %u", (unsigned)a & 15u, (unsigned)b & 4095u);
        break;
    case 2:
        DLOG_W("temp %d.%u C over limit %d", a / 10, (unsigned)(a < 0 ? -a : a) % 10u, b);
        break;
    case 3:
        DLOG_E("i2c nack addr 0x%02x reg 0x%02x try %u", (unsigned)a & 0x7Fu, (unsigned)b & 0xFFu, (unsigned)c & 7u);
        break;
    case 4:
        DLOG_I("motor %c speed %6d rpm", 'A' + (a & 3), b);
        break;
    case 5:
        DLOG_D("crc %08x len %u", (unsigned)a, (unsigned)b);
        break;
    case 6:
        DLOG_I("load 100%% for %u ms", (unsigned)c % 60000u);
        break;
    case 7:
        DLOG_E("assert line %d: %d != %d", a & 0xFFF, b, c);
        break;
    case 8:
        DLOG_W("queue %-5u of %5u, delta %+d", (unsigned)a & 1023u, (unsigned)b & 1023u, c);
        break;
    case 9:
        DLOG_D("pid e %d i %d d %d out %d", a, b, c, a + b);
        break;
    case 10:
        DLOG_I("mask %#x flags %04X", (unsigned)a & 0xFFu, (unsigned)b & 0xFFFFu);
        break;
    default:
        DLOG_D("heartbeat");
        break;
    }
}

app35g_v2.c — следующая версия того же «прибора» — для опыта со словарём.

/* Раздел 35г: тот же «прибор», следующая версия прошивки — для опыта со словарём.
 * Изменено: сообщение «load 100%…» удалено, у «motor…» другой текст и третий аргумент,
 * добавлено «fan pwm…»; из-за этого комментария все строки ещё и сдвинулись.
 * Номера остальных сообщений должны остаться прежними. */
#define DLOG_FILE app35g
#include "dlog35g.h"
#include "app35g.h"

void app_event(unsigned kind, int a, int b, int c)
{
    switch (kind % APP_KINDS) {
    case 0:
        DLOG_I("state idle -> run");
        break;
    case 1:
        DLOG_D("adc ch %u raw %u", (unsigned)a & 15u, (unsigned)b & 4095u);
        break;
    case 2:
        DLOG_W("temp %d.%u C over limit %d", a / 10, (unsigned)(a < 0 ? -a : a) % 10u, b);
        break;
    case 3:
        DLOG_E("i2c nack addr 0x%02x reg 0x%02x try %u", (unsigned)a & 0x7Fu, (unsigned)b & 0xFFu, (unsigned)c & 7u);
        break;
    case 4:
        DLOG_I("motor %c speed %d rpm, torque %d", 'A' + (a & 3), b, c);
        break;
    case 5:
        DLOG_D("crc %08x len %u", (unsigned)a, (unsigned)b);
        break;
    case 6:
        DLOG_I("fan pwm %u%%", (unsigned)c % 101u);
        break;
    case 7:
        DLOG_E("assert line %d: %d != %d", a & 0xFFF, b, c);
        break;
    case 8:
        DLOG_W("queue %-5u of %5u, delta %+d", (unsigned)a & 1023u, (unsigned)b & 1023u, c);
        break;
    case 9:
        DLOG_D("pid e %d i %d d %d out %d", a, b, c, a + b);
        break;
    case 10:
        DLOG_I("mask %#x flags %04X", (unsigned)a & 0xFFu, (unsigned)b & 0xFFFFu);
        break;
    default:
        DLOG_D("heartbeat");
        break;
    }
}

cut35g.c — выключенный уровень не оставляет в программе ничего, даже вычисления аргументов.

/* Раздел 35г: выключенный уровень не оставляет в программе ничего — даже вычисления аргументов.
 * Собирается дважды: с -DDLOG_BUILD=4 и с -DDLOG_BUILD=3. */
#include <stdio.h>
#define DLOG_FILE cut35g
#include "dlog35g.h"

static unsigned calls;

static unsigned next_sample(void)
{
    return ++calls;
}

void dlog_put(uint32_t hdr, ...)
{
    (void)hdr;
}

int main(void)
{
    for (int i = 0; i < 10; i++)
        DLOG_D("sample %u", next_sample());
    printf("DLOG_BUILD=%d next_sample called %u times\n", DLOG_BUILD, calls);
    return 0;
}

dlog_gen.py — словарь журнала: находит вызовы DLOG_* в исходниках и выдаёт номера сообщений.

#!/usr/bin/env python3
# -*- coding: utf-8 -*-
"""Раздел 35г: словарь журнала. Обходит исходники, находит вызовы DLOG_E/W/I/D("формат", ...),
выдаёт каждой строке формата постоянный номер и пишет два файла: словарь для компьютера (JSON)
и dlog_ids.h для компилятора.

    python3 dlog_gen.py dlog_dict.json dlog_ids.h app35g.c main35g.c

Номер привязан к тексту формата, а не к месту в файле: строки можно двигать. Исчезнувший формат
остаётся в словаре с пометкой "used": false, его номер заново не выдаётся."""
import json, os, re, sys, zlib

SERVICE = ["lost %u", "start, dictionary %08x"]          # номера 0 и 1 — служебные
ID_MAX, ARGS_MAX = 0x3FFF, 7
SKIP = r'//[^\n]*|/\*.*?\*/'                             # комментарии
LIT = r'"(?:\\.|[^"\\\n])*"'                             # строка в кавычках
TOKEN = re.compile(SKIP + '|' + LIT + r"|'(?:\\.|[^'\\\n])*'|\bDLOG_[EWID]\s*\(|[()]", re.S)
FIRST = re.compile(r'(?:\s|' + SKIP + r')*(' + LIT + ')', re.S)
CONV = re.compile(r'%(?:%|[-+ #0]*[0-9]*([diuxXc]))')    # что умеет декодер
ESC = {'n': '\n', 't': '\t', '\\': '\\', '"': '"', "'": "'"}


def count_args(fmt):
    """Сколько аргументов берёт формат; неподдержанное преобразование — ошибка."""
    n = i = 0
    while (i := fmt.find('%', i)) >= 0:
        m = CONV.match(fmt, i)
        if not m:
            raise ValueError("unsupported conversion in \"%s\"" % fmt)
        n += m.group(1) is not None
        i = m.end()
    if n > ARGS_MAX:
        raise ValueError("more than %d arguments in \"%s\"" % (ARGS_MAX, fmt))
    return n


def unquote(lit):
    """Литерал C → текст: тот, что увидит sizeof."""
    def one(m):
        if m.group(1) not in ESC:
            raise ValueError("unsupported escape \\%s" % m.group(1))
        return ESC[m.group(1)]
    return re.sub(r'\\(.)', one, lit[1:-1])


def scan(path):
    """Вызовы в одном файле: [(первая строка, последняя строка, формат)] и имя DLOG_FILE."""
    text = open(path, encoding="utf-8").read()
    name = re.search(r'^[ \t]*#[ \t]*define[ \t]+DLOG_FILE[ \t]+(\w+)', text, re.M)
    line = lambda pos: text.count("\n", 0, pos) + 1
    calls, it = [], TOKEN.finditer(text)
    for m in it:
        if not m.group().startswith("DLOG_"):
            continue
        where = "%s:%d" % (os.path.basename(path), line(m.start()))
        first = FIRST.match(text, m.end())
        if not first:
            raise ValueError("%s: format must be a string literal" % where)
        depth, end = 1, None
        for t in it:                                     # до парной закрывающей скобки
            depth += {"(": 1, ")": -1}.get(t.group(), 0)
            if depth == 0:
                end = t.start()
                break
        if end is None or not name:
            raise ValueError("%s: %s" % (where, "no DLOG_FILE in this file" if end else "unbalanced brackets"))
        calls.append((line(m.start()), line(end), unquote(first.group(1))))
    return name.group(1) if name else None, calls


def fingerprint(msgs):
    """Отпечаток словаря: CRC-32 по всем парам «номер, формат»."""
    return zlib.crc32("".join("%d\t%s\n" % (m["id"], m["fmt"]) for m in msgs).encode("utf-8"))


def dump(d):
    rows = ",\n".join("  " + json.dumps(m, ensure_ascii=False) for m in d["messages"])
    return '{\n "format": 1,\n "crc": "%s",\n "history": %s,\n "messages": [\n%s\n ]\n}\n' % (
        d["crc"], json.dumps(d["history"]), rows)


def main(dict_path, header_path, sources):
    if os.path.exists(dict_path):
        d = json.load(open(dict_path, encoding="utf-8"))
    else:
        d = {"crc": None, "history": [], "messages": [
            {"id": i, "fmt": f, "args": count_args(f), "used": True} for i, f in enumerate(SERVICE)]}
    msgs = d["messages"]
    by_fmt = {m["fmt"]: m for m in msgs}
    for m in msgs[len(SERVICE):]:
        m["used"] = False                                # отметим заново те, что встретятся
    lines, taken, new, ncalls = [], {}, 0, 0
    for path in sources:
        name, calls = scan(path)
        for first, last, fmt in calls:
            ncalls += 1
            if fmt not in by_fmt:                        # новый формат — следующий свободный номер
                by_fmt[fmt] = {"id": msgs[-1]["id"] + 1, "fmt": fmt, "args": count_args(fmt), "used": True}
                msgs.append(by_fmt[fmt])
                new += 1
            m = by_fmt[fmt]
            m["used"] = True
            if m["id"] > ID_MAX:
                raise ValueError("more than %d messages" % ID_MAX)
            for ln in sorted({first, last}):             # gcc берёт __LINE__ первой строки вызова, clang — последней
                if taken.setdefault((name, ln), fmt) != fmt:
                    raise ValueError("%s:%d: two DLOG calls on one line" % (os.path.basename(path), ln))
                lines.append("#define DLOG_H_%s_%d 0x%05Xu\n#define DLOG_L_%s_%d %d\n" % (
                    name, ln, m["id"] | m["args"] << 16, name, ln, len(fmt.encode("utf-8"))))
    crc = "0x%08x" % fingerprint(msgs)
    if d["crc"] not in (None, crc):
        d["history"].append(d["crc"])                    # прошивки со старым отпечатком словарь знает
    d["crc"] = crc
    head = "/* Создан dlog_gen.py — не править. H: номер | число аргументов << 16; L: длина формата. */\n"
    for path, body in ((dict_path, dump(d)), (header_path, head + "#define DLOG_DICT_CRC %su\n" % crc + "".join(lines))):
        if not os.path.exists(path) or open(path, encoding="utf-8").read() != body:
            open(path, "w", encoding="utf-8", newline="\n").write(body)
    used = sum(m["used"] for m in msgs) - len(SERVICE)
    print("dlog_gen: %d calls in %d files; messages: %d used, %d retired, %d new; next id %d; crc %s" % (
        ncalls, len(sources), used, len(msgs) - len(SERVICE) - used, new, msgs[-1]["id"] + 1, crc))


if __name__ == "__main__":
    if len(sys.argv) < 4:
        sys.exit(__doc__)
    try:
        main(sys.argv[1], sys.argv[2], sys.argv[3:])
    except ValueError as e:
        sys.exit("dlog_gen: error: %s" % e)

dlog_decode.py — декодер: поток байтов из линии → строки текста по словарю.

#!/usr/bin/env python3
# -*- coding: utf-8 -*-
"""Раздел 35г: декодер журнала. Поток байтов из линии → строки текста по словарю dlog_gen.py.

    python3 dlog_decode.py dlog_dict.json uart.bin

Кадр: COBS(номер и уровень 2 байта, счётчик кадров 1, время 4, аргументы по 4, CRC-16 2) + 0x00."""
import json, re, struct, sys

LEVELS = "EWID"
ID_LOST, ID_START = 0, 1
CONV = re.compile(r'%(?:%|([-+ #0]*)([0-9]*)([diuxXc]))')


def crc16(data):
    """CRC-16/XMODEM: полином 0x1021, начальное 0 — как в прошивке."""
    c = 0
    for b in data:
        c ^= b << 8
        for _ in range(8):
            c = ((c << 1) ^ 0x1021 if c & 0x8000 else c << 1) & 0xFFFF
    return c


def cobs_decode(enc):
    """Обратное COBS; None — если код блока выводит за конец кадра."""
    out, r = bytearray(), 0
    while r < len(enc):
        code = enc[r]
        if r + code > len(enc):
            return None
        out += enc[r + 1:r + code]
        r += code
        if code != 0xFF and r < len(enc):
            out.append(0)
    return bytes(out)


def c_format(fmt, args):
    """printf для слов по 32 бита: d i u x X c, флаги - + пробел # 0, ширина."""
    it = iter(args)

    def one(m):
        if m.group(3) is None:
            return "%"
        flags, conv, v = m.group(1), m.group(3), next(it)
        if conv in "di":
            v -= (v & 0x80000000) << 1                   # слово как число со знаком
        if conv == "c":
            return ("%" + flags.replace("0", "") + m.group(2) + "c") % chr(v & 0xFF)
        if conv in "xX" and v == 0:
            flags = flags.replace("#", "")               # в C «%#x» от нуля — просто 0
        return ("%" + flags + m.group(2) + conv.replace("u", "d")) % v
    return CONV.sub(one, fmt)


class Decoder:
    def __init__(self, dictionary):
        self.msgs = {m["id"]: m for m in dictionary["messages"]}
        self.known = {dictionary["crc"]: "same"}
        self.known.update((c, "older firmware") for c in dictionary["history"])
        self.buf = bytearray()
        self.seq = None                                  # счётчик следующего кадра; None — ещё не знаем
        self.st = dict(frames=0, empty=0, bad_cobs=0, bad_len=0, bad_crc=0, gaps=0, missed=0,
                       unknown=0, mismatch=0, device_lost=0, starts=0)

    def feed(self, data):
        """Принять кусок потока; вернуть готовые строки."""
        lines = []
        for b in data:
            if b:
                self.buf.append(b)
                continue
            frame, self.buf = bytes(self.buf), bytearray()       # ноль — конец кадра
            if not frame:
                self.st["empty"] += 1                    # два нуля подряд: пустой кадр, не ошибка
                continue
            line = self.frame(frame, lines)
            if line:
                lines.append(line)
        return lines

    def frame(self, enc, lines):
        st = self.st
        raw = cobs_decode(enc)
        if raw is None:
            st["bad_cobs"] += 1
        elif len(raw) < 9 or len(raw) > 37 or (len(raw) - 9) % 4:
            st["bad_len"] += 1
        elif crc16(raw[:-2]) != raw[-2] << 8 | raw[-1]:
            st["bad_crc"] += 1
        else:
            st["frames"] += 1
            idlvl, seq = struct.unpack_from("<HB", raw)
            t, *args = struct.unpack_from("<%dI" % ((len(raw) - 5) // 4), raw, 3)
            mid, lvl = idlvl & 0x3FFF, LEVELS[idlvl >> 14]
            if mid == ID_START and len(args) == 1:       # прибор запустился: счётчик кадров с нуля
                st["starts"] += 1
                self.seq = 0
            if self.seq is not None and seq != self.seq:
                n = (seq - self.seq) & 0xFF              # сколько кадров не дошло (по модулю 256)
                st["gaps"] += 1
                st["missed"] += n
                lines.append("-- line: %d frame(s) missing" % n)
            self.seq = (seq + 1) & 0xFF
            m = self.msgs.get(mid)
            if m is None:                                # формата нет в словаре: аргументы — как есть
                st["unknown"] += 1
                return "%u %s ?id=%u" % (t, lvl, mid) + "".join(" %08x" % a for a in args)
            if m["args"] != len(args):                   # словарь не от этой прошивки
                st["mismatch"] += 1
                return "%u %s ?id=%u wants %u args:" % (t, lvl, mid, m["args"]) + "".join(" %08x" % a for a in args)
            text = c_format(m["fmt"], args)
            if mid == ID_LOST:
                st["device_lost"] += args[0]
            if mid == ID_START:
                text += " (%s)" % self.known.get("0x%08x" % args[0], "unknown to this dictionary")
            return "%u %s %s" % (t, lvl, text)
        return None


def decode(data, dictionary):
    d = Decoder(dictionary)
    return d.feed(data), d.st


if __name__ == "__main__":
    if len(sys.argv) != 3:
        sys.exit(__doc__)
    out, st = decode(open(sys.argv[2], "rb").read(), json.load(open(sys.argv[1], encoding="utf-8")))
    sys.stdout.write("".join(s + "\n" for s in out))
    sys.stderr.write("frames %(frames)d, bad crc %(bad_crc)d, bad cobs %(bad_cobs)d, bad length %(bad_len)d, "
                     "missing %(missed)d, lost on device %(device_lost)d, unknown id %(unknown)d\n" % st)

Дальше: раздел 35д «Как отладчик управляет ядром: SWD, порты DP и AP, остановка ядра и точки останова FPB» — что идёт по двум проводам SWD, когда отладчик читает память, останавливает ядро и ставит точку останова.