Logging and Trace Techniques in Embedded C

Table of Contents

Embedded Systems Learning Path
Part 102 of 129 — View Full Path →

KEY TAKEAWAYS

A structured logging framework with severity levels (ERROR, WARN, INFO, DEBUG) lets you filter noise and focus on relevant events.
Ring buffer logging stores messages in RAM without blocking — essential for ISRs and real-time code.
Compile-time log level filtering removes debug messages from release builds with zero overhead using preprocessor macros.
Binary trace logging (event ID + timestamp + data) is 10-100× more efficient than formatted string logging.
Post-mortem logging survives crashes — store logs in a no-init RAM section that persists through resets.

Why Logging Matters in Embedded

When your firmware runs on a device in the field — no debugger attached, no GDB, no logic analyzer — logging is your only window into what happened. A good logging system records the sequence of events leading up to a crash, a communication failure, or unexpected behavior, letting you diagnose problems from log output alone.

But embedded logging is harder than desktop logging. You have limited RAM (no room for large string buffers), limited flash (can’t store verbose log strings), real-time constraints (logging can’t delay ISR execution), and often no filesystem. This article shows you how to build a logging system that handles all these constraints.

Basic Logging Framework

A good embedded logging framework must be lightweight, configurable, and fast. Unlike server-side logging where you can write freely to disk, embedded logging must minimize its impact on real-time behavior. The framework below uses compile-time log level filtering to completely eliminate disabled log calls from the binary — a disabled log statement costs zero CPU cycles and zero flash bytes. It routes output through a configurable backend so you can switch between UART, SPI, I2C, or memory-mapped output without changing application code.

/* log.h — Embedded Logging Framework */

#ifndef LOG_H
#define LOG_H

#include 

/* Log severity levels */
typedef enum {
    LOG_LEVEL_ERROR = 0,  /* System failures, unrecoverable errors */
    LOG_LEVEL_WARN  = 1,  /* Potential problems, degraded operation */
    LOG_LEVEL_INFO  = 2,  /* Normal operational events */
    LOG_LEVEL_DEBUG = 3,  /* Detailed debugging information */
    LOG_LEVEL_TRACE = 4   /* Very verbose, function entry/exit */
} log_level_t;

/* Compile-time log level — messages above this are removed entirely */
#ifndef LOG_LEVEL_MAX
    #ifdef NDEBUG
        #define LOG_LEVEL_MAX  LOG_LEVEL_INFO   /* Release: no debug/trace */
    #else
        #define LOG_LEVEL_MAX  LOG_LEVEL_DEBUG  /* Debug: include debug msgs */
    #endif
#endif

/* Module identification */
typedef enum {
    LOG_MOD_MAIN   = 0,
    LOG_MOD_UART   = 1,
    LOG_MOD_I2C    = 2,
    LOG_MOD_SPI    = 3,
    LOG_MOD_SENSOR = 4,
    LOG_MOD_MOTOR  = 5,
    LOG_MOD_APP    = 6,
    LOG_MOD_COUNT
} log_module_t;

/* Core logging function */
void log_write(log_level_t level, log_module_t module,
               const char *fmt, ...);

/* Convenience macros — zero overhead when compiled out */
#if LOG_LEVEL_MAX >= LOG_LEVEL_ERROR
    #define LOG_E(mod, fmt, ...) log_write(LOG_LEVEL_ERROR, mod, fmt, ##__VA_ARGS__)
#else
    #define LOG_E(mod, fmt, ...) ((void)0)
#endif

#if LOG_LEVEL_MAX >= LOG_LEVEL_WARN
    #define LOG_W(mod, fmt, ...) log_write(LOG_LEVEL_WARN, mod, fmt, ##__VA_ARGS__)
#else
    #define LOG_W(mod, fmt, ...) ((void)0)
#endif

#if LOG_LEVEL_MAX >= LOG_LEVEL_INFO
    #define LOG_I(mod, fmt, ...) log_write(LOG_LEVEL_INFO, mod, fmt, ##__VA_ARGS__)
#else
    #define LOG_I(mod, fmt, ...) ((void)0)
#endif

#if LOG_LEVEL_MAX >= LOG_LEVEL_DEBUG
    #define LOG_D(mod, fmt, ...) log_write(LOG_LEVEL_DEBUG, mod, fmt, ##__VA_ARGS__)
#else
    #define LOG_D(mod, fmt, ...) ((void)0)
#endif

#if LOG_LEVEL_MAX >= LOG_LEVEL_TRACE
    #define LOG_T(mod, fmt, ...) log_write(LOG_LEVEL_TRACE, mod, fmt, ##__VA_ARGS__)
#else
    #define LOG_T(mod, fmt, ...) ((void)0)
#endif

/* Runtime log level filtering (can be changed on-the-fly) */
void log_set_level(log_level_t level);
void log_set_module_level(log_module_t module, log_level_t level);

#endif /* LOG_H */

/* log.c — Logging Implementation */

#include "log.h"
#include 
#include 
#include 

/* Runtime filter level (in addition to compile-time) */
static log_level_t global_log_level = LOG_LEVEL_DEBUG;
static log_level_t module_levels[LOG_MOD_COUNT];
static uint8_t module_level_set[LOG_MOD_COUNT] = {0};

/* Level and module name strings (stored in flash) */
static const char * const level_names[] = {
    "ERR", "WRN", "INF", "DBG", "TRC"
};

static const char * const module_names[] = {
    "MAIN", "UART", "I2C", "SPI", "SENS", "MOTR", "APP"
};

/* Timestamp source */
extern uint32_t get_tick_ms(void);  /* From your SysTick or timer */

/* Output function — customize for your hardware */
static void log_output(const char *str, uint16_t len) {
    /* Option 1: UART */
    uart_send_buffer((const uint8_t *)str, len);

    /* Option 2: ITM/SWO (via debugger) */
    /* for (uint16_t i = 0; i < len; i++) itm_putchar(str[i]); */

    /* Option 3: Ring buffer (deferred output) */
    /* ringbuf_write(&log_ringbuf, str, len); */
}

void log_set_level(log_level_t level) {
    global_log_level = level;
}

void log_set_module_level(log_module_t module, log_level_t level) {
    if (module  effective_level) return;

    /* Format: [timestamp] LEVEL MODULE: messagern */
    char buf[128];
    int pos = 0;

    /* Timestamp */
    uint32_t ms = get_tick_ms();
    pos += snprintf(buf + pos, sizeof(buf) - pos,
                    "[%5lu.%03lu] %s %s: ",
                    ms / 1000, ms % 1000,
                    level_names[level],
                    module_names[module]);

    /* User message */
    va_list args;
    va_start(args, fmt);
    pos += vsnprintf(buf + pos, sizeof(buf) - pos, fmt, args);
    va_end(args);

    /* Line ending */
    if (pos < (int)sizeof(buf) - 2) {
        buf[pos++] = 'r';
        buf[pos++] = 'n';
    }

    log_output(buf, (uint16_t)pos);
}

/* Usage:
 * LOG_I(LOG_MOD_SENSOR, "Temperature: %d.%02d C", temp/100, temp%100);
 * LOG_E(LOG_MOD_I2C, "NACK from device 0x%02X", addr);
 * LOG_D(LOG_MOD_UART, "RX byte: 0x%02X", byte);
 *
 * Output:
 * [  1.234] INF SENS: Temperature: 23.45 C
 * [  1.250] ERR I2C: NACK from device 0x76
 * [  1.251] DBG UART: RX byte: 0x0A
 */

Ring Buffer Logging (Non-Blocking)

The basic framework above calls uart_send_buffer() directly, which might block if the UART TX buffer is full. For real-time code and ISRs, you need non-blocking logging. A ring buffer stores messages in RAM and drains them to UART in the background.

/* Ring buffer for non-blocking log output */

#define LOG_RINGBUF_SIZE  1024  /* Power of 2 for fast modulo */

typedef struct {
    volatile uint8_t  buffer[LOG_RINGBUF_SIZE];
    volatile uint16_t head;  /* Write index */
    volatile uint16_t tail;  /* Read index */
} log_ringbuf_t;

static log_ringbuf_t log_rb = { .head = 0, .tail = 0 };

static inline uint16_t rb_used(log_ringbuf_t *rb) {
    return (rb->head - rb->tail) & (LOG_RINGBUF_SIZE - 1);
}

static inline uint16_t rb_free(log_ringbuf_t *rb) {
    return LOG_RINGBUF_SIZE - 1 - rb_used(rb);
}

/* Write to ring buffer (called from log_write) */
static uint16_t rb_write(log_ringbuf_t *rb, const char *data, uint16_t len) {
    uint16_t free = rb_free(rb);
    if (len > free) {
        len = free;  /* Drop overflow — better than blocking */
        /* Could increment a dropped_count here */
    }

    for (uint16_t i = 0; i buffer[rb->head] = (uint8_t)data[i];
        rb->head = (rb->head + 1) & (LOG_RINGBUF_SIZE - 1);
    }
    return len;
}

/* Drain ring buffer to UART (call from main loop) */
void log_flush(void) {
    while (log_rb.tail != log_rb.head) {
        uint8_t byte = log_rb.buffer[log_rb.tail];

        if (!uart_tx_ready()) break;  /* UART busy, try later */

        uart_send_byte_nonblocking(byte);
        log_rb.tail = (log_rb.tail + 1) & (LOG_RINGBUF_SIZE - 1);
    }
}

/* Call log_flush() from main loop or a low-priority task:
 *
 * while (1) {
 *     process_events();
 *     log_flush();    // Drain pending log messages
 * }
 */

Binary Trace Logging (Minimal Overhead)

String formatting (snprintf) is expensive — hundreds of CPU cycles per call. For high-frequency events (ISR entry/exit, state transitions, packet reception), binary trace logging records just an event ID, timestamp, and optional data words. A PC-side tool decodes the trace offline.

/* Binary trace logging — minimal overhead */

#include 

/* Trace event IDs */
#define TRACE_ISR_ENTER       0x01
#define TRACE_ISR_EXIT        0x02
#define TRACE_TASK_SWITCH     0x03
#define TRACE_I2C_START       0x10
#define TRACE_I2C_COMPLETE    0x11
#define TRACE_I2C_ERROR       0x12
#define TRACE_SPI_TRANSFER    0x20
#define TRACE_SENSOR_READ     0x30
#define TRACE_STATE_CHANGE    0x40
#define TRACE_ERROR           0xFF

/* Trace entry: 8 bytes — compact and fast */
typedef struct {
    uint32_t timestamp;  /* DWT cycle counter or SysTick */
    uint8_t  event_id;   /* What happened */
    uint8_t  data_hi;    /* Extra data (upper byte) */
    uint16_t data_lo;    /* Extra data (lower 16 bits) */
} trace_entry_t;

/* Circular trace buffer */
#define TRACE_BUFFER_SIZE  256  /* 256 entries × 8 bytes = 2KB RAM */

static trace_entry_t trace_buffer[TRACE_BUFFER_SIZE];
static volatile uint16_t trace_head = 0;
static volatile uint8_t  trace_enabled = 1;

/* DWT cycle counter for timestamps (ARM Cortex-M3/M4/M7) */
#define DWT_CYCCNT  (*(volatile uint32_t *)0xE0001004)
#define DWT_CTRL    (*(volatile uint32_t *)0xE0001000)
#define DCB_DEMCR   (*(volatile uint32_t *)0xE000EDFC)

void trace_init(void) {
    DCB_DEMCR |= (1 << 24);   /* Enable DWT */
    DWT_CTRL  |= 1;           /* Enable cycle counter */
}

/* Record a trace event — designed to be FAST (> 16);
    trace_buffer[idx].data_lo   = (uint16_t)(data & 0xFFFF);

    trace_head = (idx + 1) & (TRACE_BUFFER_SIZE - 1);
}

/* Usage in ISR — near-zero overhead */
void TIM2_IRQHandler(void) {
    trace_record(TRACE_ISR_ENTER, 2);  /* ISR #2 entered */

    /* ... handle interrupt ... */
    uint16_t adc_val = ADC1->DR;
    trace_record(TRACE_SENSOR_READ, adc_val);

    trace_record(TRACE_ISR_EXIT, 2);   /* ISR #2 exited */
}

/* Dump trace buffer via UART (for offline analysis) */
void trace_dump(void) {
    trace_enabled = 0;  /* Pause tracing during dump */

    printf("=== TRACE DUMP (%d entries) ===\n", TRACE_BUFFER_SIZE);

    for (uint16_t i = 0; i timestamp == 0 && e->event_id == 0) continue;

        uint32_t data = ((uint32_t)e->data_hi <data_lo;
        printf("%10lu  0x%02X  0x%06lX\n",
               e->timestamp, e->event_id, data);
    }

    trace_enabled = 1;
}

Post-Mortem Logging (Survives Crashes)

Regular logging is lost when the MCU crashes and resets. Post-mortem logging uses a special RAM section that is not initialized at startup, so its contents survive a reset. After a crash, the firmware reads the post-mortem buffer on the next boot and reports what happened before the crash.

/* Post-mortem log — survives MCU resets */

/* Place in a no-init RAM section (linker script dependent) */
/* GCC attribute: */
#define NOINIT __attribute__((section(".noinit")))

/* For STM32 linker scripts, add to your .ld file:
 *
 *   .noinit (NOLOAD) : {
 *       *(.noinit)
 *   } > RAM
 *
 * This section is NOT zero-initialized at startup.
 */

#define PM_LOG_SIZE   32  /* entries */
#define PM_MAGIC      0xDEAD1066

typedef struct {
    uint32_t timestamp;
    uint8_t  event;
    uint8_t  data[3];
} pm_entry_t;

typedef struct {
    uint32_t   magic;              /* Validity marker */
    uint32_t   reset_count;        /* How many times we've reset */
    uint32_t   last_reset_reason;  /* RCC_CSR reset flags */
    uint16_t   head;
    uint16_t   count;
    pm_entry_t entries[PM_LOG_SIZE];
} pm_log_t;

NOINIT static pm_log_t pm_log;

/* Call at startup, BEFORE other initialization */
void pm_log_init(void) {
    if (pm_log.magic != PM_MAGIC) {
        /* First boot or RAM was corrupted — initialize */
        memset(&pm_log, 0, sizeof(pm_log));
        pm_log.magic = PM_MAGIC;
    } else {
        /* Survived a reset! Increment counter and report */
        pm_log.reset_count++;

        /* Save reset reason from RCC */
        pm_log.last_reset_reason = RCC_CSR;
        RCC_CSR |= (1 << 24);  /* Clear reset flags */

        /* Output the post-mortem log */
        pm_log_report();
    }
}

void pm_log_record(uint8_t event, uint8_t d0, uint8_t d1, uint8_t d2) {
    uint16_t idx = pm_log.head;
    pm_log.entries[idx].timestamp = get_tick_ms();
    pm_log.entries[idx].event = event;
    pm_log.entries[idx].data[0] = d0;
    pm_log.entries[idx].data[1] = d1;
    pm_log.entries[idx].data[2] = d2;

    pm_log.head = (idx + 1) % PM_LOG_SIZE;
    if (pm_log.count < PM_LOG_SIZE) pm_log.count++;
}

void pm_log_report(void) {
    printf("n=== POST-MORTEM LOG ===n");
    printf("Reset count: %lun", pm_log.reset_count);
    printf("Last reset: 0x%08lX ", pm_log.last_reset_reason);

    /* Decode reset flags (STM32) */
    if (pm_log.last_reset_reason & (1 << 31)) printf("[LPWR]");
    if (pm_log.last_reset_reason & (1 << 30)) printf("[WWDG]");
    if (pm_log.last_reset_reason & (1 << 29)) printf("[IWDG]");
    if (pm_log.last_reset_reason & (1 << 28)) printf("[SFT]");
    if (pm_log.last_reset_reason & (1 << 27)) printf("[POR]");
    if (pm_log.last_reset_reason & (1 << 26)) printf("[PIN]");
    printf("n");

    printf("Last %d events before crash:n", pm_log.count);
    for (uint16_t i = 0; i timestamp, e->event,
               e->data[0], e->data[1], e->data[2]);
    }
    printf("=== END POST-MORTEM ===\n\n");
}

/* Usage — sprinkle throughout critical code paths */
/*
void main_init(void) {
    pm_log_init();   // First thing after reset!
    pm_log_record(0x01, 0, 0, 0);  // "System starting"

    if (init_uart() < 0)
        pm_log_record(0xE1, 0, 0, 0);  // "UART init failed"

    if (init_i2c() > 16) & 0xFF, (pc >> 8) & 0xFF, pc & 0xFF);
    NVIC_SystemReset();  // Reset — pm_log survives!
}
*/

Assertion Framework

Assertions catch bugs during development by verifying conditions that should always be true. In embedded systems, a failed assertion is more serious than on a desktop — you cannot just print a stack trace and exit. The assertion handler must log as much diagnostic information as possible (file, line, the failed expression) and then either halt the processor for debugger attachment or trigger a controlled reset. The key is making assertions cheap enough to leave enabled in production when needed.

/* Custom assert for embedded — logs location before halting/resetting */

#ifdef NDEBUG
    #define ASSERT(cond)  ((void)0)
#else
    #define ASSERT(cond)  do { 
        if (!(cond)) { 
            assert_failed(__FILE__, __LINE__, #cond); 
        } 
    } while (0)
#endif

void assert_failed(const char *file, int line, const char *expr) {
    /* Disable interrupts to prevent further damage */
    __asm volatile ("cpsid i");

    /* Log the assertion */
    LOG_E(LOG_MOD_MAIN, "ASSERT: %s:%d '%s'", file, line, expr);

    /* Record in post-mortem log */
    pm_log_record(0xFE, (uint8_t)(line >> 8), (uint8_t)line, 0);

    /* Flush log buffer */
    log_flush_blocking();

    /* Option 1: Halt (for debugging) */
    #ifdef DEBUG
    __asm volatile ("BKPT #0");  /* Trigger debugger breakpoint */
    #endif

    /* Option 2: Reset (for production) */
    NVIC_SystemReset();
}

/* Usage */
/*
void spi_transfer(uint8_t *buf, uint16_t len) {
    ASSERT(buf != NULL);
    ASSERT(len > 0 && len <= SPI_MAX_TRANSFER);
    // ... transfer code ...
}
*/

Choosing a Logging Strategy

The right logging approach depends on your constraints — available memory, acceptable CPU overhead, whether you need to survive power loss, and how you will retrieve the logs. Here is a decision guide based on common embedded scenarios.

UART text logging: Best for development and debugging. Human-readable. Use the framework above with ring buffer.
Binary trace: Best for performance analysis and high-frequency events. Minimal overhead. Needs PC decode tool.
Post-mortem: Essential for field debugging. Survives crashes. Combine with watchdog and reset tracking.
ITM/SWO trace: Best when UART is unavailable but debugger is connected. Zero firmware overhead with hardware trace.
LED blink codes: Last resort when nothing else is available. Encode error codes as blink patterns.

In practice, production firmware uses all of these: text logging during development, binary trace for performance tuning, post-mortem for field diagnostics, and assertions as safety nets.

Related on this site

Logging captures what happened; for stepping through what’s happening now, see GDB for embedded debugging.
Hardware-side debugging tools complement firmware tracing — see using a logic analyzer for embedded debugging.
For the broader embedded debugging landscape (which tool when), see debugging embedded systems: tools and techniques.

← Writing an I2C Driver in Embedded C

📚 Learning Path

Using an Oscilloscope for Embedded Systems: Practical Guide →

Vivek Bhageria

Vivek Bhageria — Lead Firmware R&D Engineer, 12+ years. Ex-Bosch (automotive powertrain), MusicTribe (real-time audio), medical devices. M.Tech BITS Pilani. I write at NerdyElectronics — practical, register-level embedded systems for engineers who want to understand what’s actually happening under the hood.

nerdyelectronics.com/about/