From eca1546f7a3fe083001236c9ffc5343473d3c75b Mon Sep 17 00:00:00 2001 From: Sean McBride Date: Mon, 27 Jul 2020 21:00:11 -0400 Subject: [PATCH] chore: improved logging --- runtime/include/libuv_callbacks.h | 1 - runtime/include/module.h | 7 ++-- runtime/include/panic.h | 19 ++++----- runtime/include/sandbox.h | 8 ++-- runtime/include/sandbox_request.h | 3 +- runtime/include/software_interrupt.h | 1 + runtime/include/types.h | 12 +++--- runtime/src/local_runqueue_list.c | 3 -- runtime/src/local_runqueue_minheap.c | 4 +- runtime/src/sandbox.c | 60 +++++++++++++--------------- 10 files changed, 54 insertions(+), 64 deletions(-) diff --git a/runtime/include/libuv_callbacks.h b/runtime/include/libuv_callbacks.h index ce859d9..ad47a9e 100644 --- a/runtime/include/libuv_callbacks.h +++ b/runtime/include/libuv_callbacks.h @@ -2,7 +2,6 @@ #include #include -#include #include #include diff --git a/runtime/include/module.h b/runtime/include/module.h index 27774e5..56879f2 100644 --- a/runtime/include/module.h +++ b/runtime/include/module.h @@ -137,12 +137,11 @@ module_validate(struct module *module) assert(!software_interrupt_is_enabled()); if (!module) { - panic("%lu | module %p | module is unexpectedly NULL\n", pthread_self(), module); + panic("module %p | module is unexpectedly NULL\n", module); } else if (!module->dynamic_library_handle) { - panic("%lu | module %p | module->dynamic_library_handle is unexpectedly NULL\n", pthread_self(), - module); + panic("module %p | module->dynamic_library_handle is unexpectedly NULL\n", module); } else if (!module->main) { - panic("%lu | module %p | module->main is unexpectedly NULL\n", pthread_self(), module); + panic("module %p | module->main is unexpectedly NULL\n", module); } } diff --git a/runtime/include/panic.h b/runtime/include/panic.h index 4b28101..5b36c78 100644 --- a/runtime/include/panic.h +++ b/runtime/include/panic.h @@ -1,16 +1,13 @@ #pragma once #include +#include +#include #include -#include -#include -__attribute__((noreturn, format(printf, 1, 2))) static inline void -panic(const char *format, ...) -{ - va_list args; - va_start(args, format); - vfprintf(stderr, format, args); - va_end(args); - assert(0); -} +#define panic(fmt, ...) \ + { \ + fprintf(stderr, "C: %02d, T: 0x%lx, F: %s> PANIC! \n\t" fmt "\n", sched_getcpu(), pthread_self(), \ + __func__, ##__VA_ARGS__); \ + exit(EXIT_FAILURE); \ + } diff --git a/runtime/include/sandbox.h b/runtime/include/sandbox.h index 410198b..512366f 100644 --- a/runtime/include/sandbox.h +++ b/runtime/include/sandbox.h @@ -314,13 +314,13 @@ sandbox_print_perf(struct sandbox *sandbox) uint64_t running_us = sandbox->running_duration / runtime_processor_speed_MHz; uint64_t blocked_us = sandbox->blocked_duration / runtime_processor_speed_MHz; uint64_t returned_us = sandbox->returned_duration / runtime_processor_speed_MHz; - debuglog("%s():%d, state: %s, deadline: %u, actual: %lu, queued: %lu, initializing: %lu, runnable: %lu, " + debuglog("%lu, %s():%d, state: %s, deadline: %u, actual: %lu, queued: %lu, initializing: %lu, runnable: %lu, " "running: " "%lu, blocked: " "%lu, returned %lu\n", - sandbox->module->name, sandbox->module->port, sandbox_state_stringify(sandbox->state), - sandbox->module->relative_deadline_us, total_time_us, queued_us, initializing_us, runnable_us, - running_us, blocked_us, returned_us); + sandbox->request_arrival_timestamp, sandbox->module->name, sandbox->module->port, + sandbox_state_stringify(sandbox->state), sandbox->module->relative_deadline_us, total_time_us, + queued_us, initializing_us, runnable_us, running_us, blocked_us, returned_us); } void sandbox_set_as_initialized(struct sandbox *sandbox, struct sandbox_request *sandbox_request, diff --git a/runtime/include/sandbox_request.h b/runtime/include/sandbox_request.h index 26928e1..de6e557 100644 --- a/runtime/include/sandbox_request.h +++ b/runtime/include/sandbox_request.h @@ -43,6 +43,7 @@ sandbox_request_allocate(struct module *module, char *arguments, int socket_desc sandbox_request->absolute_deadline = request_arrival_timestamp + module->relative_deadline_us * runtime_processor_speed_MHz; - debuglog("%s:%d @ %p\n", sandbox_request->module->name, sandbox_request->module->port, sandbox_request); + debuglog("Allocating %lu of %s:%d\n", sandbox_request->request_arrival_timestamp, sandbox_request->module->name, + sandbox_request->module->port); return sandbox_request; } diff --git a/runtime/include/software_interrupt.h b/runtime/include/software_interrupt.h index c0f0c8f..ff02547 100644 --- a/runtime/include/software_interrupt.h +++ b/runtime/include/software_interrupt.h @@ -2,6 +2,7 @@ #include #include +#include #include #include #include diff --git a/runtime/include/types.h b/runtime/include/types.h index 81f5c3c..8de81e0 100644 --- a/runtime/include/types.h +++ b/runtime/include/types.h @@ -6,6 +6,7 @@ #include #include #include +#include #include #include #include @@ -89,12 +90,13 @@ typedef void (*mod_libc_fn_t)(int32_t, int32_t); */ #ifdef DEBUG #ifdef LOG_TO_FILE -#define debuglog(fmt, ...) \ - dprintf(runtime_log_file_descriptor, "CPU: %02d, Thread: %x> %s: " fmt, sched_getcpu(), pthread_self(), \ - __func__, ##__VA_ARGS__) +#define debuglog(fmt, ...) \ + dprintf(runtime_log_file_descriptor, "C: %02d, T: 0x%lx, F: %s> \n\t" fmt "\n", sched_getcpu(), \ + pthread_self(), __func__, ##__VA_ARGS__); #else /* !LOG_TO_FILE */ -#define debuglog(fmt, ...) \ - printf("CPU: %02d, Thread: 0x%lx> %s: " fmt, sched_getcpu(), pthread_self(), __func__, ##__VA_ARGS__) +#define debuglog(fmt, ...) \ + fprintf(stderr, "C: %02d, T: 0x%lx, F: %s> \n\t" fmt "\n", sched_getcpu(), pthread_self(), __func__, \ + ##__VA_ARGS__); #endif /* LOG_TO_FILE */ #else /* !DEBUG */ #define debuglog(fmt, ...) diff --git a/runtime/src/local_runqueue_list.c b/runtime/src/local_runqueue_list.c index 96ec61a..2f362ad 100644 --- a/runtime/src/local_runqueue_list.c +++ b/runtime/src/local_runqueue_list.c @@ -71,7 +71,6 @@ local_runqueue_list_get_next() assert(next_sandbox->state != SANDBOX_RETURNED); local_runqueue_add(next_sandbox); - debuglog("[%p: %s]\n", next_sandbox, next_sandbox->module->name); return next_sandbox; } @@ -84,8 +83,6 @@ void local_runqueue_list_append(struct sandbox *sandbox_to_append) { assert(ps_list_singleton_d(sandbox_to_append)); - debuglog("(%d,%lu) %s: run %p, %s\n", sched_getcpu(), pthread_self(), __func__, sandbox_to_append, - sandbox_to_append->module->name); ps_list_head_append_d(&local_runqueue_list, sandbox_to_append); } diff --git a/runtime/src/local_runqueue_minheap.c b/runtime/src/local_runqueue_minheap.c index 353ef71..fbba67b 100644 --- a/runtime/src/local_runqueue_minheap.c +++ b/runtime/src/local_runqueue_minheap.c @@ -55,8 +55,8 @@ local_runqueue_minheap_delete(struct sandbox *sandbox) assert(sandbox != NULL); int rc = priority_queue_delete(&local_runqueue_minheap, sandbox); if (rc == -1) { - panic("Err: Thread Local %lu tried to delete sandbox %lu from runqueue, but was not present\n", - pthread_self(), sandbox->request_arrival_timestamp); + panic("Tried to delete sandbox %lu from runqueue, but was not present\n", + sandbox->request_arrival_timestamp); } } diff --git a/runtime/src/sandbox.c b/runtime/src/sandbox.c index 1383512..f1f1fe4 100644 --- a/runtime/src/sandbox.c +++ b/runtime/src/sandbox.c @@ -192,9 +192,6 @@ sandbox_build_and_send_client_response(struct sandbox *sandbox) sandbox->total_time = end_time - sandbox->request_arrival_timestamp; uint64_t total_time_us = sandbox->total_time / runtime_processor_speed_MHz; - debuglog("%s():%d, %u, %lu\n", sandbox->module->name, sandbox->module->port, - sandbox->module->relative_deadline_us, total_time_us); - #ifndef USE_HTTP_UVIO int r = send(sandbox->client_socket_descriptor, sandbox->request_response_data, response_cursor, 0); if (r < 0) { @@ -387,6 +384,7 @@ sandbox_allocate_memory(struct module *module) } /* Populate Sandbox members */ + sandbox->state = SANDBOX_UNINITIALIZED; sandbox->linear_memory_start = (char *)addr + sandbox_size; sandbox->linear_memory_size = linear_memory_size; sandbox->linear_memory_max_size = linear_memory_max_size; @@ -427,8 +425,7 @@ err_stack_allocation_failed: } /** - * Transitions a sandbox to the SANDBOX_INITIALIZED state. Because this is the initial state of a new sandbox, we have - * to assume that sandbox->state is garbage. + * Transitions a sandbox to the SANDBOX_INITIALIZED state. * @param sandbox an uninitialized sandbox * @param sandbox_request the request we are initializing the sandbox from * @param allocation_timestamp timestamp of allocation @@ -448,7 +445,7 @@ sandbox_set_as_initialized(struct sandbox *sandbox, struct sandbox_request *sand assert(allocation_timestamp > 0); - debuglog("Thread %lu | Sandbox %lu | Uninitialized => Initialized\n", pthread_self(), allocation_timestamp); + debuglog("Sandbox %lu | Uninitialized => Initialized\n", sandbox->request_arrival_timestamp); sandbox->request_arrival_timestamp = sandbox_request->request_arrival_timestamp; sandbox->allocation_timestamp = allocation_timestamp; @@ -504,7 +501,7 @@ sandbox_set_as_runnable(struct sandbox *sandbox) uint64_t duration_of_last_state = now - sandbox->last_state_change_timestamp; sandbox_state_t last_state = sandbox->state; sandbox->state = SANDBOX_SET_AS_RUNNABLE; - debuglog("Thread %lu | Sandbox %lu | %s => Runnable\n", pthread_self(), sandbox->allocation_timestamp, + debuglog("Sandbox %lu | %s => Runnable\n", sandbox->request_arrival_timestamp, sandbox_state_stringify(last_state)); switch (last_state) { @@ -517,8 +514,8 @@ sandbox_set_as_runnable(struct sandbox *sandbox) break; } default: { - panic("Thread %lu | Sandbox %lu | Illegal transition from %s to Runnable\n", pthread_self(), - sandbox->allocation_timestamp, sandbox_state_stringify(last_state)); + panic("Sandbox %lu | Illegal transition from %s to Runnable\n", sandbox->request_arrival_timestamp, + sandbox_state_stringify(last_state)); } } @@ -549,7 +546,7 @@ sandbox_set_as_running(struct sandbox *sandbox) sandbox_state_t last_state = sandbox->state; sandbox->state = SANDBOX_SET_AS_RUNNING; - debuglog("Thread %lu | Sandbox %lu | %s => Running\n", pthread_self(), sandbox->allocation_timestamp, + debuglog("Sandbox %lu | %s => Running\n", sandbox->request_arrival_timestamp, sandbox_state_stringify(last_state)); switch (last_state) { @@ -562,8 +559,8 @@ sandbox_set_as_running(struct sandbox *sandbox) break; } default: { - panic("Thread %lu | Sandbox %lu | Illegal transition from %s to Running\n", pthread_self(), - sandbox->allocation_timestamp, sandbox_state_stringify(last_state)); + panic("Sandbox %lu | Illegal transition from %s to Running\n", sandbox->request_arrival_timestamp, + sandbox_state_stringify(last_state)); } } @@ -590,7 +587,7 @@ sandbox_set_as_preempted(struct sandbox *sandbox) uint64_t duration_of_last_state = now - sandbox->last_state_change_timestamp; sandbox_state_t last_state = sandbox->state; sandbox->state = SANDBOX_SET_AS_PREEMPTED; - debuglog("Thread %lu | Sandbox %lu | %s => Preempted\n", pthread_self(), sandbox->allocation_timestamp, + debuglog("Sandbox %lu | %s => Preempted\n", sandbox->request_arrival_timestamp, sandbox_state_stringify(last_state)); switch (last_state) { @@ -599,8 +596,8 @@ sandbox_set_as_preempted(struct sandbox *sandbox) break; } default: { - panic("Thread %lu | Sandbox %lu | Illegal transition from %s to Preempted\n", pthread_self(), - sandbox->allocation_timestamp, sandbox_state_stringify(last_state)); + panic("Sandbox %lu | Illegal transition from %s to Preempted\n", sandbox->request_arrival_timestamp, + sandbox_state_stringify(last_state)); } } @@ -624,8 +621,7 @@ sandbox_set_as_blocked(struct sandbox *sandbox) uint64_t duration_of_last_state = now - sandbox->last_state_change_timestamp; sandbox_state_t last_state = sandbox->state; sandbox->state = SANDBOX_SET_AS_BLOCKED; - debuglog("Thread %lu | Sandbox %lu | %s => Blocked\n", pthread_self(), sandbox->allocation_timestamp, - sandbox_state_stringify(last_state)); + debuglog("Sandbox %lu | %s => Blocked\n", sandbox->request_arrival_timestamp, sandbox_state_stringify(last_state)); switch (last_state) { case SANDBOX_RUNNING: { @@ -634,8 +630,8 @@ sandbox_set_as_blocked(struct sandbox *sandbox) break; } default: { - panic("Thread %lu | Sandbox %lu | Illegal transition from %s to Blocked\n", pthread_self(), - sandbox->allocation_timestamp, sandbox_state_stringify(last_state)); + panic("Sandbox %lu | Illegal transition from %s to Blocked\n", sandbox->request_arrival_timestamp, + sandbox_state_stringify(last_state)); } } @@ -660,8 +656,7 @@ sandbox_set_as_returned(struct sandbox *sandbox) uint64_t duration_of_last_state = now - sandbox->last_state_change_timestamp; sandbox_state_t last_state = sandbox->state; sandbox->state = SANDBOX_SET_AS_RETURNED; - debuglog("Thread %lu | Sandbox %lu | %s => Returned\n", pthread_self(), sandbox->allocation_timestamp, - sandbox_state_stringify(last_state)); + debuglog("Sandbox %lu | %s => Returned\n", sandbox->request_arrival_timestamp, sandbox_state_stringify(last_state)); switch (last_state) { case SANDBOX_RUNNING: { @@ -673,8 +668,8 @@ sandbox_set_as_returned(struct sandbox *sandbox) break; } default: { - panic("Thread %lu | Sandbox %lu | Illegal transition from %s to Returned\n", pthread_self(), - sandbox->allocation_timestamp, sandbox_state_stringify(last_state)); + panic("Sandbox %lu | Illegal transition from %s to Returned\n", sandbox->request_arrival_timestamp, + sandbox_state_stringify(last_state)); } } @@ -700,8 +695,7 @@ sandbox_set_as_error(struct sandbox *sandbox) uint64_t duration_of_last_state = now - sandbox->last_state_change_timestamp; sandbox_state_t last_state = sandbox->state; sandbox->state = SANDBOX_SET_AS_ERROR; - debuglog("Thread %lu | Sandbox %lu | %s => Error\n", pthread_self(), sandbox->allocation_timestamp, - sandbox_state_stringify(last_state)); + debuglog("Sandbox %lu | %s => Error\n", sandbox->request_arrival_timestamp, sandbox_state_stringify(last_state)); switch (last_state) { case SANDBOX_SET_AS_INITIALIZED: @@ -714,8 +708,8 @@ sandbox_set_as_error(struct sandbox *sandbox) break; } default: { - panic("Thread %lu | Sandbox %lu | Illegal transition from %s to Error\n", pthread_self(), - sandbox->allocation_timestamp, sandbox_state_stringify(last_state)); + panic("Sandbox %lu | Illegal transition from %s to Error\n", sandbox->request_arrival_timestamp, + sandbox_state_stringify(last_state)); } } @@ -742,7 +736,7 @@ sandbox_set_as_complete(struct sandbox *sandbox) uint64_t duration_of_last_state = now - sandbox->last_state_change_timestamp; sandbox_state_t last_state = sandbox->state; sandbox->state = SANDBOX_SET_AS_COMPLETE; - debuglog("Thread %lu | Sandbox %lu | %s => Complete\n", pthread_self(), sandbox->allocation_timestamp, + debuglog("Sandbox %lu | %s => Complete\n", sandbox->request_arrival_timestamp, sandbox_state_stringify(last_state)); switch (last_state) { @@ -752,8 +746,8 @@ sandbox_set_as_complete(struct sandbox *sandbox) break; } default: { - panic("Thread %lu | Sandbox %lu | Illegal transition from %s to Error\n", pthread_self(), - sandbox->allocation_timestamp, sandbox_state_stringify(last_state)); + panic("Sandbox %lu | Illegal transition from %s to Error\n", sandbox->request_arrival_timestamp, + sandbox_state_stringify(last_state)); } } @@ -857,7 +851,7 @@ sandbox_free(struct sandbox *sandbox) errno = 0; rc = munmap(stkaddr, stksz); if (rc == -1) { - fprintf(stderr, "Thread %lu | Failed to unmap stack %p\n", pthread_self(), sandbox); + debuglog("Failed to unmap stack of Sandbox %lu\n", sandbox->request_arrival_timestamp); goto err_free_stack_failed; }; @@ -871,7 +865,7 @@ sandbox_free(struct sandbox *sandbox) errno = 0; rc = munmap(sandbox, sandbox_address_space_size); if (rc == -1) { - fprintf(stderr, "Thread %lu | Failed to unmap sanbox %p\n", pthread_self(), sandbox); + debuglog("Failed to unmap Sandbox %lu\n", sandbox->request_arrival_timestamp); goto err_free_sandbox_failed; }; @@ -881,5 +875,5 @@ err_free_sandbox_failed: err_free_stack_failed: err: /* Errors freeing memory is a fatal error */ - panic("Thread %lu | Failed to free sandbox %p\n", pthread_self(), sandbox); + panic("Failed to free Sandbox %lu\n", sandbox->request_arrival_timestamp); }