diff --git a/runtime/include/sandbox.h b/runtime/include/sandbox.h index 8bc7ef2..b04f829 100644 --- a/runtime/include/sandbox.h +++ b/runtime/include/sandbox.h @@ -252,3 +252,27 @@ sandbox_get_libuv_handle(struct sandbox *sandbox, int io_handle_index) if (io_handle_index >= SANDBOX_MAX_IO_HANDLE_COUNT || io_handle_index < 0) return NULL; return &sandbox->io_handles[io_handle_index].libuv_handle; } + +/** + * Prints key performance metrics for a sandbox to STDOUT + * @param sandbox + **/ +static inline void +sandbox_print_perf(struct sandbox *sandbox) +{ + uint64_t total_time_us = sandbox->total_time / runtime_processor_speed_MHz; + uint64_t queued_us = (sandbox->allocation_timestamp - sandbox->request_arrival_timestamp) + / runtime_processor_speed_MHz; + uint64_t initializing_us = sandbox->initializing_duration / runtime_processor_speed_MHz; + uint64_t runnable_us = sandbox->runnable_duration / runtime_processor_speed_MHz; + uint64_t running_us = sandbox->running_duration / runtime_processor_speed_MHz; + uint64_t blocked_us = sandbox->blocked_duration / runtime_processor_speed_MHz; + uint64_t returned_us = sandbox->returned_duration / runtime_processor_speed_MHz; + debuglog("%s():%d, state: %s, deadline: %u, actual: %lu, queued: %lu, initializing: %lu, runnable: %lu, " + "running: " + "%lu, blocked: " + "%lu, returned %lu\n", + 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); +} diff --git a/runtime/src/sandbox.c b/runtime/src/sandbox.c index af8839a..f645307 100644 --- a/runtime/src/sandbox.c +++ b/runtime/src/sandbox.c @@ -359,7 +359,8 @@ current_sandbox_main(void) sandbox_setup_arguments(sandbox); /* Executing the function */ - sandbox->return_value = module_main(current_module, argument_count, sandbox->arguments_offset); + sandbox->return_value = module_main(current_module, argument_count, sandbox->arguments_offset); + sandbox->completion_timestamp = __getcycles(); /* Retrieve the result, construct the HTTP response, and send to client */ rc = sandbox_build_and_send_client_response(sandbox); @@ -368,6 +369,8 @@ current_sandbox_main(void) goto err; }; + sandbox->response_timestamp = __getcycles(); + done: /* Cleanup connection and exit sandbox */ sandbox_close_http(sandbox); @@ -480,6 +483,7 @@ sandbox_allocate(struct sandbox_request *sandbox_request) struct sandbox *sandbox; char * error_message = ""; + uint64_t now = __getcycles(); /* Allocate Sandbox control structures, buffers, and linear memory in a 4GB address space */ sandbox = sandbox_allocate_memory(sandbox_request->module); @@ -488,6 +492,8 @@ sandbox_allocate(struct sandbox_request *sandbox_request) goto err_memory_allocation_failed; } + sandbox->allocation_timestamp = now; + /* Set state to initializing */ sandbox->state = SANDBOX_UNINITIALIZED; diff --git a/runtime/src/worker_thread.c b/runtime/src/worker_thread.c index 75a2401..e3ae20b 100644 --- a/runtime/src/worker_thread.c +++ b/runtime/src/worker_thread.c @@ -269,6 +269,8 @@ worker_thread_on_sandbox_exit(struct sandbox *exiting_sandbox) software_interrupt_disable(); local_runqueue_delete(exiting_sandbox); exiting_sandbox->state = SANDBOX_RETURNED; + + sandbox_print_perf(exiting_sandbox); local_completion_queue_add(exiting_sandbox); /* This should force return to main event loop */