diff --git a/runtime/include/sandbox_functions.h b/runtime/include/sandbox_functions.h index d3fdbc4..ebe32c8 100644 --- a/runtime/include/sandbox_functions.h +++ b/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); } diff --git a/runtime/include/sandbox_request.h b/runtime/include/sandbox_request.h index 4a84aaa..0005dfa 100644 --- a/runtime/include/sandbox_request.h +++ b/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; diff --git a/runtime/include/sandbox_send_response.h b/runtime/include/sandbox_send_response.h index 4dfb4e3..65e8f40 100644 --- a/runtime/include/sandbox_send_response.h +++ b/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; diff --git a/runtime/include/sandbox_set_as_initialized.h b/runtime/include/sandbox_set_as_initialized.h index 3413619..6e66c9a 100644 --- a/runtime/include/sandbox_set_as_initialized.h +++ b/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; diff --git a/runtime/include/sandbox_set_as_returned.h b/runtime/include/sandbox_set_as_returned.h index 06cceae..bc0c277 100644 --- a/runtime/include/sandbox_set_as_returned.h +++ b/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); diff --git a/runtime/include/sandbox_types.h b/runtime/include/sandbox_types.h index 44318e7..343d814 100644 --- a/runtime/include/sandbox_types.h +++ b/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 diff --git a/runtime/src/current_sandbox.c b/runtime/src/current_sandbox.c index c93ebc0..864de71 100644 --- a/runtime/src/current_sandbox.c +++ b/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 */ diff --git a/runtime/src/listener_thread.c b/runtime/src/listener_thread.c index a9616c4..d9a7522 100644 --- a/runtime/src/listener_thread.c +++ b/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); diff --git a/runtime/src/main.c b/runtime/src/main.c index 0729edf..e527699 100644 --- a/runtime/src/main.c +++ b/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"); diff --git a/runtime/tests/Makefile b/runtime/tests/Makefile index 61aa2c0..9c60f28 100644 --- a/runtime/tests/Makefile +++ b/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)