correct queuing time and total time for chain function

runtime/include/sandbox_functions.h

@@ -166,7 +166,9 @@ sandbox_print_perf(struct sandbox *sandbox)
 	if (runtime_sandbox_perf_log == NULL) return;
 
 	uint32_t total_time_us = sandbox->total_time / runtime_processor_speed_MHz;
-	uint32_t queued_us     = (sandbox->allocation_timestamp - sandbox->request_arrival_timestamp)
+	uint32_t execution_time_ms = (sandbox->completion_timestamp - sandbox->start_execution_timestamp)
+					/ 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;
@@ -179,9 +181,9 @@ sandbox_print_perf(struct sandbox *sandbox)
 	 * becomes more intelligent, then peak linear memory size needs to be tracked
 	 * seperately from current linear memory size.
 	 */
-	fprintf(runtime_sandbox_perf_log, "%lu,%s():%d,%s,%u,%u,%u,%u,%u,%u,%u,%u,%u\n", sandbox->id,
+	fprintf(runtime_sandbox_perf_log, "%lu,%s():%d,%s,%u,%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);
+	        running_us, blocked_us, returned_us, execution_time_ms, sandbox->linear_memory_size);
 	fflush(runtime_sandbox_perf_log);
 }

runtime/include/sandbox_request.h

@@ -21,6 +21,7 @@ struct sandbox_request {
 	int             socket_descriptor;
 	struct sockaddr socket_address;
 	uint64_t        request_arrival_timestamp; /* cycles */
+	uint64_t        enqueue_timestamp; /* cycles */
 	uint64_t        absolute_deadline;         /* cycles */
 	char * previous_function_output;
 	ssize_t output_length;
@@ -70,8 +71,8 @@ sandbox_request_log_allocation(struct sandbox_request *sandbox_request)
 static inline struct sandbox_request *
 sandbox_request_allocate(struct module *module, bool request_from_outside, ssize_t request_length, 
 			 char *arguments, int socket_descriptor, const struct sockaddr *socket_address, 
-			 uint64_t request_arrival_timestamp, uint64_t admissions_estimate, 
-			 char *previous_function_output, ssize_t output_length)
+			 uint64_t request_arrival_timestamp, uint64_t enqueue_timestamp, 
+			 uint64_t admissions_estimate, char *previous_function_output, ssize_t output_length)
 {
 	struct sandbox_request *sandbox_request = (struct sandbox_request *)malloc(sizeof(struct sandbox_request));
 	assert(sandbox_request);
@@ -85,6 +86,7 @@ sandbox_request_allocate(struct module *module, bool request_from_outside, ssize
 	sandbox_request->socket_descriptor = socket_descriptor;
 	memcpy(&sandbox_request->socket_address, socket_address, sizeof(struct sockaddr));
 	sandbox_request->request_arrival_timestamp = request_arrival_timestamp;
+	sandbox_request->enqueue_timestamp = enqueue_timestamp;
 	sandbox_request->absolute_deadline         = request_arrival_timestamp + module->relative_deadline;
 	sandbox_request->previous_function_output = previous_function_output;
 	sandbox_request->output_length = output_length;

runtime/include/sandbox_send_response.h

@@ -96,7 +96,7 @@ sandbox_send_response(struct sandbox *sandbox)
 
 	/* Capture Timekeeping data for end-to-end latency */
 	uint64_t end_time   = __getcycles();
-	sandbox->total_time = end_time - sandbox->request_arrival_timestamp;
+	sandbox->total_time = end_time - sandbox->enqueue_timestamp;
 
 	int rc;
 	int sent = 0;

runtime/include/sandbox_set_as_initialized.h

@@ -30,6 +30,7 @@ sandbox_set_as_initialized(struct sandbox *sandbox, struct sandbox_request *sand
 	sandbox->admissions_estimate = sandbox_request->admissions_estimate;
 
 	sandbox->request_arrival_timestamp = sandbox_request->request_arrival_timestamp;
+	sandbox->enqueue_timestamp = sandbox_request->enqueue_timestamp;
 	sandbox->allocation_timestamp      = allocation_timestamp;
 	sandbox->state                     = SANDBOX_SET_AS_INITIALIZED;
 

runtime/include/sandbox_set_as_returned.h

@@ -32,7 +32,7 @@ sandbox_set_as_returned(struct sandbox *sandbox, sandbox_state_t last_state)
 	switch (last_state) {
 	case SANDBOX_RUNNING: {
 		sandbox->response_timestamp = now;
-		sandbox->total_time         = now - sandbox->request_arrival_timestamp;
+		sandbox->total_time         = now - sandbox->enqueue_timestamp;
 		sandbox->running_duration += duration_of_last_state;
 		local_runqueue_delete(sandbox);
 		sandbox_free_linear_memory(sandbox);

runtime/include/sandbox_types.h

@@ -50,6 +50,8 @@ struct sandbox {
 	struct arch_context ctxt; /* register context for context switch. */
 
 	uint64_t request_arrival_timestamp;   /* Timestamp when request is received */
+	uint64_t enqueue_timestamp;   /* Timestamp when sandbox request is enqueued */
+	uint64_t start_execution_timestamp;   /* Timestamp when sandbox starts execution */
 	uint64_t allocation_timestamp;        /* Timestamp when sandbox is allocated */
 	uint64_t response_timestamp;          /* Timestamp when response is sent */
 	uint64_t completion_timestamp;        /* Timestamp when sandbox runs to completion */
@@ -67,6 +69,7 @@ struct sandbox {
 
 	uint64_t absolute_deadline;
 	uint64_t total_time; /* From Request to Response */
+	uint64_t execution_time; /* From running to response */
 
 	/*
 	 * Unitless estimate of the instantaneous fraction of system capacity required to run the request

runtime/src/current_sandbox.c

@@ -61,9 +61,11 @@ current_sandbox_disable_preemption(struct sandbox *sandbox)
 void
 current_sandbox_start(void)
 {
+	uint64_t start_execution_timestamp =  __getcycles();
 	struct sandbox *sandbox = current_sandbox_get();
 	assert(sandbox != NULL);
 	assert(sandbox->state == SANDBOX_RUNNING);
+	sandbox->start_execution_timestamp = start_execution_timestamp;
 
 	char *error_message = "";
 
@@ -109,11 +111,13 @@ current_sandbox_start(void)
 		ssize_t output_length = sandbox->request_response_data_length - sandbox->request_length;
 		char * pre_func_output = (char *) malloc(output_length);
 		memcpy(pre_func_output, sandbox->request_response_data + sandbox->request_length, output_length);
+	 	uint64_t enqueue_timestamp = __getcycles();	
 		struct sandbox_request *sandbox_request =
                                   sandbox_request_allocate(next_module, false, sandbox->request_length, 
 							   next_module->name, sandbox->client_socket_descriptor,
                                                            (const struct sockaddr *)&sandbox->client_address,
-                                                           sandbox->request_arrival_timestamp, true, pre_func_output, output_length);
+                                                           sandbox->request_arrival_timestamp, enqueue_timestamp, 
+							   true, pre_func_output, output_length);
                 /* reset the request id to the same as the current request id */
 		sandbox_request->id = sandbox->id;  
 		/* Add to the Global Sandbox Request Scheduler */

runtime/src/listener_thread.c

@@ -179,7 +179,8 @@ listener_thread_main(void *dummy)
 				struct sandbox_request *sandbox_request =
 				  sandbox_request_allocate(module, true, 0, module->name, client_socket,
 				                           (const struct sockaddr *)&client_address,
-				                           request_arrival_timestamp, work_admitted, NULL, 0);
+				                           request_arrival_timestamp, request_arrival_timestamp, 
+							   work_admitted, NULL, 0);
 
 				/* Add to the Global Sandbox Request Scheduler */
 				global_request_scheduler_add(sandbox_request);

runtime/src/main.c

@@ -225,7 +225,7 @@ runtime_configure()
 		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,memory\n");
+		                                  "running,blocked,returned,execution,memory\n");
 		fflush(runtime_sandbox_perf_log);
 	} else {
 		printf("\tSandbox Performance Log: Disabled\n");

runtime/tests/Makefile

@@ -1,6 +1,6 @@
 include Makefile.inc
 
-TESTS=fibonacci empty work work1k work10k work100k work1m forever filesys sockserver sockclient empty
+TESTS=fibonacci big_fibonacci empty work work1k work10k work100k work1m forever filesys sockserver sockclient empty
 
 TESTSRT=$(TESTS:%=%_rt)