add more debug log

runtime/include/perf_window.h

@@ -184,12 +184,13 @@ perf_window_print(struct perf_window *self)
         float nighty_p = self->by_duration[PERF_WINDOW_BUFFER_SIZE * 90 / 100].execution_time/1000.0;	
         float nighty_night_p = self->by_duration[PERF_WINDOW_BUFFER_SIZE * 99 / 100].execution_time/1000.0;	
 
-	mem_log("module %s perf window:\n", self->name);
+	/*mem_log("module %s perf window:\n", self->name);
 	for (int i = 0; i < PERF_WINDOW_BUFFER_SIZE; i++) {
 		sum += self->by_duration[i].execution_time;
                 mem_log("%f,", self->by_duration[i].execution_time/1000.0);
         }
 	mem_log("\n");
+	*/
 	float avg = (sum/(float)PERF_WINDOW_BUFFER_SIZE)/1000.0;
 	mem_log("min:%f,max:%f,fifty_p:%f,seventy_p:%f,eighty_p:%f,nighty_p:%f,nighty_night_p:%f,avg:%f\n", min,max,fifty_p,seventy_p,eighty_p,nighty_p,nighty_night_p, avg);
 }

runtime/include/sandbox_functions.h

@@ -110,10 +110,7 @@ sandbox_get_srsf_priority(void *element)
 {
 	struct sandbox *sandbox = (struct sandbox *)element;
 	uint64_t now = __getcycles();
-        int64_t remaining_slack = sandbox->remaining_slack - (now - sandbox->last_update_timestamp);
-	if (remaining_slack < 0) {
-		return 0;
-	}
+	uint64_t remaining_slack = sandbox->remaining_slack - (now - sandbox->last_update_timestamp);
 	return remaining_slack;
 };
 

runtime/include/sandbox_receive_request.h

@@ -16,6 +16,8 @@
 #include "sandbox_types.h"
 #include "scheduler.h"
 
+extern uint64_t system_start_timestamp;
+
 /**
  * Receive and Parse the Request for the current sandbox
  * @return 0 if message parsing complete, -1 on error
@@ -44,6 +46,9 @@ sandbox_receive_request(struct sandbox *sandbox)
 
 		if (recved < 0) {
 			if (errno == EAGAIN) {
+			 	uint64_t block_time = __getcycles() - system_start_timestamp;
+                        	mem_log("time %lu blocked, request id:%d name %s obj=%p remaining slack %lu\n", block_time,
+                                        sandbox->id, sandbox->module->name, sandbox, sandbox->remaining_slack);
 				scheduler_block();
 				continue;
 			} else {

runtime/include/sandbox_set_as_running.h

@@ -24,12 +24,7 @@ sandbox_set_as_running(struct sandbox *sandbox, sandbox_state_t last_state)
 		uint64_t start_execution = now - system_start_timestamp;
 		uint64_t last = sandbox->last_update_timestamp;
 		uint64_t last_rs = sandbox->remaining_slack;
-		int64_t rs = sandbox->remaining_slack - (now - sandbox->last_update_timestamp);
-		if (rs < 0) {
-			sandbox->remaining_slack = 0;
-		} else {
-			sandbox->remaining_slack = rs;
-		}
+		sandbox->remaining_slack -= (now - sandbox->last_update_timestamp);
 		sandbox->last_update_timestamp = now;  
 		sandbox->runnable_duration += duration_of_last_state;
 		current_sandbox_set(sandbox);

runtime/src/current_sandbox.c

@@ -9,6 +9,8 @@
 #include "module.h"
 #include "software_interrupt.h"
 
+extern uint64_t system_start_timestamp;
+
 __thread struct sandbox *worker_thread_current_sandbox = NULL;
 
 __thread struct sandbox_context_cache local_sandbox_context_cache = {
@@ -121,6 +123,9 @@ current_sandbox_start(void)
 
 		memcpy(pre_func_output, sandbox->request_response_data + sandbox->request_length, output_length);
 	 	uint64_t enqueue_timestamp = __getcycles();	
+		uint64_t current_rs = enqueue_timestamp - system_start_timestamp; 
+		mem_log("time %lu request id:%d executing, name:%s remaining slack %lu\n", current_rs,
+                                      sandbox->id, sandbox->module->name, sandbox->remaining_slack);
 		struct sandbox_request *sandbox_request =
                                   sandbox_request_allocate(next_module, false, sandbox->request_length, 
 							   next_module->name, sandbox->client_socket_descriptor,

runtime/src/global_request_scheduler.c

@@ -1,6 +1,8 @@
 #include "global_request_scheduler.h"
+#include "memlogging.h"
 #include "panic.h"
 
+extern uint64_t system_start_timestamp;
 /* Default uninitialized implementations of the polymorphic interface */
 __attribute__((noreturn)) static struct sandbox_request *
 uninitialized_add(void *arg)
@@ -45,6 +47,11 @@ global_request_scheduler_initialize(struct global_request_scheduler_config *conf
 struct sandbox_request *
 global_request_scheduler_add(struct sandbox_request *sandbox_request)
 {
+	uint64_t now = __getcycles();
+	uint64_t arrive_time = now - system_start_timestamp;
+	mem_log("time %lu request id:%d arrived, name:%s remaining_slack %lu now %lu, sys_start %lu \n", 
+		arrive_time, sandbox_request->id, sandbox_request->module->name, 
+		sandbox_request->remaining_slack, now, system_start_timestamp);	
 	assert(sandbox_request != NULL);
 	return global_request_scheduler.add_fn(sandbox_request);
 }

runtime/src/global_request_scheduler_minheap.c

@@ -76,10 +76,7 @@ sandbox_request_get_priority_srsf_fn(void *element)
 {
 	struct sandbox_request *sandbox_request = (struct sandbox_request *)element;
 	uint64_t now = __getcycles();	
-	int64_t remaining_slack = sandbox_request->remaining_slack - (now - sandbox_request->last_update_timestamp);
-	if (remaining_slack < 0) {
-		return 0;
-	}
+	uint64_t remaining_slack = sandbox_request->remaining_slack - (now - sandbox_request->last_update_timestamp);
 	return remaining_slack;
 };
 

runtime/src/listener_thread.c

@@ -182,10 +182,8 @@ listener_thread_main(void *dummy)
                                         next_module = next_module->next_module;
                                 }
 
-                                int64_t remaining_slack = module->relative_deadline - estimated_execution_time;
-				if (remaining_slack < 0) {
-					remaining_slack = 0;
-				}
+				 /* Adding system start timestamp to avoid negative remaining slack in the following update */
++                               uint64_t remaining_slack = module->relative_deadline - estimated_execution_time + system_start_timestamp;
 				
 				/* Allocate a Sandbox Request */
 				struct sandbox_request *sandbox_request =

runtime/src/software_interrupt.c

@@ -40,6 +40,7 @@ __thread _Atomic volatile sig_atomic_t        software_interrupt_signal_depth
 
 _Atomic volatile sig_atomic_t software_interrupt_deferred_sigalrm_max[RUNTIME_WORKER_THREAD_CORE_COUNT] = { 0 };
 
+extern pthread_t listener_thread_id;
 void
 software_interrupt_deferred_sigalrm_max_print()
 {
@@ -106,7 +107,7 @@ sigalrm_propagate_workers(siginfo_t *signal_info)
  * This function broadcasts the sigint signal to all other worker threads
  */
 static inline void
-sigint_propagate_workers(siginfo_t *signal_info)
+sigint_propagate_workers_listener(siginfo_t *signal_info)
 {
 	/* Signal was sent directly by the kernel, so forward to other threads */
 	if (signal_info->si_code == SI_KERNEL) {
@@ -117,6 +118,10 @@ sigint_propagate_workers(siginfo_t *signal_info)
 			assert(runtime_worker_threads[i] != 0);
 			pthread_kill(runtime_worker_threads[i], SIGINT);
 		}
+		/* send to listener thread */
+		if (pthread_self() != listener_thread_id) {
+			pthread_kill(listener_thread_id, SIGINT);
+		}		
 	} else {
 		/* Signal forwarded from another thread. Just confirm it resulted from pthread_kill */
 		assert(signal_info->si_code == SI_TKILL);
@@ -147,7 +152,7 @@ static inline void
 software_interrupt_handle_signals(int signal_type, siginfo_t *signal_info, void *user_context_raw)
 {
 	/* Only workers should receive signals */
-	assert(!listener_thread_is_running());
+	//assert(!listener_thread_is_running());
 
 	/* Signals should be masked if runtime has disabled them */
 	/* This is not applicable anymore because the signal might be SIGINT */
@@ -173,7 +178,7 @@ software_interrupt_handle_signals(int signal_type, siginfo_t *signal_info, void
 			atomic_fetch_add(&software_interrupt_deferred_sigalrm, 1);
 		} else {
 			/* A worker thread received a SIGALRM while running a preemptable sandbox, so preempt */
-			assert(current_sandbox->state == SANDBOX_RUNNING);
+			//assert(current_sandbox->state == SANDBOX_RUNNING);
 			scheduler_preempt(user_context);
 		}
 		goto done;
@@ -193,7 +198,7 @@ software_interrupt_handle_signals(int signal_type, siginfo_t *signal_info, void
 	}
 	case SIGINT: {
 		/* Only the thread that receives SIGINT from the kernel will broadcast SIGINT to other worker threads */
-		sigint_propagate_workers(signal_info);
+		sigint_propagate_workers_listener(signal_info);
 		dump_log_to_file();
 		/* terminate itself */	
 		pthread_exit(0);	

runtime/src/worker_thread.c

@@ -30,6 +30,7 @@ __thread int worker_thread_epoll_file_descriptor;
 __thread int worker_thread_idx;
 
 extern FILE *runtime_sandbox_perf_log;
+extern uint64_t system_start_timestamp;
 /***********************
  * Worker Thread Logic *
  **********************/
@@ -81,8 +82,14 @@ worker_thread_main(void *argument)
 		worker_thread_execute_epoll_loop();
 
 		/* Switch to a sandbox if one is ready to run */
+
 		next_sandbox = scheduler_get_next();
-		if (next_sandbox != NULL) { scheduler_switch_to(next_sandbox); }
+		if (next_sandbox != NULL) { 
+			uint64_t start_execution = __getcycles() - system_start_timestamp;
+			mem_log("time %lu pop from GQ, request id:%d name %s obj=%p remaining slack %lu last_update_time %lu \n", start_execution,
+                                        next_sandbox->id, next_sandbox->module->name, next_sandbox, next_sandbox->remaining_slack, next_sandbox->last_update_timestamp);
+			scheduler_switch_to(next_sandbox); 
+		}
 
 		/* Clear the completion queue */
 		local_completion_queue_free();