diff --git a/Makefile b/Makefile index ba9b071..23ef4d0 100644 --- a/Makefile +++ b/Makefile @@ -17,7 +17,7 @@ include arch/$(ARCH)/build.mk INC_DIRS += -I $(SRC_DIR)/include \ -I $(SRC_DIR)/include/lib -KERNEL_OBJS := timer.o mqueue.o pipe.o semaphore.o mutex.o error.o syscall.o task.o main.o +KERNEL_OBJS := timer.o mqueue.o pipe.o semaphore.o mutex.o logger.o error.o syscall.o task.o main.o KERNEL_OBJS := $(addprefix $(BUILD_KERNEL_DIR)/,$(KERNEL_OBJS)) deps += $(KERNEL_OBJS:%.o=%.o.d) diff --git a/app/mutex.c b/app/mutex.c index 1bff200..c332687 100644 --- a/app/mutex.c +++ b/app/mutex.c @@ -18,14 +18,13 @@ static int currently_in_critical_section = 0; /* Enhanced Task A */ void task_a(void) { - /* WORKAROUND: Printf not thread-safe in preemptive mode - minimize usage */ - for (int i = 0; i < MAX_ITERATIONS; i++) { mo_sem_wait(binary_mutex); /* === CRITICAL SECTION START === */ if (currently_in_critical_section != 0) { critical_section_violations++; + printf("Task A: VIOLATION detected at iteration %d\n", i); } currently_in_critical_section = mo_task_id(); @@ -37,9 +36,11 @@ void task_a(void) shared_counter = old_counter + 1; task_a_count++; + printf("Task A: iteration %d, counter=%d\n", i, shared_counter); if (currently_in_critical_section != mo_task_id()) { critical_section_violations++; + printf("Task A: VIOLATION on exit at iteration %d\n", i); } currently_in_critical_section = 0; /* === CRITICAL SECTION END === */ @@ -51,6 +52,8 @@ void task_a(void) mo_task_yield(); } + printf("Task A completed all iterations\n"); + /* Keep running to prevent panic */ while (1) { for (int i = 0; i < 10; i++) @@ -61,18 +64,18 @@ void task_a(void) /* Enhanced Task B */ void task_b(void) { - /* WORKAROUND: Printf not thread-safe in preemptive mode - minimize usage */ - for (int i = 0; i < MAX_ITERATIONS; i++) { /* Try non-blocking first */ int32_t trylock_result = mo_sem_trywait(binary_mutex); if (trylock_result != ERR_OK) { + printf("Task B: trylock failed, blocking at iteration %d\n", i); mo_sem_wait(binary_mutex); } /* === CRITICAL SECTION START === */ if (currently_in_critical_section != 0) { critical_section_violations++; + printf("Task B: VIOLATION detected at iteration %d\n", i); } currently_in_critical_section = mo_task_id(); @@ -84,9 +87,11 @@ void task_b(void) shared_counter = old_counter + 10; task_b_count++; + printf("Task B: iteration %d, counter=%d\n", i, shared_counter); if (currently_in_critical_section != mo_task_id()) { critical_section_violations++; + printf("Task B: VIOLATION on exit at iteration %d\n", i); } currently_in_critical_section = 0; /* === CRITICAL SECTION END === */ @@ -98,6 +103,8 @@ void task_b(void) mo_task_yield(); } + printf("Task B completed all iterations\n"); + /* Keep running to prevent panic */ while (1) { for (int i = 0; i < 10; i++) @@ -108,15 +115,16 @@ void task_b(void) /* Simple monitor task */ void monitor_task(void) { - /* WORKAROUND: Printf not thread-safe - only print at end when tasks idle */ - int cycles = 0; + printf("Monitor: Starting test monitoring\n"); + while (cycles < 50) { /* Monitor for reasonable time */ cycles++; /* Check if both tasks completed */ if (task_a_count >= MAX_ITERATIONS && task_b_count >= MAX_ITERATIONS) { + printf("Monitor: Both tasks completed, finalizing test\n"); break; } @@ -125,11 +133,11 @@ void monitor_task(void) mo_task_yield(); } - /* Wait a bit for tasks to fully idle */ + /* Wait a bit for tasks to fully complete */ for (int i = 0; i < 50; i++) mo_task_yield(); - /* Final report - safe to print when other tasks are idle */ + /* Final report */ printf("\n=== FINAL RESULTS ===\n"); printf("Task A iterations: %d\n", task_a_count); printf("Task B iterations: %d\n", task_b_count); @@ -193,7 +201,9 @@ int32_t app_main(void) return false; } - /* CRITICAL FIX: Printf hangs after task_spawn - remove all printf calls */ - /* Tasks created: A=%d, B=%d, Monitor=%d, Idle=%d */ + printf("Tasks created: A=%d, B=%d, Monitor=%d, Idle=%d\n", task_a_id, + task_b_id, monitor_id, idle_id); + printf("Enabling preemptive scheduling mode\n"); + return true; /* Enable preemptive scheduling */ } diff --git a/include/lib/libc.h b/include/lib/libc.h index 5951c3b..43ef61f 100644 --- a/include/lib/libc.h +++ b/include/lib/libc.h @@ -141,6 +141,7 @@ int random_r(struct random_data *buf, int32_t *result); /* Character and string output */ int32_t puts(const char *str); +int _putchar(int c); /* Low-level character output (used by logger) */ /* Character and string input */ int getchar(void); diff --git a/include/linmo.h b/include/linmo.h index 420e7d0..e4cbecf 100644 --- a/include/linmo.h +++ b/include/linmo.h @@ -6,6 +6,7 @@ #include #include +#include #include #include #include diff --git a/include/private/error.h b/include/private/error.h index 27dcfb8..5589087 100644 --- a/include/private/error.h +++ b/include/private/error.h @@ -26,7 +26,7 @@ enum { ERR_NOT_OWNER, /* Operation requires ownership */ /* Memory Protection Errors */ - ERR_STACK_CHECK, /* Stack overflow or corruption detected */ + ERR_STACK_CHECK, /* Stack overflow or corruption detected */ ERR_HEAP_CORRUPT, /* Heap corruption or invalid free detected */ /* IPC and Synchronization Errors */ diff --git a/include/sys/logger.h b/include/sys/logger.h new file mode 100644 index 0000000..eb0ecf7 --- /dev/null +++ b/include/sys/logger.h @@ -0,0 +1,60 @@ +#pragma once + +/* Deferred logging system for thread-safe printf in preemptive mode. + * + * Architecture: + * - printf/puts format into a buffer and enqueue the complete message + * - Logger task dequeues messages and outputs to UART + * - Minimal critical sections (only during enqueue/dequeue operations) + * - No long interrupt disable periods during UART output + * + * Benefits: + * - Low interrupt latency + * - ISRs remain responsive during logging + * - No nested critical section issues + * - Proper separation between formatting and output + */ + +#include + +/* Logger Configuration - Optimized for memory efficiency + * These values balance memory usage with logging capacity: + * - 8 entries handles typical burst logging scenarios + * - 128 bytes accommodates most debug messages + * Total buffer overhead: 8 × 128 = 1KB (down from 4KB) + */ +#define LOG_QSIZE 8 /* Number of log entries in ring buffer */ +#define LOG_ENTRY_SZ 128 /* Maximum length of single log message */ + +/* Logger Control */ + +/* Initialize the logger subsystem. + * Creates the log queue and spawns the logger task. + * Must be called during kernel initialization, after heap and task system init. + * + * Returns ERR_OK on success, ERR_FAIL on failure + */ +int32_t mo_logger_init(void); + +/* Enqueue a log message for deferred output. + * Non-blocking: if queue is full, message is dropped. + * Thread-safe: protected by short critical section. + * @msg : Null-terminated message string + * @length : Length of message (excluding null terminator) + * + * Returns ERR_OK if enqueued, ERR_BUSY if queue full + */ +int32_t mo_logger_enqueue(const char *msg, uint16_t length); + +/* Get the number of messages currently in the queue. + * Useful for monitoring queue depth and detecting overruns. + * + * Returns number of queued messages + */ +uint32_t mo_logger_queue_depth(void); + +/* Get the total number of dropped messages due to queue overflow. + * + * Returns total dropped message count since logger init + */ +uint32_t mo_logger_dropped_count(void); diff --git a/kernel/logger.c b/kernel/logger.c new file mode 100644 index 0000000..701a36f --- /dev/null +++ b/kernel/logger.c @@ -0,0 +1,151 @@ +/* Deferred logging: async I/O pattern for thread-safe printf. + * + * Design rationale: + * - Ring buffer + mutex + * - Logger task at IDLE priority: drains queue without blocking tasks + * - UART output outside lock: other tasks enqueue while we output + * - Graceful degradation: fallback to direct output on queue full + */ + +#include +#include +#include +#include + +#include "private/error.h" + +/* Ring buffer entry: fixed-size for O(1) enqueue/dequeue */ +typedef struct { + uint16_t length; + char data[LOG_ENTRY_SZ]; +} log_entry_t; + +/* Logger state: single global instance, no dynamic allocation */ +typedef struct { + log_entry_t queue[LOG_QSIZE]; + uint32_t head, tail, count; + uint32_t dropped; /* Diagnostic: tracks queue overflow events */ + mutex_t lock; /* Protects queue manipulation, not UART output */ + int32_t task_id; + bool initialized; +} logger_state_t; + +static logger_state_t logger; + +/* Logger task: IDLE priority ensures application tasks run first */ +static void logger_task(void) +{ + log_entry_t entry; + + while (1) { + bool have_message = false; + + /* Critical section: only queue manipulation, not UART I/O */ + mo_mutex_lock(&logger.lock); + if (logger.count > 0) { + memcpy(&entry, &logger.queue[logger.tail], sizeof(log_entry_t)); + logger.tail = (logger.tail + 1) % LOG_QSIZE; + logger.count--; + have_message = true; + } + mo_mutex_unlock(&logger.lock); + + if (have_message) { + /* Key design: UART output outside lock prevents blocking enqueuers. + * shorter UART write does not hold mutex - other tasks enqueue in + * parallel. + */ + for (uint16_t i = 0; i < entry.length; i++) + _putchar(entry.data[i]); + } else { + /* Block when idle: sleep 1 tick, scheduler wakes us next period */ + mo_task_delay(1); + } + } +} + +/* Call after heap + task system init, before enabling preemption */ +int32_t mo_logger_init(void) +{ + if (logger.initialized) + return ERR_OK; + + memset(&logger, 0, sizeof(logger_state_t)); + + if (mo_mutex_init(&logger.lock) != ERR_OK) + return ERR_FAIL; + + /* 512B stack: simple operations only (no printf/recursion/ISR use) */ + logger.task_id = mo_task_spawn(logger_task, 512); + if (logger.task_id < 0) { + mo_mutex_destroy(&logger.lock); + return ERR_FAIL; + } + + /* IDLE priority: runs only when no application tasks are ready */ + mo_task_priority(logger.task_id, TASK_PRIO_IDLE); + + logger.initialized = true; + return ERR_OK; +} + +/* Non-blocking enqueue: returns ERR_TASK_BUSY on overflow, never waits */ +int32_t mo_logger_enqueue(const char *msg, uint16_t length) +{ + if (!logger.initialized || !msg || length == 0) + return ERR_FAIL; + + /* Defensive check: stdio.c pre-filters, but validate anyway */ + if (length > LOG_ENTRY_SZ - 1) + length = LOG_ENTRY_SZ - 1; + + mo_mutex_lock(&logger.lock); + + /* Drop message on full queue: non-blocking design, caller falls back to + * direct I/O + */ + if (logger.count >= LOG_QSIZE) { + logger.dropped++; + mo_mutex_unlock(&logger.lock); + return ERR_TASK_BUSY; + } + + log_entry_t *entry = &logger.queue[logger.head]; + entry->length = length; + memcpy(entry->data, msg, length); + /* Safety: enables direct string ops on data[] */ + entry->data[length] = '\0'; + + logger.head = (logger.head + 1) % LOG_QSIZE; + logger.count++; + + mo_mutex_unlock(&logger.lock); + + return ERR_OK; +} + +/* Diagnostic: monitor queue depth to detect sustained overflow conditions */ +uint32_t mo_logger_queue_depth(void) +{ + if (!logger.initialized) + return 0; + + mo_mutex_lock(&logger.lock); + uint32_t depth = logger.count; + mo_mutex_unlock(&logger.lock); + + return depth; +} + +/* Diagnostic: total messages lost since init (non-resettable counter) */ +uint32_t mo_logger_dropped_count(void) +{ + if (!logger.initialized) + return 0; + + mo_mutex_lock(&logger.lock); + uint32_t dropped = logger.dropped; + mo_mutex_unlock(&logger.lock); + + return dropped; +} diff --git a/kernel/main.c b/kernel/main.c index efa46ff..b0f666e 100644 --- a/kernel/main.c +++ b/kernel/main.c @@ -1,5 +1,6 @@ #include #include +#include #include #include "private/error.h" @@ -23,6 +24,17 @@ int32_t main(void) printf("Heap initialized, %u bytes available\n", (unsigned int) (size_t) &_heap_size); + /* Initialize deferred logging system. + * Must be done after heap init but before app_main() to ensure + * application tasks can use thread-safe printf. + * Note: Early printf calls (above) use direct output fallback. + */ + if (mo_logger_init() != 0) { + printf("Warning: Logger initialization failed, using direct output\n"); + } else { + printf("Logger initialized\n"); + } + /* Call the application's main entry point to create initial tasks. */ kcb->preemptive = (bool) app_main(); printf("Scheduler mode: %s\n", diff --git a/lib/stdio.c b/lib/stdio.c index 7529eb7..65f0eba 100644 --- a/lib/stdio.c +++ b/lib/stdio.c @@ -3,10 +3,16 @@ * Default handlers do nothing (or return error codes) so the kernel can run * even if the board code forgets to install real console hooks. These hooks * allow a consistent I/O interface regardless of the underlying hardware. + * + * Thread-safe printing: + * Uses deferred logging system for thread-safe output in preemptive mode. + * Messages are enqueued and processed by a dedicated logger task. + * Falls back to direct output during early boot or if queue is full. */ #include #include +#include #include "private/stdio.h" @@ -287,6 +293,8 @@ int vsnprintf(char *str, size_t size, const char *fmt, va_list args) /* Formatted output to stdout. * Uses a fixed stack buffer - very long output will be truncated. + * Thread-safe: Uses deferred logging via logger task. + * Falls back to direct output during early boot or if queue is full. */ int32_t printf(const char *fmt, ...) { @@ -297,7 +305,13 @@ int32_t printf(const char *fmt, ...) int32_t len = vsnprintf(buf, sizeof(buf), fmt, args); va_end(args); - /* Output the formatted string to stdout */ + /* Try deferred logging only if message fits (avoids silent truncation). + * Long messages fall back to direct output for completeness. + */ + if (len <= LOG_ENTRY_SZ - 1 && mo_logger_enqueue(buf, len) == 0) + return len; /* Successfully enqueued */ + + /* Fallback to direct output (early boot, queue full, or too long) */ char *p = buf; while (*p) _putchar(*p++); @@ -320,12 +334,29 @@ int32_t snprintf(char *str, size_t size, const char *fmt, ...) return v; } -/* Writes a string to stdout, followed by a newline. */ +/* Writes a string to stdout, followed by a newline. + * Thread-safe: Uses deferred logging via logger task. + * Falls back to direct output during early boot or if queue is full. + */ int32_t puts(const char *str) { - while (*str) - _putchar(*str++); - _putchar('\n'); + char buf[256]; /* Buffer for string + newline */ + int len = 0; + + /* Copy string to buffer */ + while (*str && len < 254) + buf[len++] = *str++; + buf[len++] = '\n'; + buf[len] = '\0'; + + /* Try deferred logging only if message fits (avoids silent truncation) */ + if (len <= LOG_ENTRY_SZ - 1 && mo_logger_enqueue(buf, len) == 0) + return 0; /* Successfully enqueued */ + + /* Fallback to direct output (early boot, queue full, or too long) */ + char *p = buf; + while (*p) + _putchar(*p++); return 0; }