feat: Instrument spinlocks

runtime/include/perf_window.h

@@ -3,6 +3,9 @@
 #include <spinlock/fas.h>
 #include <stdint.h>
 
+#include "runtime.h"
+#include "worker_thread.h"
+
 /* Should be Power of 2! */
 #define PERF_WINDOW_BUFFER_SIZE 16
 
@@ -68,7 +71,9 @@ perf_window_add(struct perf_window *self, uint64_t value)
 	/* A successful invocation should run for a non-zero amount of time */
 	assert(value > 0);
 
+	uint64_t pre = __getcycles();
 	ck_spinlock_fas_lock(&self->lock);
+	worker_thread_lock_duration += (__getcycles() - pre);
 	self->buffer[self->count++ % PERF_WINDOW_BUFFER_SIZE] = value;
 	perf_window_update_mean(self);
 	ck_spinlock_fas_unlock(&self->lock);

runtime/include/priority_queue.h

@@ -3,6 +3,9 @@
 
 #include <spinlock/fas.h>
 
+#include "runtime.h"
+#include "worker_thread.h"
+
 #define MAX 4096
 
 /**

runtime/include/worker_thread.h

@@ -6,6 +6,8 @@
 If there are fewer cores than this, main dynamically overrides this and uses all available */
 #define WORKER_THREAD_CORE_COUNT (NCORES > 1 ? NCORES - 1 : NCORES)
 
+extern __thread uint64_t  worker_thread_lock_duration;
+extern __thread uint64_t  worker_thread_start_timestamp;
 extern __thread uv_loop_t worker_thread_uvio_handle;
 
 void *worker_thread_main(void *return_code);

runtime/src/priority_queue.c

@@ -157,7 +157,9 @@ int
 priority_queue_length(struct priority_queue *self)
 {
 	assert(self != NULL);
+	uint64_t pre = __getcycles();
 	ck_spinlock_fas_lock(&self->lock);
+	worker_thread_lock_duration += (__getcycles() - pre);
 	int length = self->first_free - 1;
 	ck_spinlock_fas_unlock(&self->lock);
 	return length;
@@ -172,7 +174,9 @@ int
 priority_queue_enqueue(struct priority_queue *self, void *value)
 {
 	assert(self != NULL);
+	uint64_t pre = __getcycles();
 	ck_spinlock_fas_lock(&self->lock);
+	worker_thread_lock_duration += (__getcycles() - pre);
 
 	if (priority_queue_append(self, value) == -ENOSPC) return -ENOSPC;
 
@@ -194,7 +198,9 @@ int
 priority_queue_delete(struct priority_queue *self, void *value)
 {
 	assert(self != NULL);
+	uint64_t pre = __getcycles();
 	ck_spinlock_fas_lock(&self->lock);
+	worker_thread_lock_duration += (__getcycles() - pre);
 
 	bool did_delete = false;
 	for (int i = 1; i < self->first_free; i++) {
@@ -225,10 +231,13 @@ priority_queue_dequeue(struct priority_queue *self, void **dequeued_element)
 
 	int return_code;
 
+	uint64_t pre = __getcycles();
 	if (ck_spinlock_fas_trylock(&self->lock) == false) {
+		worker_thread_lock_duration += (__getcycles() - pre);
 		return_code = -EAGAIN;
 		goto done;
 	};
+	worker_thread_lock_duration += (__getcycles() - pre);
 
 	if (priority_queue_is_empty_locked(self)) {
 		return_code = -ENOENT;
@@ -270,10 +279,13 @@ priority_queue_top(struct priority_queue *self, void **dequeued_element)
 
 	int return_code;
 
+	uint64_t pre = __getcycles();
 	if (ck_spinlock_fas_trylock(&self->lock) == false) {
+		worker_thread_lock_duration += (__getcycles() - pre);
 		return_code = -EAGAIN;
 		goto done;
 	};
+	worker_thread_lock_duration += (__getcycles() - pre);
 
 	if (priority_queue_is_empty_locked(self)) {
 		return_code = -ENOENT;

runtime/src/worker_thread.c

@@ -29,10 +29,29 @@ __thread uv_loop_t worker_thread_uvio_handle;
 /* Flag to signify if the thread is currently running callbacks in the libuv event loop */
 static __thread bool worker_thread_is_in_libuv_event_loop = false;
 
+/* Total Lock Contention in Cycles */
+__thread uint64_t worker_thread_lock_duration;
+
+/* Timestamp when worker thread began executing */
+__thread uint64_t worker_thread_start_timestamp;
+
 /***********************
  * Worker Thread Logic *
  **********************/
 
+/**
+ * Reports lock contention for the worker thread
+ */
+static inline void
+worker_thread_dump_lock_overhead()
+{
+#ifdef DEBUG
+	uint64_t worker_duration = __getcycles() - worker_thread_start_timestamp;
+	debuglog("Locks consumed %lu / %lu cycles, or %f%%\n", worker_thread_lock_duration, worker_duration,
+	         (double)worker_thread_lock_duration / worker_duration * 100);
+#endif
+}
+
 /**
  * Conditionally triggers appropriate state changes for exiting sandboxes
  * @param exiting_sandbox - The sandbox that ran to completion
@@ -228,6 +247,10 @@ worker_thread_execute_libuv_event_loop(void)
 void *
 worker_thread_main(void *return_code)
 {
+	/* Initialize Bookkeeping */
+	worker_thread_start_timestamp = __getcycles();
+	worker_thread_lock_duration   = 0;
+
 	/* Initialize Base Context */
 	arch_context_init(&worker_thread_base_context, 0, 0);
 
@@ -286,6 +309,7 @@ worker_thread_on_sandbox_exit(struct sandbox *exiting_sandbox)
 {
 	assert(exiting_sandbox);
 	software_interrupt_disable();
+	worker_thread_dump_lock_overhead();
 	worker_thread_switch_to_base_context();
 	assert(0);
 }