1.Implement memory-based logging for each worker thread. 2. Dump all memory-based log to a file when receiving SIGINT signal

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.

runtime/include/memlogging.h

@@ -0,0 +1,15 @@
+#pragma once
+#include <stdint.h>
+#include <stdio.h>
+
+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();

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);
+
+}

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 */

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);

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);

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");

runtime/src/memlogging.c

@@ -0,0 +1,125 @@
+#include <errno.h>
+#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);
+}
+

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, &current_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];

runtime/src/worker_thread.c

@@ -6,6 +6,7 @@
 #include <stdlib.h>
 
 #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) {