From 048b01e69039970654700be10fc5ec3f9be04f54 Mon Sep 17 00:00:00 2001
From: Sean McBride <spmcbride1201@gmail.com>
Date: Fri, 24 Jul 2020 13:22:17 -0400
Subject: [PATCH] feat: print_perf

---
 runtime/include/sandbox.h   | 24 ++++++++++++++++++++++++
 runtime/src/sandbox.c       |  8 +++++++-
 runtime/src/worker_thread.c |  2 ++
 3 files changed, 33 insertions(+), 1 deletion(-)

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