From 3afe74ae78936a4256e0c9e9eefa6c2c0d260148 Mon Sep 17 00:00:00 2001 From: Sean McBride Date: Sun, 11 Oct 2020 20:02:20 -0400 Subject: [PATCH] feat: runtime configurable sandbox perf logging --- runtime/Makefile | 1 - runtime/include/runtime.h | 3 +++ runtime/include/sandbox.h | 13 +++++-------- runtime/src/main.c | 12 ++++++++++++ runtime/src/runtime.c | 4 ++++ runtime/src/sandbox.c | 8 ++------ 6 files changed, 26 insertions(+), 15 deletions(-) diff --git a/runtime/Makefile b/runtime/Makefile index eb00610..8311e2f 100644 --- a/runtime/Makefile +++ b/runtime/Makefile @@ -32,7 +32,6 @@ CFLAGS += -DDEBUG # 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 diff --git a/runtime/include/runtime.h b/runtime/include/runtime.h index 3e4d7a4..3f9391a 100644 --- a/runtime/include/runtime.h +++ b/runtime/include/runtime.h @@ -24,6 +24,9 @@ */ extern int runtime_epoll_file_descriptor; +/* Optional path to a file to log sandbox perf metrics */ +extern FILE *runtime_sandbox_perf_log; + /* * Assumption: All cores are the same speed * See runtime_get_processor_speed_MHz for further details diff --git a/runtime/include/sandbox.h b/runtime/include/sandbox.h index 8886f67..07261ae 100644 --- a/runtime/include/sandbox.h +++ b/runtime/include/sandbox.h @@ -327,14 +327,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, " - "running: %u, " - "blocked: %u, " - "returned: %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); + + fprintf(runtime_sandbox_perf_log, "%lu,%s():%d,%s,%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); } static inline void diff --git a/runtime/src/main.c b/runtime/src/main.c index 906bca2..e08db16 100644 --- a/runtime/src/main.c +++ b/runtime/src/main.c @@ -28,6 +28,9 @@ uint32_t runtime_first_worker_processor = 0; int runtime_worker_threads_argument[WORKER_THREAD_CORE_COUNT] = { 0 }; /* The worker sets its argument to -1 on error */ pthread_t runtime_worker_threads[WORKER_THREAD_CORE_COUNT]; + +FILE *runtime_sandbox_perf_log = NULL; + enum RUNTIME_SCHEDULER runtime_scheduler = RUNTIME_SCHEDULER_FIFO; int runtime_worker_core_count; @@ -205,6 +208,15 @@ runtime_configure() } else { panic("Invalid scheduler policy: %s. Must be {EDF|FIFO}\n", scheduler_policy); } + + /* Runtime Perf Log */ + char *runtime_sandbox_perf_log_path = getenv("SLEDGE_SANDBOX_PERF_LOG"); + if (runtime_sandbox_perf_log_path != NULL) { + runtime_sandbox_perf_log = fopen(runtime_sandbox_perf_log_path, "w"); + 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\n"); + } } int diff --git a/runtime/src/runtime.c b/runtime/src/runtime.c index 2cf0592..ee8d5b5 100644 --- a/runtime/src/runtime.c +++ b/runtime/src/runtime.c @@ -310,6 +310,10 @@ listener_thread_main(void *dummy) } /* while true */ panic("Listener thread unexpectedly broke loop\n"); + + + /* Cleanup Tasks... These won't run, but placed here to keep track */ + fclose(runtime_sandbox_perf_log); } /** diff --git a/runtime/src/sandbox.c b/runtime/src/sandbox.c index 8dad762..709a56c 100644 --- a/runtime/src/sandbox.c +++ b/runtime/src/sandbox.c @@ -821,9 +821,7 @@ 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 + if (runtime_sandbox_perf_log != NULL) sandbox_print_perf(sandbox); /* Assumption: Should never underflow */ assert(runtime_admitted >= sandbox->admissions_estimate); @@ -891,9 +889,7 @@ sandbox_set_as_complete(struct sandbox *sandbox, sandbox_state_t last_state) debuglog("Runtime Admitted: %lu / %lu\n", runtime_admitted, runtime_admissions_capacity); #endif -#ifdef LOG_SANDBOX_PERF - sandbox_print_perf(sandbox); -#endif + if (runtime_sandbox_perf_log != NULL) sandbox_print_perf(sandbox); /* Do not touch sandbox state after adding to the completion queue to avoid use-after-free bugs */ local_completion_queue_add(sandbox);