The "Holy Bible" for embedded engineers
Understanding real-time debugging techniques, tools, and strategies for embedded systems with focus on FreeRTOS debugging and real-time system troubleshooting
Real-time debugging is like being a detective investigating a crime scene where the evidence keeps changing. Unlike regular debugging where you can pause and examine things at your leisure, real-time debugging requires you to catch problems “in the act” without disrupting the system’s timing.
In real-time systems, timing is everything. A bug that only appears when the system is running at full speed might be invisible when you pause execution. Real-time debugging techniques help you find these elusive timing-related bugs without breaking the real-time guarantees your system depends on.
// Real-time debugging with minimal overhead
void vApplicationStackOverflowHook(TaskHandle_t xTask, char *pcTaskName) {
// Log stack overflow without blocking
static uint32_t overflow_count = 0;
overflow_count++;
// Use GPIO for immediate visual feedback
GPIO_SetBits(GPIOA, GPIO_Pin_0); // Set LED to indicate overflow
// Log minimal information
log_debug_event("STACK_OVERFLOW", pcTaskName, overflow_count);
// Take corrective action if possible
if (overflow_count < 3) {
// Try to recover
vTaskDelete(xTask);
} else {
// System reset after multiple overflows
NVIC_SystemReset();
}
}
// Non-blocking debug output
void debug_print(const char* message) {
// Use circular buffer to avoid blocking
if (debug_buffer_space_available()) {
debug_buffer_write(message, strlen(message));
}
// Don't block if buffer is full
}
Real-time debugging requires a different mindset - you need to observe the system while it’s running, use non-intrusive techniques, and think about timing implications of every debugging action.
Real-time debugging and trace analysis are critical for understanding system behavior, identifying timing issues, and optimizing performance in embedded real-time systems. Effective debugging systems provide non-intrusive monitoring and comprehensive trace data for system analysis.
1. System Understanding:
2. Problem Diagnosis:
3. System Optimization:
1. Non-Intrusiveness:
2. Data Collection:
3. Analysis Capabilities:
Core Components:
System Flow:
System Events → Event Capture → Trace Buffer → Analysis → Output/Export
1. Task Events:
2. Synchronization Events:
3. Timing Events:
4. System Events:
Event Header:
typedef struct {
uint32_t timestamp; // Event timestamp
uint8_t event_type; // Event type identifier
uint8_t event_subtype; // Event subtype
uint16_t event_size; // Event data size
uint32_t task_id; // Associated task ID
} trace_event_header_t;
Event Types:
typedef enum {
TRACE_EVENT_TASK_CREATE = 0,
TRACE_EVENT_TASK_DELETE,
TRACE_EVENT_TASK_SWITCH,
TRACE_EVENT_TASK_BLOCK,
TRACE_EVENT_TASK_UNBLOCK,
TRACE_EVENT_MUTEX_TAKE,
TRACE_EVENT_MUTEX_GIVE,
TRACE_EVENT_SEMAPHORE_TAKE,
TRACE_EVENT_SEMAPHORE_GIVE,
TRACE_EVENT_QUEUE_SEND,
TRACE_EVENT_QUEUE_RECEIVE,
TRACE_EVENT_INTERRUPT_ENTER,
TRACE_EVENT_INTERRUPT_EXIT,
TRACE_EVENT_TICK,
TRACE_EVENT_DEADLINE_MISS,
TRACE_EVENT_MEMORY_ALLOC,
TRACE_EVENT_MEMORY_FREE,
TRACE_EVENT_SYSTEM_ERROR,
TRACE_EVENT_CUSTOM = 0xFF
} trace_event_type_t;
Circular Trace Buffer:
typedef struct {
trace_event_header_t *buffer;
uint32_t buffer_size;
uint32_t head_index;
uint32_t tail_index;
uint32_t event_count;
bool buffer_full;
SemaphoreHandle_t buffer_mutex;
} trace_buffer_t;
trace_buffer_t g_trace_buffer = {0};
void vInitializeTraceBuffer(uint32_t buffer_size) {
g_trace_buffer.buffer = pvPortMalloc(buffer_size * sizeof(trace_event_header_t));
g_trace_buffer.buffer_size = buffer_size;
g_trace_buffer.head_index = 0;
g_trace_buffer.tail_index = 0;
g_trace_buffer.event_count = 0;
g_trace_buffer.buffer_full = false;
g_trace_buffer.buffer_mutex = xSemaphoreCreateMutex();
printf("Trace buffer initialized with %lu events\n", buffer_size);
}
bool vAddTraceEvent(trace_event_type_t event_type, uint8_t event_subtype,
uint32_t task_id, void *event_data, uint16_t data_size) {
if (xSemaphoreTake(g_trace_buffer.buffer_mutex, pdMS_TO_ICKS(10)) != pdTRUE) {
return false; // Buffer busy
}
// Check if buffer is full
if (g_trace_buffer.buffer_full) {
// Overwrite oldest event
g_trace_buffer.tail_index = (g_trace_buffer.tail_index + 1) % g_trace_buffer.buffer_size;
g_trace_buffer.event_count--;
}
// Add new event
uint32_t current_index = g_trace_buffer.head_index;
g_trace_buffer.buffer[current_index].timestamp = xTaskGetTickCount();
g_trace_buffer.buffer[current_index].event_type = event_type;
g_trace_buffer.buffer[current_index].event_subtype = event_subtype;
g_trace_buffer.buffer[current_index].event_size = data_size;
g_trace_buffer.buffer[current_index].task_id = task_id;
// Update buffer state
g_trace_buffer.head_index = (g_trace_buffer.head_index + 1) % g_trace_buffer.buffer_size;
g_trace_buffer.event_count++;
if (g_trace_buffer.head_index == g_trace_buffer.tail_index) {
g_trace_buffer.buffer_full = true;
}
xSemaphoreGive(g_trace_buffer.buffer_mutex);
return true;
}
Task Switch Tracing:
void vTraceTaskSwitch(TaskHandle_t previous_task, TaskHandle_t current_task) {
uint32_t previous_task_id = (previous_task != NULL) ? (uint32_t)previous_task : 0;
uint32_t current_task_id = (current_task != NULL) ? (uint32_t)current_task : 0;
// Create task switch event
task_switch_event_t switch_event;
switch_event.previous_task_id = previous_task_id;
switch_event.current_task_id = current_task_id;
switch_event.switch_reason = 0; // Can be extended with switch reason
vAddTraceEvent(TRACE_EVENT_TASK_SWITCH, 0, current_task_id,
&switch_event, sizeof(switch_event));
}
typedef struct {
uint32_t previous_task_id;
uint32_t current_task_id;
uint8_t switch_reason;
} task_switch_event_t;
Task Block/Unblock Tracing:
void vTraceTaskBlock(TaskHandle_t task_handle, uint8_t block_reason) {
uint32_t task_id = (task_handle != NULL) ? (uint32_t)task_handle : 0;
task_block_event_t block_event;
block_event.block_reason = block_reason;
block_event.block_time = xTaskGetTickCount();
vAddTraceEvent(TRACE_EVENT_TASK_BLOCK, block_reason, task_id,
&block_event, sizeof(block_event));
}
typedef struct {
uint8_t block_reason;
uint32_t block_time;
} task_block_event_t;
Log Entry Structure:
typedef struct {
uint32_t timestamp;
uint8_t log_level;
uint8_t component_id;
uint16_t message_id;
char message[64];
uint32_t data_value;
} log_entry_t;
typedef enum {
LOG_LEVEL_DEBUG = 0,
LOG_LEVEL_INFO,
LOG_LEVEL_WARNING,
LOG_LEVEL_ERROR,
LOG_LEVEL_CRITICAL
} log_level_t;
typedef enum {
COMPONENT_SYSTEM = 0,
COMPONENT_SCHEDULER,
COMPONENT_MEMORY,
COMPONENT_INTERRUPT,
COMPONENT_TASK,
COMPONENT_SYNC,
COMPONENT_CUSTOM
} component_id_t;
Logging Implementation:
typedef struct {
log_entry_t *log_buffer;
uint32_t buffer_size;
uint32_t head_index;
uint32_t tail_index;
uint32_t entry_count;
bool buffer_full;
SemaphoreHandle_t log_mutex;
} log_system_t;
log_system_t g_log_system = {0};
void vInitializeLogSystem(uint32_t buffer_size) {
g_log_system.log_buffer = pvPortMalloc(buffer_size * sizeof(log_entry_t));
g_log_system.buffer_size = buffer_size;
g_log_system.head_index = 0;
g_log_system.tail_index = 0;
g_log_system.entry_count = 0;
g_log_system.buffer_full = false;
g_log_system.log_mutex = xSemaphoreCreateMutex();
printf("Log system initialized with %lu entries\n", buffer_size);
}
void vLogEvent(log_level_t level, component_id_t component, uint16_t message_id,
const char *message, uint32_t data_value) {
if (xSemaphoreTake(g_log_system.log_mutex, pdMS_TO_ICKS(10)) != pdTRUE) {
return; // Log system busy
}
// Check if buffer is full
if (g_log_system.buffer_full) {
// Overwrite oldest entry
g_log_system.tail_index = (g_log_system.tail_index + 1) % g_log_system.buffer_size;
g_log_system.entry_count--;
}
// Add new log entry
uint32_t current_index = g_log_system.head_index;
g_log_system.log_buffer[current_index].timestamp = xTaskGetTickCount();
g_log_system.log_buffer[current_index].log_level = level;
g_log_system.log_buffer[current_index].component_id = component;
g_log_system.log_buffer[current_index].message_id = message_id;
g_log_system.log_buffer[current_index].data_value = data_value;
strncpy(g_log_system.log_buffer[current_index].message, message, 63);
g_log_system.log_buffer[current_index].message[63] = '\0';
// Update buffer state
g_log_system.head_index = (g_log_system.head_index + 1) % g_log_system.buffer_size;
g_log_system.entry_count++;
if (g_log_system.head_index == g_log_system.tail_index) {
g_log_system.buffer_full = true;
}
xSemaphoreGive(g_log_system.log_mutex);
// Print critical and error messages immediately
if (level >= LOG_LEVEL_ERROR) {
printf("[%s] %s (Data: %lu)\n",
vGetLogLevelString(level), message, data_value);
}
}
Trace Analysis Engine:
typedef struct {
uint32_t total_events;
uint32_t events_by_type[32];
uint32_t events_by_task[10];
uint32_t deadline_misses;
uint32_t response_time_violations;
uint32_t memory_errors;
uint32_t synchronization_errors;
} trace_analysis_t;
trace_analysis_t g_trace_analysis = {0};
void vAnalyzeTraceData(void) {
memset(&g_trace_analysis, 0, sizeof(trace_analysis_t));
if (xSemaphoreTake(g_trace_buffer.buffer_mutex, portMAX_DELAY) == pdTRUE) {
uint32_t current_index = g_trace_buffer.tail_index;
uint32_t events_processed = 0;
while (events_processed < g_trace_buffer.event_count) {
trace_event_header_t *event = &g_trace_buffer.buffer[current_index];
// Count events by type
if (event->event_type < 32) {
g_trace_analysis.events_by_type[event->event_type]++;
}
// Count events by task
if (event->task_id < 10) {
g_trace_analysis.events_by_task[event->task_id]++;
}
// Analyze specific event types
switch (event->event_type) {
case TRACE_EVENT_DEADLINE_MISS:
g_trace_analysis.deadline_misses++;
break;
case TRACE_EVENT_SYSTEM_ERROR:
g_trace_analysis.memory_errors++;
break;
default:
break;
}
g_trace_analysis.total_events++;
current_index = (current_index + 1) % g_trace_buffer.buffer_size;
events_processed++;
}
xSemaphoreGive(g_trace_buffer.buffer_mutex);
}
// Print analysis results
vPrintTraceAnalysis();
}
void vPrintTraceAnalysis(void) {
printf("\n=== Trace Analysis Results ===\n");
printf("Total Events: %lu\n", g_trace_analysis.total_events);
printf("Deadline Misses: %lu\n", g_trace_analysis.deadline_misses);
printf("System Errors: %lu\n", g_trace_analysis.memory_errors);
printf("\nEvents by Type:\n");
for (int i = 0; i < 32; i++) {
if (g_trace_analysis.events_by_type[i] > 0) {
printf(" Type %d: %lu events\n", i, g_trace_analysis.events_by_type[i]);
}
}
printf("\nEvents by Task:\n");
for (int i = 0; i < 10; i++) {
if (g_trace_analysis.events_by_task[i] > 0) {
printf(" Task %d: %lu events\n", i, g_trace_analysis.events_by_task[i]);
}
}
printf("=============================\n\n");
}
Console Command Structure:
typedef struct {
const char *command_name;
const char *description;
void (*command_function)(int argc, char *argv[]);
} console_command_t;
console_command_t debug_commands[] = {
{"help", "Show available commands", vConsoleHelp},
{"status", "Show system status", vConsoleStatus},
{"trace", "Control trace system", vConsoleTrace},
{"log", "Control logging system", vConsoleLog},
{"memory", "Show memory information", vConsoleMemory},
{"tasks", "Show task information", vConsoleTasks},
{"performance", "Show performance data", vConsolePerformance},
{"clear", "Clear trace/log buffers", vConsoleClear},
{"export", "Export trace data", vConsoleExport}
};
void vProcessConsoleCommand(char *command_line) {
char *argv[16];
int argc = 0;
// Parse command line
char *token = strtok(command_line, " ");
while (token != NULL && argc < 16) {
argv[argc++] = token;
token = strtok(NULL, " ");
}
if (argc > 0) {
// Find and execute command
bool command_found = false;
for (int i = 0; i < sizeof(debug_commands) / sizeof(debug_commands[0]); i++) {
if (strcmp(argv[0], debug_commands[i].command_name) == 0) {
debug_commands[i].command_function(argc, argv);
command_found = true;
break;
}
}
if (!command_found) {
printf("Unknown command: %s\n", argv[0]);
printf("Type 'help' for available commands\n");
}
}
}
Console Command Implementations:
void vConsoleStatus(int argc, char *argv[]) {
printf("\n=== System Status ===\n");
printf("System Uptime: %lu ticks\n", xTaskGetTickCount());
printf("Free Heap: %zu bytes\n", xPortGetFreeHeapSize());
printf("Minimum Free Heap: %zu bytes\n", xPortGetMinimumEverFreeHeapSize());
printf("Trace Events: %lu\n", g_trace_buffer.event_count);
printf("Log Entries: %lu\n", g_log_system.entry_count);
printf("===================\n\n");
}
void vConsoleTrace(int argc, char *argv[]) {
if (argc < 2) {
printf("Usage: trace [start|stop|status|clear]\n");
return;
}
if (strcmp(argv[1], "start") == 0) {
g_trace_buffer.buffer_mutex = xSemaphoreCreateMutex();
printf("Trace system started\n");
} else if (strcmp(argv[1], "stop") == 0) {
printf("Trace system stopped\n");
} else if (strcmp(argv[1], "status") == 0) {
printf("Trace buffer: %lu/%lu events\n",
g_trace_buffer.event_count, g_trace_buffer.buffer_size);
} else if (strcmp(argv[1], "clear") == 0) {
g_trace_buffer.head_index = 0;
g_trace_buffer.tail_index = 0;
g_trace_buffer.event_count = 0;
g_trace_buffer.buffer_full = false;
printf("Trace buffer cleared\n");
}
}
void vConsoleExport(int argc, char *argv[]) {
if (argc < 2) {
printf("Usage: export [trace|log] [filename]\n");
return;
}
if (strcmp(argv[1], "trace") == 0) {
vExportTraceData(argc > 2 ? argv[2] : "trace.csv");
} else if (strcmp(argv[1], "log") == 0) {
vExportLogData(argc > 2 ? argv[2] : "log.csv");
}
}
CSV Export Implementation:
void vExportTraceData(const char *filename) {
FILE *file = fopen(filename, "w");
if (file == NULL) {
printf("Error: Cannot create file %s\n", filename);
return;
}
// Write CSV header
fprintf(file, "Timestamp,EventType,EventSubtype,TaskID,EventSize\n");
if (xSemaphoreTake(g_trace_buffer.buffer_mutex, portMAX_DELAY) == pdTRUE) {
uint32_t current_index = g_trace_buffer.tail_index;
uint32_t events_processed = 0;
while (events_processed < g_trace_buffer.event_count) {
trace_event_header_t *event = &g_trace_buffer.buffer[current_index];
fprintf(file, "%lu,%u,%u,%lu,%u\n",
event->timestamp,
event->event_type,
event->event_subtype,
event->task_id,
event->event_size);
current_index = (current_index + 1) % g_trace_buffer.buffer_size;
events_processed++;
}
xSemaphoreGive(g_trace_buffer.buffer_mutex);
}
fclose(file);
printf("Trace data exported to %s\n", filename);
}
void vExportLogData(const char *filename) {
FILE *file = fopen(filename, "w");
if (file == NULL) {
printf("Error: Cannot create file %s\n", filename);
return;
}
// Write CSV header
fprintf(file, "Timestamp,Level,Component,MessageID,Message,DataValue\n");
if (xSemaphoreTake(g_log_system.log_mutex, portMAX_DELAY) == pdTRUE) {
uint32_t current_index = g_log_system.tail_index;
uint32_t entries_processed = 0;
while (entries_processed < g_log_system.entry_count) {
log_entry_t *entry = &g_log_system.log_buffer[current_index];
fprintf(file, "%lu,%u,%u,%u,\"%s\",%lu\n",
entry->timestamp,
entry->log_level,
entry->component_id,
entry->message_id,
entry->message,
entry->data_value);
current_index = (current_index + 1) % g_log_system.buffer_size;
entries_processed++;
}
xSemaphoreGive(g_log_system.log_mutex);
}
fclose(file);
printf("Log data exported to %s\n", filename);
}
Profiler Implementation:
typedef struct {
const char *function_name;
uint32_t call_count;
uint32_t total_execution_time;
uint32_t min_execution_time;
uint32_t max_execution_time;
uint32_t last_start_time;
bool is_profiling;
} function_profile_t;
function_profile_t function_profiles[100];
uint8_t profile_count = 0;
void vStartFunctionProfiling(const char *function_name) {
int profile_index = vFindProfileIndex(function_name);
if (profile_index >= 0) {
function_profiles[profile_index].last_start_time = DWT->CYCCNT;
function_profiles[profile_index].is_profiling = true;
}
}
void vEndFunctionProfiling(const char *function_name) {
int profile_index = vFindProfileIndex(function_name);
if (profile_index >= 0 && function_profiles[profile_index].is_profiling) {
uint32_t end_time = DWT->CYCCNT;
uint32_t execution_time = end_time - function_profiles[profile_index].last_start_time;
// Update statistics
function_profiles[profile_index].call_count++;
function_profiles[profile_index].total_execution_time += execution_time;
if (execution_time < function_profiles[profile_index].min_execution_time ||
function_profiles[profile_index].min_execution_time == 0) {
function_profiles[profile_index].min_execution_time = execution_time;
}
if (execution_time > function_profiles[profile_index].max_execution_time) {
function_profiles[profile_index].max_execution_time = execution_time;
}
function_profiles[profile_index].is_profiling = false;
}
}
void vPrintFunctionProfiles(void) {
printf("\n=== Function Profiles ===\n");
for (int i = 0; i < profile_count; i++) {
if (function_profiles[i].call_count > 0) {
float avg_time = (float)function_profiles[i].total_execution_time /
(float)function_profiles[i].call_count;
printf("%s:\n", function_profiles[i].function_name);
printf(" Calls: %lu\n", function_profiles[i].call_count);
printf(" Avg Time: %.2f cycles\n", avg_time);
printf(" Min Time: %lu cycles\n", function_profiles[i].min_execution_time);
printf(" Max Time: %lu cycles\n", function_profiles[i].max_execution_time);
printf(" Total Time: %lu cycles\n", function_profiles[i].total_execution_time);
printf("\n");
}
}
printf("=======================\n\n");
}
Memory Allocation Profiling:
typedef struct {
const char *allocation_site;
uint32_t allocation_count;
size_t total_allocated;
size_t current_allocated;
size_t max_allocated;
size_t min_allocation_size;
size_t max_allocation_size;
} memory_profile_t;
memory_profile_t memory_profiles[50];
uint8_t memory_profile_count = 0;
void* vProfiledMalloc(size_t size, const char *site) {
void *ptr = pvPortMalloc(size);
if (ptr != NULL) {
int profile_index = vFindMemoryProfileIndex(site);
if (profile_index >= 0) {
memory_profiles[profile_index].allocation_count++;
memory_profiles[profile_index].total_allocated += size;
memory_profiles[profile_index].current_allocated += size;
if (size < memory_profiles[profile_index].min_allocation_size ||
memory_profiles[profile_index].min_allocation_size == 0) {
memory_profiles[profile_index].min_allocation_size = size;
}
if (size > memory_profiles[profile_index].max_allocation_size) {
memory_profiles[profile_index].max_allocation_size = size;
}
if (memory_profiles[profile_index].current_allocated >
memory_profiles[profile_index].max_allocated) {
memory_profiles[profile_index].max_allocated =
memory_profiles[profile_index].current_allocated;
}
}
}
return ptr;
}
void vProfiledFree(void *ptr, const char *site) {
// Note: This is a simplified version - real implementation would track
// allocation sizes per pointer for accurate deallocation tracking
int profile_index = vFindMemoryProfileIndex(site);
if (profile_index >= 0) {
// For simplicity, assume average allocation size
size_t avg_size = memory_profiles[profile_index].total_allocated /
memory_profiles[profile_index].allocation_count;
memory_profiles[profile_index].current_allocated -= avg_size;
}
vPortFree(ptr);
}
System Initialization:
void vInitializeDebugSystem(void) {
// Initialize trace system
vInitializeTraceBuffer(1000); // 1000 trace events
// Initialize log system
vInitializeLogSystem(500); // 500 log entries
// Initialize function profiling
memset(function_profiles, 0, sizeof(function_profiles));
// Initialize memory profiling
memset(memory_profiles, 0, sizeof(memory_profiles));
// Start debug console task
xTaskCreate(vDebugConsoleTask, "DebugConsole", 512, NULL, 1, NULL);
// Start trace analysis task
xTaskCreate(vTraceAnalysisTask, "TraceAnalysis", 512, NULL, 1, NULL);
printf("Debug system initialized\n");
}
Debug Console Task:
void vDebugConsoleTask(void *pvParameters) {
char command_line[256];
int char_index = 0;
printf("Debug console ready. Type 'help' for commands.\n");
while (1) {
// Simple character-based input (can be enhanced with UART interrupt handling)
if (char_index < 255) {
int ch = getchar(); // Replace with your UART input function
if (ch != EOF && ch != '\n') {
command_line[char_index++] = ch;
putchar(ch); // Echo character
} else if (ch == '\n') {
command_line[char_index] = '\0';
putchar('\n');
if (char_index > 0) {
vProcessConsoleCommand(command_line);
}
char_index = 0;
printf("> ");
}
} else {
// Buffer full, reset
char_index = 0;
printf("\nBuffer overflow, command ignored\n> ");
}
vTaskDelay(pdMS_TO_TICKS(10));
}
}
Trace Analysis Task:
void vTraceAnalysisTask(void *pvParameters) {
TickType_t last_analysis_time = xTaskGetTickCount();
while (1) {
// Perform trace analysis every 10 seconds
vTaskDelayUntil(&last_analysis_time, pdMS_TO_TICKS(10000));
vAnalyzeTraceData();
// Check for critical conditions
if (g_trace_analysis.deadline_misses > 5) {
vLogEvent(LOG_LEVEL_WARNING, COMPONENT_SYSTEM, 1001,
"High deadline miss count", g_trace_analysis.deadline_misses);
}
if (g_trace_analysis.memory_errors > 0) {
vLogEvent(LOG_LEVEL_ERROR, COMPONENT_MEMORY, 2001,
"Memory errors detected", g_trace_analysis.memory_errors);
}
}
}
Objective: Implement basic debug hooks for system monitoring Steps:
Expected Outcome: System health monitoring without affecting timing
Objective: Implement trace collection and analysis Steps:
Expected Outcome: Complete visibility into system behavior over time
Objective: Debug timing issues without affecting system performance Steps:
Expected Outcome: Effective debugging without breaking real-time guarantees
This comprehensive Real-Time Debugging document provides embedded engineers with the theoretical foundation, practical implementation examples, and best practices needed to implement effective debugging and trace analysis systems in real-time environments.