diff --git a/runtime/Makefile b/runtime/Makefile index a90e9af..f75bcfd 100644 --- a/runtime/Makefile +++ b/runtime/Makefile @@ -59,6 +59,8 @@ BINARY_NAME=sledgert # CFLAGS += -DLOG_PREEMPTION # CFLAGS += -DLOG_MODULE_LOADING # CFLAGS += -DOPT_AVOID_GLOBAL_QUEUE +# CFLAGS += -DLOG_RUNTIME_FILE_LOG + CFLAGS += -DLOG_RUNTIME_MEM_LOG # This dumps per module *.csv files containing the cycle a sandbox has been in RUNNING when each # page is allocated. This helps understand the relationship to memory allocation and execution time. diff --git a/runtime/include/memlogging.h b/runtime/include/memlogging.h new file mode 100644 index 0000000..8584620 --- /dev/null +++ b/runtime/include/memlogging.h @@ -0,0 +1,15 @@ +#pragma once +#include +#include + +struct mem_logging_obj { + uint32_t log_size; + char *logger; + uint32_t offset; + FILE* fout; +}; + +void mem_log_init(uint32_t log_size, char const* file); +void mem_log_init2(uint32_t log_size, FILE* file); +void mem_log(char const * fmt, ...); +void dump_log_to_file(); diff --git a/runtime/include/sandbox_functions.h b/runtime/include/sandbox_functions.h index 0ffa33c..ff53eb7 100644 --- a/runtime/include/sandbox_functions.h +++ b/runtime/include/sandbox_functions.h @@ -7,6 +7,7 @@ #include "client_socket.h" #include "panic.h" #include "sandbox_request.h" +#include "memlogging.h" /*************************** * Public API * @@ -158,13 +159,16 @@ sandbox_open_http(struct sandbox *sandbox) } /** - * Prints key performance metrics for a sandbox to runtime_sandbox_perf_log + * Prints key performance metrics for a sandbox to runtime_sandbox_perf_log in runtime * This is defined by an environment variable * @param sandbox */ static inline void sandbox_print_perf(struct sandbox *sandbox) { +#ifndef LOG_RUNTIME_FILE_LOG + return; +#endif /* If the log was not defined by an environment variable, early out */ if (runtime_sandbox_perf_log == NULL) return; @@ -187,3 +191,35 @@ sandbox_print_perf(struct sandbox *sandbox) sandbox->module->relative_deadline_us, total_time_us, queued_us, initializing_us, runnable_us, running_us, blocked_us, returned_us, sandbox->linear_memory_size); } + +/** + * Prints key performance metrics for a sandbox to memory in runtime + * @param sandbox + */ + +static inline void +sandbox_mem_print_perf(struct sandbox *sandbox) +{ +#ifndef LOG_RUNTIME_MEM_LOG + return; +#endif + uint32_t total_time_us = sandbox->total_time / runtime_processor_speed_MHz; + uint32_t queued_us = (sandbox->allocation_timestamp - sandbox->enqueue_timestamp) + / runtime_processor_speed_MHz; + uint32_t initializing_us = sandbox->initializing_duration / runtime_processor_speed_MHz; + uint32_t runnable_us = sandbox->runnable_duration / runtime_processor_speed_MHz; + 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; + + /* + * Assumption: A sandbox is never able to free pages. If linear memory management + * becomes more intelligent, then peak linear memory size needs to be tracked + * seperately from current linear memory size. + */ + mem_log("%lu,%s():%d,%s,%u,%u,%u,%u,%u,%u,%u,%u,%u\n", sandbox->id, + 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->linear_memory_size); + +} diff --git a/runtime/include/sandbox_set_as_complete.h b/runtime/include/sandbox_set_as_complete.h index 9a4891d..805e784 100644 --- a/runtime/include/sandbox_set_as_complete.h +++ b/runtime/include/sandbox_set_as_complete.h @@ -54,6 +54,7 @@ sandbox_set_as_complete(struct sandbox *sandbox, sandbox_state_t last_state) /* Terminal State Logging */ sandbox_print_perf(sandbox); + sandbox_mem_print_perf(sandbox); sandbox_summarize_page_allocations(sandbox); /* Do not touch sandbox state after adding to completion queue to avoid use-after-free bugs */ diff --git a/runtime/include/sandbox_set_as_error.h b/runtime/include/sandbox_set_as_error.h index 575864b..de77797 100644 --- a/runtime/include/sandbox_set_as_error.h +++ b/runtime/include/sandbox_set_as_error.h @@ -52,6 +52,7 @@ sandbox_set_as_error(struct sandbox *sandbox, sandbox_state_t last_state) uint64_t sandbox_id = sandbox->id; sandbox->state = SANDBOX_ERROR; sandbox_print_perf(sandbox); + sandbox_mem_print_perf(sandbox); sandbox_summarize_page_allocations(sandbox); sandbox_free_linear_memory(sandbox); admissions_control_subtract(sandbox->admissions_estimate); diff --git a/runtime/include/software_interrupt.h b/runtime/include/software_interrupt.h index 698d767..e7a2c34 100644 --- a/runtime/include/software_interrupt.h +++ b/runtime/include/software_interrupt.h @@ -35,7 +35,7 @@ software_interrupt_mask_signal(int signal) sigset_t set; int return_code; - assert(signal == SIGALRM || signal == SIGUSR1); + assert(signal == SIGALRM || signal == SIGUSR1 || signal == SIGINT); /* all threads created by the calling thread will have signal blocked */ sigemptyset(&set); sigaddset(&set, signal); @@ -59,7 +59,7 @@ software_interrupt_unmask_signal(int signal) sigset_t set; int return_code; - assert(signal == SIGALRM || signal == SIGUSR1); + assert(signal == SIGALRM || signal == SIGUSR1 || signal == SIGINT); /* all threads created by the calling thread will have signal unblocked */ sigemptyset(&set); sigaddset(&set, signal); diff --git a/runtime/src/main.c b/runtime/src/main.c index e2101ce..6cb8cf2 100644 --- a/runtime/src/main.c +++ b/runtime/src/main.c @@ -222,7 +222,7 @@ runtime_configure() char *runtime_sandbox_perf_log_path = getenv("SLEDGE_SANDBOX_PERF_LOG"); if (runtime_sandbox_perf_log_path != NULL) { printf("\tSandbox Performance Log: %s\n", runtime_sandbox_perf_log_path); - runtime_sandbox_perf_log = fopen(runtime_sandbox_perf_log_path, "w"); + runtime_sandbox_perf_log = fopen(runtime_sandbox_perf_log_path, "a+"); if (runtime_sandbox_perf_log == NULL) { perror("sandbox perf log"); } fprintf(runtime_sandbox_perf_log, "id,function,state,deadline,actual,queued,initializing,runnable," "running,blocked,returned,memory\n"); diff --git a/runtime/src/memlogging.c b/runtime/src/memlogging.c new file mode 100644 index 0000000..e27f7f2 --- /dev/null +++ b/runtime/src/memlogging.c @@ -0,0 +1,125 @@ +#include +#include "memlogging.h" +#include "panic.h" + +__thread struct mem_logging_obj log_obj; + +/** + * Initialize memory log. This should be called in each worker thread. + * Every worker thread writes log to its own memory. + * @param log_size the number of bytes of memory to allocate for logging + * @param file the FILE pointer to an opened file, each worker thread will + * dump the memory log to this file when sledge exits. The file is + * defined by an environment variable + */ +void +mem_log_init2(uint32_t log_size, FILE* file) +{ +#ifndef LOG_RUNTIME_MEM_LOG + return; +#endif + log_obj.log_size = log_size; + log_obj.logger = (char *)malloc(log_size); + if (!log_obj.logger) { + panic("failed to allocate memory for logging\n"); + } + + log_obj.offset = 0; + log_obj.fout = file; + if (!log_obj.fout) { + panic("failed to open log file:%s\n", strerror(errno)); + } + +} + +/** + * Initialize memory log. This should be called in each worker thread. + * Every worker thread writes log to its own memory. + * @param log_size the number of bytes of memory to allocate for logging + * @param file the file to dump the memory log when sledge exits + */ +void +mem_log_init(uint32_t log_size, char const* file) +{ +#ifndef LOG_RUNTIME_MEM_LOG + return; +#endif + log_obj.log_size = log_size; + log_obj.logger = (char *)malloc(log_size); + if (!log_obj.logger) { + panic("failed to allocate memory for logging\n"); + } + + log_obj.offset = 0; + log_obj.fout = fopen(file, "a+"); + if (!log_obj.fout) { + panic("failed to open log file:%s\n", strerror(errno)); + } + +} + +/** + * Prints log to memory + */ +void +mem_log(char const * fmt, ...) +{ +#ifndef LOG_RUNTIME_MEM_LOG + return; +#endif + assert(log_obj.logger); + assert(log_obj.fout); + + va_list va; + va_start(va, fmt); + int n = vsnprintf(log_obj.logger + log_obj.offset, log_obj.log_size - log_obj.offset, fmt, va); + va_end(va); + + if (n < 0) { + /* Based on the doc of vsnprintf, the write is failed if n is negative */ + panic("failed to write data to memory, return value:%d\n", n); + } else if (n >= log_obj.log_size - log_obj.offset) { + /* Memory is full, realloc memory */ + char* old_logger = log_obj.logger; + + while (n >=log_obj.log_size - log_obj.offset) { + log_obj.logger = (char *)realloc(log_obj.logger, log_obj.log_size * 2); + if (!log_obj.logger) { + log_obj.logger = old_logger; + dump_log_to_file(log_obj); + panic("failed to realloc memory for logging\n"); + } + + log_obj.log_size = log_obj.log_size * 2; + va_start(va, fmt); + n = vsnprintf(log_obj.logger + log_obj.offset, log_obj.log_size - log_obj.offset, fmt, va); + va_end(va); + } + log_obj.offset += n; + } else { + /* Write Success */ + log_obj.offset += n; + } +} + +/** + * Dump log from memory to file. This should be called when a worker thread receives SIGINT signal + */ + +void +dump_log_to_file() +{ +#ifndef LOG_RUNTIME_MEM_LOG + return; +#endif + assert(log_obj.logger); + assert(log_obj.fout); + + uint32_t write_bytes = 0; + while(write_bytes != log_obj.offset) { + int return_bytes = fprintf(log_obj.fout, "%s", log_obj.logger + write_bytes); + write_bytes += return_bytes; + } + fflush(log_obj.fout); +} + diff --git a/runtime/src/software_interrupt.c b/runtime/src/software_interrupt.c index 48d1f42..fd63847 100644 --- a/runtime/src/software_interrupt.c +++ b/runtime/src/software_interrupt.c @@ -20,6 +20,7 @@ #include "sandbox_types.h" #include "scheduler.h" #include "software_interrupt.h" +#include "memlogging.h" /******************* * Process Globals * @@ -100,6 +101,27 @@ sigalrm_propagate_workers(siginfo_t *signal_info) } } +/** + * A POSIX signal is delivered to only one thread. + * This function broadcasts the sigint signal to all other worker threads + */ +static inline void +sigint_propagate_workers(siginfo_t *signal_info) +{ + /* Signal was sent directly by the kernel, so forward to other threads */ + if (signal_info->si_code == SI_KERNEL) { + for (int i = 0; i < runtime_worker_threads_count; i++) { + if (pthread_self() == runtime_worker_threads[i]) continue; + + /* All threads should have been initialized */ + assert(runtime_worker_threads[i] != 0); + pthread_kill(runtime_worker_threads[i], SIGINT); + } + } else { + /* Signal forwarded from another thread. Just confirm it resulted from pthread_kill */ + assert(signal_info->si_code == SI_TKILL); + } +} /** * Validates that the thread running the signal handler is a known worker thread */ @@ -166,6 +188,13 @@ software_interrupt_handle_signals(int signal_type, siginfo_t *signal_info, void arch_mcontext_restore(&user_context->uc_mcontext, ¤t_sandbox->ctxt); goto done; } + case SIGINT: { + /* Only the thread that receives SIGINT from the kernel will broadcast SIGINT to other worker threads */ + sigint_propagate_workers(signal_info); + dump_log_to_file(); + /* terminate itself */ + pthread_exit(0); + } default: { switch (signal_info->si_code) { case SI_TKILL: @@ -229,7 +258,7 @@ software_interrupt_disarm_timer(void) /** * Initialize software Interrupts - * Register softint_handler to execute on SIGALRM and SIGUSR1 + * Register softint_handler to execute on SIGALRM, SIGINT, and SIGUSR1 */ void software_interrupt_initialize(void) @@ -244,9 +273,10 @@ software_interrupt_initialize(void) sigemptyset(&signal_action.sa_mask); sigaddset(&signal_action.sa_mask, SIGALRM); sigaddset(&signal_action.sa_mask, SIGUSR1); + sigaddset(&signal_action.sa_mask, SIGINT); - const int supported_signals[] = { SIGALRM, SIGUSR1 }; - const size_t supported_signals_len = 2; + const int supported_signals[] = { SIGALRM, SIGUSR1, SIGINT }; + const size_t supported_signals_len = 3; for (int i = 0; i < supported_signals_len; i++) { int signal = supported_signals[i]; diff --git a/runtime/src/worker_thread.c b/runtime/src/worker_thread.c index 168ad5b..cd1c48d 100644 --- a/runtime/src/worker_thread.c +++ b/runtime/src/worker_thread.c @@ -6,6 +6,7 @@ #include #include "current_sandbox.h" +#include "memlogging.h" #include "local_completion_queue.h" #include "local_runqueue.h" #include "local_runqueue_list.h" @@ -28,6 +29,7 @@ __thread int worker_thread_epoll_file_descriptor; /* Used to index into global arguments and deadlines arrays */ __thread int worker_thread_idx; +extern FILE *runtime_sandbox_perf_log; /*********************** * Worker Thread Logic * **********************/ @@ -52,6 +54,8 @@ worker_thread_main(void *argument) scheduler_runqueue_initialize(); + /* Initialize memory logging */ + mem_log_init2(1024*1024*1024, runtime_sandbox_perf_log); /* Initialize Completion Queue */ local_completion_queue_initialize(); @@ -65,6 +69,9 @@ worker_thread_main(void *argument) software_interrupt_unmask_signal(SIGUSR1); } + /* Unmask SIGINT signals */ + software_interrupt_unmask_signal(SIGINT); + /* Begin Worker Execution Loop */ struct sandbox *next_sandbox = NULL; while (true) {