Merge pull request #210 from gwsystems/only-longest-lock

feat: track longest held lock

runtime/include/generic_thread.h

@@ -3,6 +3,7 @@
 #include <stdint.h>
 
 extern __thread uint64_t generic_thread_lock_duration;
+extern __thread uint64_t generic_thread_lock_longest;
 extern __thread uint64_t generic_thread_start_timestamp;
 
 void generic_thread_dump_lock_overhead();

runtime/include/lock.h

@@ -1,6 +1,7 @@
 #pragma once
 
 #include <spinlock/mcs.h>
+#include <stdint.h>
 
 #include "arch/getcycles.h"
 #include "runtime.h"
@@ -27,12 +28,17 @@ typedef ck_spinlock_mcs_t lock_t;
  * @param lock - the address of the lock
  * @param unique_variable_name - a unique prefix to hygienically namespace an associated lock/unlock pair
  */
-#define LOCK_LOCK_WITH_BOOKKEEPING(lock, unique_variable_name)                        \
-	assert(listener_thread_is_running() || !software_interrupt_is_enabled());     \
-	struct ck_spinlock_mcs _hygiene_##unique_variable_name##_node;                \
-	uint64_t               _hygiene_##unique_variable_name##_pre = __getcycles(); \
-	ck_spinlock_mcs_lock((lock), &(_hygiene_##unique_variable_name##_node));      \
-	generic_thread_lock_duration += (__getcycles() - _hygiene_##unique_variable_name##_pre);
+
+#define LOCK_LOCK_WITH_BOOKKEEPING(lock, unique_variable_name)                                                         \
+	assert(listener_thread_is_running() || !software_interrupt_is_enabled());                                      \
+	struct ck_spinlock_mcs _hygiene_##unique_variable_name##_node;                                                 \
+	uint64_t               _hygiene_##unique_variable_name##_pre = __getcycles();                                  \
+	ck_spinlock_mcs_lock((lock), &(_hygiene_##unique_variable_name##_node));                                       \
+	uint64_t _hygiene_##unique_variable_name##_duration = (__getcycles() - _hygiene_##unique_variable_name##_pre); \
+	if (_hygiene_##unique_variable_name##_duration > generic_thread_lock_longest) {                                \
+		generic_thread_lock_longest = _hygiene_##unique_variable_name##_duration;                              \
+	}                                                                                                              \
+	generic_thread_lock_duration += _hygiene_##unique_variable_name##_duration;
 
 /**
  * Unlocks a lock

runtime/src/generic_thread.c

@@ -6,12 +6,14 @@
 /* Implemented by listener and workers */
 
 __thread uint64_t generic_thread_lock_duration   = 0;
+__thread uint64_t generic_thread_lock_longest    = 0;
 __thread uint64_t generic_thread_start_timestamp = 0;
 
 void
 generic_thread_initialize()
 {
 	generic_thread_start_timestamp = __getcycles();
+	generic_thread_lock_longest    = 0;
 	generic_thread_lock_duration   = 0;
 }
 
@@ -26,6 +28,8 @@ generic_thread_dump_lock_overhead()
 	uint64_t duration = __getcycles() - generic_thread_start_timestamp;
 	debuglog("Locks consumed %lu / %lu cycles, or %f%%\n", generic_thread_lock_duration, duration,
 	         (double)generic_thread_lock_duration / duration * 100);
+	debuglog("Longest Held Lock was %lu cycles, or %f quantums\n", generic_thread_lock_longest,
+	         (double)generic_thread_lock_longest / ((uint64_t)runtime_processor_speed_MHz * runtime_quantum_us));
 #endif
 #endif
 }