feat: runtime configurable sandbox perf logging

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

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

runtime/include/sandbox.h

@@ -327,12 +327,9 @@ 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, "
+	fprintf(runtime_sandbox_perf_log, "%lu,%s():%d,%s,%u,%u,%u,%u,%u,%u,%u,%u\n", sandbox->id,
-	         "running: %u, "
+	        sandbox->module->name, sandbox->module->port, sandbox_state_stringify(sandbox->state),
-	         "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);
 }

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

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);
 }
 
 /**

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
+	if (runtime_sandbox_perf_log != NULL) sandbox_print_perf(sandbox);
-	sandbox_print_perf(sandbox);
-#endif
 
 	/* 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
+	if (runtime_sandbox_perf_log != NULL) sandbox_print_perf(sandbox);
-	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);