From 9bed646e3bdc470f4f3111a725c108b39f3225e7 Mon Sep 17 00:00:00 2001 From: Sean McBride Date: Tue, 11 Aug 2020 19:25:17 -0400 Subject: [PATCH] chore: enhance log granularity --- runtime/Makefile | 28 ++++++++++++++++++++++++--- runtime/include/sandbox.h | 5 +++-- runtime/include/sandbox_request.h | 2 ++ runtime/src/local_runqueue_minheap.c | 4 ++++ runtime/src/main.c | 9 +++++---- runtime/src/module.c | 5 ++++- runtime/src/runtime.c | 2 ++ runtime/src/sandbox.c | 29 +++++++++++++++++++++++++--- runtime/src/software_interrupt.c | 5 ++++- runtime/src/worker_thread.c | 8 ++++++++ 10 files changed, 83 insertions(+), 14 deletions(-) diff --git a/runtime/Makefile b/runtime/Makefile index 0bb79a1..2e21468 100644 --- a/runtime/Makefile +++ b/runtime/Makefile @@ -14,10 +14,32 @@ NCORES = ${TOTAL_CORES} # Options: {USE_MEM_GENERIC, USE_MEM_VM} USE_MEM = USE_MEM_VM -# Flags +# Debugging Flags + +# Strips out calls to assert() +# CFLAGS += -DNDEBUG + +# Turns on debuglog and other assorted printfs in third party libs +CFLAGS += -DDEBUG + +# Redirects debuglogs to /runtime/bin/awesome.log +#FIXME This log should be changed to sledge.log (and likely to a user defined path) +# CFLAGS += -DLOG_TO_FILE + +# Various Informational Logs for Debugging +# CFLAGS += -DLOG_STATE_CHANGES +# CFLAGS += -DLOG_LOCK_OVERHEAD +# CFLAGS += -DLOG_CONTEXT_SWITCHES +# CFLAGS += -DLOG_ADMISSIONS_CONTROL +# CFLAGS += -DLOG_SANDBOX_PERF +# CFLAGS += -DLOG_REQUEST_ALLOCATION +# CFLAGS += -DLOG_PREEMPTION +# CFLAGS += -DLOG_MODULE_LOADING + +# System Configuraiton Flags + +# Sets a flag equal to the processor architecture CFLAGS += -D${ARCH} -#CFLAGS += -DDEBUG -#CFLAGS += -DLOG_TO_FILE CFLAGS += -DNCORES=${NCORES} CFLAGS += -DPAGE_SIZE=$(PAGE_SIZE) #CFLAGS += -DPREEMPT_DISABLE diff --git a/runtime/include/sandbox.h b/runtime/include/sandbox.h index 71743ad..94f3aea 100644 --- a/runtime/include/sandbox.h +++ b/runtime/include/sandbox.h @@ -325,10 +325,11 @@ sandbox_print_perf(struct sandbox *sandbox) uint32_t running_us = sandbox->running_duration / runtime_processor_speed_MHz; uint32_t blocked_us = sandbox->blocked_duration / runtime_processor_speed_MHz; uint32_t returned_us = sandbox->returned_duration / runtime_processor_speed_MHz; - debuglog("%lu, %s():%d, state: %s, deadline: %u, actual: %u, queued: %u, initializing: %u, runnable: %u, " + debuglog("%lu, %s():%d, state: %s, deadline: %u, actual: %u, queued: %u, initializing: %u, " + "runnable: %u, " "running: %u, " "blocked: %u, " - "returned %u\n", + "returned: %u\n", 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); diff --git a/runtime/include/sandbox_request.h b/runtime/include/sandbox_request.h index b0e7a0f..46f779c 100644 --- a/runtime/include/sandbox_request.h +++ b/runtime/include/sandbox_request.h @@ -48,7 +48,9 @@ sandbox_request_allocate(struct module *module, char *arguments, int socket_desc sandbox_request->absolute_deadline = request_arrival_timestamp + module->relative_deadline; sandbox_request->admissions_estimate = admissions_estimate; +#ifdef LOG_REQUEST_ALLOCATION debuglog("Allocating %lu of %s:%d\n", sandbox_request->request_arrival_timestamp, sandbox_request->module->name, sandbox_request->module->port); +#endif return sandbox_request; } diff --git a/runtime/src/local_runqueue_minheap.c b/runtime/src/local_runqueue_minheap.c index 3187e9e..364bf11 100644 --- a/runtime/src/local_runqueue_minheap.c +++ b/runtime/src/local_runqueue_minheap.c @@ -137,15 +137,19 @@ 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) { +#ifdef LOG_PREEMPTION debuglog("Sandbox %lu has deadline of %lu. Trying to preempt for request with %lu\n", current_sandbox->request_arrival_timestamp, local_deadline, global_deadline); +#endif 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; +#ifdef LOG_PREEMPTION debuglog("Preempted %lu for %lu\n", local_deadline, sandbox_request->absolute_deadline); +#endif /* Allocate the request */ struct sandbox *next_sandbox = sandbox_allocate(sandbox_request); diff --git a/runtime/src/main.c b/runtime/src/main.c index 79d4dcc..312b26a 100644 --- a/runtime/src/main.c +++ b/runtime/src/main.c @@ -87,9 +87,9 @@ runtime_allocate_available_cores() assert(runtime_worker_threads_count == WORKER_THREAD_CORE_COUNT); - printf("Number of cores %u, sandboxing cores %u (start: %u) and module reqs %u\n", - runtime_total_online_processors, runtime_worker_threads_count, runtime_first_worker_processor, - LISTENER_THREAD_CORE_ID); + debuglog("Number of cores %u, sandboxing cores %u (start: %u) and module reqs %u\n", + runtime_total_online_processors, runtime_worker_threads_count, runtime_first_worker_processor, + LISTENER_THREAD_CORE_ID); } /** @@ -210,8 +210,9 @@ main(int argc, char **argv) runtime_set_resource_limits_to_max(); runtime_allocate_available_cores(); runtime_initialize(); - +#ifdef LOG_MODULE_LOADING debuglog("Parsing modules file [%s]\n", argv[1]); +#endif if (module_new_from_json(argv[1])) panic("failed to parse modules file[%s]\n", argv[1]); debuglog("Starting listener thread\n"); diff --git a/runtime/src/module.c b/runtime/src/module.c index adc0a44..0eb7178 100644 --- a/runtime/src/module.c +++ b/runtime/src/module.c @@ -261,7 +261,9 @@ module_new_from_json(char *file_name) /* Read the file into the buffer and check that the buffer size equals the file size */ errno = 0; int total_chars_read = fread(file_buffer, sizeof(char), stat_buffer.st_size, module_file); +#ifdef LOG_MODULE_LOADING debuglog("size read: %d content: %s\n", total_chars_read, file_buffer); +#endif if (total_chars_read != stat_buffer.st_size) { fprintf(stderr, "Attempt to read %s into buffer failed: %s\n", file_name, strerror(errno)); goto fread_err; @@ -417,8 +419,9 @@ module_new_from_json(char *file_name) } if (module_count == 0) fprintf(stderr, "%s contained no active modules\n", file_name); +#ifdef LOG_MODULE_LOADING debuglog("Loaded %d module%s!\n", module_count, module_count > 1 ? "s" : ""); - +#endif free(file_buffer); return_code = 0; diff --git a/runtime/src/runtime.c b/runtime/src/runtime.c index 90fc3c9..c0af303 100644 --- a/runtime/src/runtime.c +++ b/runtime/src/runtime.c @@ -124,7 +124,9 @@ listener_thread_main(void *dummy) /* Add to work accepted by the runtime */ runtime_admitted += admissions_estimate; +#ifdef LOG_ADMISSIONS_CONTROL debuglog("Runtime Admitted: %f / %u\n", runtime_admitted, runtime_worker_threads_count); +#endif } } } diff --git a/runtime/src/sandbox.c b/runtime/src/sandbox.c index e599d05..77ca29f 100644 --- a/runtime/src/sandbox.c +++ b/runtime/src/sandbox.c @@ -453,9 +453,9 @@ sandbox_set_as_initialized(struct sandbox *sandbox, struct sandbox_request *sand assert(sandbox_request->socket_descriptor > 0); assert(allocation_timestamp > 0); - +#ifdef LOG_STATE_CHANGES debuglog("Sandbox %lu | Uninitialized => Initialized\n", sandbox_request->request_arrival_timestamp); - +#endif sandbox->admissions_estimate = sandbox_request->admissions_estimate; sandbox->request_arrival_timestamp = sandbox_request->request_arrival_timestamp; @@ -503,8 +503,11 @@ sandbox_set_as_runnable(struct sandbox *sandbox, sandbox_state_t last_state) uint32_t duration_of_last_state = now - sandbox->last_state_change_timestamp; sandbox->state = SANDBOX_SET_AS_RUNNABLE; + +#ifdef LOG_STATE_CHANGES debuglog("Sandbox %lu | %s => Runnable\n", sandbox->request_arrival_timestamp, sandbox_state_stringify(last_state)); +#endif switch (last_state) { case SANDBOX_INITIALIZED: { @@ -549,8 +552,10 @@ sandbox_set_as_running(struct sandbox *sandbox, sandbox_state_t last_state) uint32_t duration_of_last_state = now - sandbox->last_state_change_timestamp; sandbox->state = SANDBOX_SET_AS_RUNNING; +#ifdef LOG_STATE_CHANGES debuglog("Sandbox %lu | %s => Running\n", sandbox->request_arrival_timestamp, sandbox_state_stringify(last_state)); +#endif switch (last_state) { case SANDBOX_RUNNABLE: { @@ -592,8 +597,10 @@ sandbox_set_as_preempted(struct sandbox *sandbox, sandbox_state_t last_state) uint32_t duration_of_last_state = now - sandbox->last_state_change_timestamp; sandbox->state = SANDBOX_SET_AS_PREEMPTED; +#ifdef LOG_STATE_CHANGES debuglog("Sandbox %lu | %s => Preempted\n", sandbox->request_arrival_timestamp, sandbox_state_stringify(last_state)); +#endif switch (last_state) { case SANDBOX_RUNNING: { @@ -628,8 +635,10 @@ sandbox_set_as_blocked(struct sandbox *sandbox, sandbox_state_t last_state) uint32_t duration_of_last_state = now - sandbox->last_state_change_timestamp; sandbox->state = SANDBOX_SET_AS_BLOCKED; +#ifdef LOG_STATE_CHANGES debuglog("Sandbox %lu | %s => Blocked\n", sandbox->request_arrival_timestamp, sandbox_state_stringify(last_state)); +#endif switch (last_state) { case SANDBOX_RUNNING: { @@ -666,8 +675,10 @@ sandbox_set_as_returned(struct sandbox *sandbox, sandbox_state_t last_state) uint32_t duration_of_last_state = now - sandbox->last_state_change_timestamp; sandbox->state = SANDBOX_SET_AS_RETURNED; +#ifdef LOG_STATE_CHANGES debuglog("Sandbox %lu | %s => Returned\n", sandbox->request_arrival_timestamp, sandbox_state_stringify(last_state)); +#endif switch (last_state) { case SANDBOX_RUNNING: { @@ -709,8 +720,10 @@ sandbox_set_as_error(struct sandbox *sandbox, sandbox_state_t last_state) uint32_t duration_of_last_state = now - sandbox->last_state_change_timestamp; sandbox->state = SANDBOX_SET_AS_ERROR; +#ifdef LOG_STATE_CHANGES debuglog("Sandbox %lu | %s => Error\n", sandbox->request_arrival_timestamp, sandbox_state_stringify(last_state)); +#endif switch (last_state) { case SANDBOX_SET_AS_INITIALIZED: @@ -733,12 +746,16 @@ sandbox_set_as_error(struct sandbox *sandbox, sandbox_state_t last_state) sandbox->last_state_change_timestamp = now; sandbox->state = SANDBOX_ERROR; +#ifdef LOG_SANDBOX_PERF sandbox_print_perf(sandbox); +#endif runtime_admitted -= sandbox->admissions_estimate; assert(runtime_admitted >= 0); - debuglog("Runtime Utilization: %f%%\n", runtime_admitted / runtime_worker_threads_count * 100); +#ifdef LOG_ADMISSIONS_CONTROL + debuglog("Runtime Admitted: %f / %u\n", runtime_admitted, runtime_worker_threads_count); +#endif /* Do not touch sandbox state after adding to the completion queue to avoid use-after-free bugs */ local_completion_queue_add(sandbox); @@ -759,8 +776,10 @@ sandbox_set_as_complete(struct sandbox *sandbox, sandbox_state_t last_state) uint32_t duration_of_last_state = now - sandbox->last_state_change_timestamp; sandbox->state = SANDBOX_SET_AS_COMPLETE; +#ifdef LOG_STATE_CHANGES debuglog("Sandbox %lu | %s => Complete\n", sandbox->request_arrival_timestamp, sandbox_state_stringify(last_state)); +#endif switch (last_state) { case SANDBOX_RETURNED: { @@ -785,9 +804,13 @@ sandbox_set_as_complete(struct sandbox *sandbox, sandbox_state_t last_state) runtime_admitted -= sandbox->admissions_estimate; +#ifdef LOG_ADMISSIONS_CONTROL debuglog("Runtime Admitted: %f / %u\n", runtime_admitted, runtime_worker_threads_count); +#endif +#ifdef LOG_SANDBOX_PERF sandbox_print_perf(sandbox); +#endif /* Do not touch sandbox state after adding to the completion queue to avoid use-after-free bugs */ local_completion_queue_add(sandbox); diff --git a/runtime/src/software_interrupt.c b/runtime/src/software_interrupt.c index 6156c8a..f987814 100644 --- a/runtime/src/software_interrupt.c +++ b/runtime/src/software_interrupt.c @@ -126,7 +126,10 @@ sigusr1_handler(siginfo_t *signal_info, ucontext_t *user_context, struct sandbox assert(current_sandbox->ctxt.variant == ARCH_CONTEXT_VARIANT_SLOW); software_interrupt_SIGUSR_count++; - debuglog("usr1:%d\n", software_interrupt_SIGUSR_count); + +#ifdef LOG_PREEMPTION + debuglog("Total SIGUSR1 Received: %d\n", software_interrupt_SIGUSR_count); +#endif arch_mcontext_restore(&user_context->uc_mcontext, ¤t_sandbox->ctxt); diff --git a/runtime/src/worker_thread.c b/runtime/src/worker_thread.c index baa5601..844cb50 100644 --- a/runtime/src/worker_thread.c +++ b/runtime/src/worker_thread.c @@ -47,10 +47,12 @@ static inline void worker_thread_dump_lock_overhead() { #ifdef DEBUG +#ifdef LOG_LOCK_OVERHEAD uint64_t worker_duration = __getcycles() - worker_thread_start_timestamp; debuglog("Locks consumed %lu / %lu cycles, or %f%%\n", worker_thread_lock_duration, worker_duration, (double)worker_thread_lock_duration / worker_duration * 100); #endif +#endif } /** @@ -100,9 +102,11 @@ worker_thread_switch_to_sandbox(struct sandbox *next_sandbox) sandbox_set_as_running(next_sandbox, next_sandbox->state); +#ifdef LOG_CONTEXT_SWITCHES debuglog("Base Context (%s) > Sandbox %lu (%s)\n", arch_context_variant_print(worker_thread_base_context.variant), next_sandbox->request_arrival_timestamp, arch_context_variant_print(next_context->variant)); +#endif arch_context_switch(NULL, next_context); } else { @@ -115,8 +119,10 @@ worker_thread_switch_to_sandbox(struct sandbox *next_sandbox) struct arch_context *current_context = ¤t_sandbox->ctxt; +#ifdef LOG_CONTEXT_SWITCHES debuglog("Sandbox %lu > Sandbox %lu\n", current_sandbox->request_arrival_timestamp, next_sandbox->request_arrival_timestamp); +#endif /* Switch to the associated context. */ arch_context_switch(current_context, next_context); @@ -143,9 +149,11 @@ worker_thread_switch_to_base_context() current_sandbox_set(NULL); +#ifdef LOG_CONTEXT_SWITCHES debuglog("Sandbox %lu (%s) > Base Context (%s)\n", current_sandbox->request_arrival_timestamp, arch_context_variant_print(current_sandbox->ctxt.variant), arch_context_variant_print(worker_thread_base_context.variant)); +#endif arch_context_switch(¤t_sandbox->ctxt, &worker_thread_base_context);