From b979809c127a4d13d81a2d80d1d8cce511b77650 Mon Sep 17 00:00:00 2001 From: Sean McBride Date: Wed, 15 Jul 2020 17:24:37 -0400 Subject: [PATCH] chore: fix debuglog usage --- runtime/Makefile | 2 +- runtime/include/arch/x86_64/context.h | 6 ++++++ runtime/include/sandbox_request.h | 2 +- runtime/include/types.h | 9 +++++---- runtime/src/arch_context.c | 1 + runtime/src/local_runqueue_list.c | 3 ++- runtime/src/local_runqueue_minheap.c | 7 +++---- runtime/src/sandbox.c | 7 +++---- runtime/src/software_interrupt.c | 1 - runtime/src/worker_thread.c | 18 +++++++++--------- 10 files changed, 31 insertions(+), 25 deletions(-) diff --git a/runtime/Makefile b/runtime/Makefile index bf961e0..f9710ed 100644 --- a/runtime/Makefile +++ b/runtime/Makefile @@ -13,7 +13,7 @@ USE_MEM = USE_MEM_VM CFLAGS = ${OPTFLAGS} -D${USE_MEM} -I${INC} -pthread CFLAGS += -D${ARCH} CFILES += ${RTDIR}/arch/${ARCH}/*.c -#CFLAGS += -DDEBUG +CFLAGS += -DDEBUG CFLAGS += -D_GNU_SOURCE #CFLAGS += -DLOG_TO_FILE #CFLAGS += -DUSE_HTTP_UVIO #-DUSE_HTTP_SYNC diff --git a/runtime/include/arch/x86_64/context.h b/runtime/include/arch/x86_64/context.h index 6ce1759..fa8f50f 100644 --- a/runtime/include/arch/x86_64/context.h +++ b/runtime/include/arch/x86_64/context.h @@ -1,6 +1,7 @@ #pragma once #include "arch/common.h" +#include "types.h" #define ARCH_SIG_JMP_OFF 8 @@ -55,6 +56,11 @@ arch_context_switch(struct arch_context *current, struct arch_context *next) /* Assumption: Software Interrupts are disabled by caller */ assert(software_interrupt_is_disabled); + if (next->variant == ARCH_CONTEXT_QUICK && (next->regs[UREG_RIP] == 0 || next->regs[UREG_RSP] == 0)) { + debuglog("Next Context was Quick Variant, but data was invalid."); + assert(0); + } + /* if both current and next are NULL, there is no state change */ assert(current != NULL || next != NULL); diff --git a/runtime/include/sandbox_request.h b/runtime/include/sandbox_request.h index 6f22f17..26928e1 100644 --- a/runtime/include/sandbox_request.h +++ b/runtime/include/sandbox_request.h @@ -43,6 +43,6 @@ 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("[%p: %s]\n", sandbox_request, sandbox_request->module->name); + debuglog("%s:%d @ %p\n", sandbox_request->module->name, sandbox_request->module->port, sandbox_request); return sandbox_request; } diff --git a/runtime/include/types.h b/runtime/include/types.h index 6f250e5..6423798 100644 --- a/runtime/include/types.h +++ b/runtime/include/types.h @@ -89,11 +89,12 @@ typedef void (*mod_libc_fn_t)(int32_t, int32_t); */ #ifdef DEBUG #ifdef LOG_TO_FILE -#define debuglog(fmt, ...) \ - dprintf(runtime_log_file_descriptor, "(%d,%lu) %s: " fmt, sched_getcpu(), pthread_self(), __func__, \ - ##__VA_ARGS__) +#define debuglog(fmt, ...) \ + dprintf(runtime_log_file_descriptor, "CPU: %02d, Thread: %x> %s: " fmt, sched_getcpu(), pthread_self(), \ + __func__, ##__VA_ARGS__) #else /* !LOG_TO_FILE */ -#define debuglog(fmt, ...) printf("(%d,%lu) %s: " fmt, sched_getcpu(), pthread_self(), __func__, ##__VA_ARGS__) +#define debuglog(fmt, ...) \ + printf("CPU: %02d, Thread: 0x%lx> %s: " fmt, sched_getcpu(), pthread_self(), __func__, ##__VA_ARGS__) #endif /* LOG_TO_FILE */ #else /* !DEBUG */ #define debuglog(fmt, ...) diff --git a/runtime/src/arch_context.c b/runtime/src/arch_context.c index a1851a9..c0eb746 100644 --- a/runtime/src/arch_context.c +++ b/runtime/src/arch_context.c @@ -11,6 +11,7 @@ */ void __attribute__((noinline)) __attribute__((noreturn)) arch_context_mcontext_restore(void) { + debuglog("Sending SIGUSR1"); pthread_kill(pthread_self(), SIGUSR1); assert(false); } diff --git a/runtime/src/local_runqueue_list.c b/runtime/src/local_runqueue_list.c index 4759c4f..96ec61a 100644 --- a/runtime/src/local_runqueue_list.c +++ b/runtime/src/local_runqueue_list.c @@ -84,7 +84,8 @@ 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__, s, s->module->name); + 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 05d3639..31393bc 100644 --- a/runtime/src/local_runqueue_minheap.c +++ b/runtime/src/local_runqueue_minheap.c @@ -142,16 +142,15 @@ local_runqueue_minheap_preempt(ucontext_t *user_context) /* If we're able to get a sandbox request with a tighter deadline, preempt the current context and run it */ struct sandbox_request *sandbox_request; if (global_deadline < local_deadline) { - debuglog("Thread %lu | Sandbox %lu | Had deadline of %lu. Trying to preempt for request with %lu\n", - pthread_self(), current_sandbox->allocation_timestamp, local_deadline, global_deadline); + debuglog("Sandbox %lu has deadline of %lu. Trying to preempt for request with %lu\n", + current_sandbox->request_arrival_timestamp, local_deadline, global_deadline); int return_code = global_request_scheduler_remove(&sandbox_request); /* If we were unable to get a sandbox_request, exit */ if (return_code != 0) goto done; - debuglog("Thread %lu Preempted %lu for %lu\n", pthread_self(), local_deadline, - sandbox_request->absolute_deadline); + debuglog("Preempted %lu for %lu\n", local_deadline, sandbox_request->absolute_deadline); /* Allocate the request */ struct sandbox *next_sandbox = sandbox_allocate(sandbox_request); diff --git a/runtime/src/sandbox.c b/runtime/src/sandbox.c index ee988a1..dd5d41d 100644 --- a/runtime/src/sandbox.c +++ b/runtime/src/sandbox.c @@ -66,7 +66,7 @@ sandbox_parse_http_request(struct sandbox *sandbox, size_t length) /** * Receive and Parse the Request for the current sandbox - * @return 1 on success, 0 if no context, < 0 on failure. + * @return 1 on success, < 0 on failure. */ static inline int sandbox_receive_and_parse_client_request(struct sandbox *sandbox) @@ -78,9 +78,8 @@ sandbox_receive_and_parse_client_request(struct sandbox *sandbox) int r = 0; r = recv(sandbox->client_socket_descriptor, (sandbox->request_response_data), sandbox->module->max_request_size, 0); - if (r <= 0) { - if (r < 0) perror("Error reading request data from client socket"); - if (r == 0) perror("Client unexpectedly returned zero bytes"); + if (r < 0) { + perror("Error reading request data from client socket"); return r; } while (r > 0) { diff --git a/runtime/src/software_interrupt.c b/runtime/src/software_interrupt.c index 8fb6dd6..3eeac2a 100644 --- a/runtime/src/software_interrupt.c +++ b/runtime/src/software_interrupt.c @@ -81,7 +81,6 @@ software_interrupt_handle_signals(int signal_type, siginfo_t *signal_info, void assert(signal_info->si_code == SI_TKILL); } - debuglog("alrm:%d\n", software_interrupt_SIGALRM_count); software_interrupt_SIGALRM_count++; /* NOOP if software interrupts not enabled */ diff --git a/runtime/src/worker_thread.c b/runtime/src/worker_thread.c index 3d71ba5..ca99554 100644 --- a/runtime/src/worker_thread.c +++ b/runtime/src/worker_thread.c @@ -60,8 +60,8 @@ worker_thread_switch_to_sandbox(struct sandbox *next_sandbox) /* Switching from "Base Context" */ current_sandbox_set(next_sandbox); - debuglog("Thread %lu | Switching from Base Context to Sandbox %lu\n", pthread_self(), - next_sandbox->allocation_timestamp); + debuglog("Base Context > Sandbox %lu (%d variant)\n", next_sandbox->request_arrival_timestamp, + next_context->variant); arch_context_switch(NULL, next_context); @@ -76,8 +76,8 @@ worker_thread_switch_to_sandbox(struct sandbox *next_sandbox) current_sandbox_set(next_sandbox); - debuglog("Thread %lu | Switching from Sandbox %lu to Sandbox %lu\n", pthread_self(), - current_sandbox->allocation_timestamp, next_sandbox->allocation_timestamp); + debuglog("Sandbox %lu > Sandbox %lu\n", current_sandbox->request_arrival_timestamp, + next_sandbox->request_arrival_timestamp); /* Switch to the associated context. */ arch_context_switch(current_context, next_context); @@ -93,7 +93,7 @@ worker_thread_switch_to_sandbox(struct sandbox *next_sandbox) static inline void worker_thread_switch_to_base_context() { - software_interrupt_disable(); + assert(!software_interrupt_is_enabled()); assert(worker_thread_is_switching_context == false); worker_thread_is_switching_context = true; @@ -105,8 +105,7 @@ worker_thread_switch_to_base_context() current_sandbox_set(NULL); - debuglog("Thread %lu | Switching from Sandbox %lu to Base Context\n", pthread_self(), - current_sandbox->allocation_timestamp); + debuglog("Sandbox %lu > Base Context\n", current_sandbox->request_arrival_timestamp); arch_context_switch(¤t_sandbox->ctxt, &worker_thread_base_context); @@ -155,8 +154,8 @@ worker_thread_block_current_sandbox(void) /* Switch to the next sandbox */ struct sandbox *next_sandbox = local_runqueue_get_next(); - debuglog("[%p: %next_sandbox, %p: %next_sandbox]\n", current_sandbox, current_sandbox->module->name, - next_sandbox, next_sandbox ? next_sandbox->module->name : ""); + debuglog("[%p: %p, %p: %p]\n", current_sandbox, current_sandbox->module->name, next_sandbox, + next_sandbox ? next_sandbox->module->name : ""); /* If able to get one, switch to it. Otherwise, return to base context */ if (next_sandbox == NULL) { @@ -273,6 +272,7 @@ __attribute__((noreturn)) void worker_thread_on_sandbox_exit(struct sandbox *exiting_sandbox) { assert(exiting_sandbox); + debuglog("Exiting %lu\n", exiting_sandbox->request_arrival_timestamp); /* Because the stack is still in use, only unmap linear memory and defer free resources until "main function execution" */