chore: Update logs and flags

runtime/Makefile

@@ -14,22 +14,22 @@ BINARY_NAME=sledgert
 # Options: {USE_MEM_GENERIC, USE_MEM_VM}
 USE_MEM = USE_MEM_VM
 
+# Feature Toggles
+# CFLAGS += -DADMISSIONS_CONTROL
+
 # Debugging Flags
 
-# Strips out calls to assert()
+# Strips out calls to assert() and disables debuglog
 # CFLAGS += -DNDEBUG
 
-# Turns on debuglog and other assorted printfs in third party libs
-CFLAGS += -DDEBUG
-
-# Redirects debuglogs to /runtime/bin/awesome.log 
-#FIXME This log should be changed to sledge.log (and likely to a user defined path)
+# Redirects debuglogs to /runtime/bin/sledge.log 
 # CFLAGS += -DLOG_TO_FILE
 
 # Various Informational Logs for Debugging
 # CFLAGS += -DLOG_HTTP_PARSER
 # CFLAGS += -DLOG_STATE_CHANGES
 # CFLAGS += -DLOG_LOCK_OVERHEAD
+# CFLAGS += -DLOG_LISTENER_LOCK_OVERHEAD
 # CFLAGS += -DLOG_CONTEXT_SWITCHES
 # CFLAGS += -DLOG_ADMISSIONS_CONTROL
 # CFLAGS += -DLOG_REQUEST_ALLOCATION
@@ -38,13 +38,13 @@ CFLAGS += -DDEBUG
 
 # This flag dumps totals of incoming requests and outgoing responses, broken out by status code
 # family, such as 2XX, 4XX, 5XX. It is useful to debug clients hanging waiting for a response.
-# To log, run `call runtime_log_requests_responses()` while in GDB
+# To log, run `call http_total_log()` while in GDB
 # CFLAGS += -DLOG_TOTAL_REQS_RESPS
 
 # This flag logs the total number of sandboxes in the various states
 # It is useful to debug if sandboxes are "getting caught" in a particular state
 # To log, run `call runtime_log_sandbox_states()` while in GDB
-# CFLAGS += -DLOG_SANDBOX_TOTALS
+# CFLAGS += -DLOG_SANDBOX_COUNT
 
 # This flag enables an per-worker atomic count of sandbox's local runqueue count in thread local storage
 # Useful to debug if sandboxes are "getting caught" or "leaking" while in a local runqueue

runtime/src/runtime.c

@@ -64,6 +64,25 @@ runtime_initialize(void)
  * Listener Thread Logic *
  ************************/
 
+static inline void
+listener_thread_start_lock_overhead_measurement(uint64_t request_arrival_timestamp)
+{
+#ifdef LOG_LISTENER_LOCK_OVERHEAD
+	worker_thread_start_timestamp = request_arrival_timestamp;
+	worker_thread_lock_duration   = 0;
+#endif
+}
+
+static inline void
+listener_thread_stop_lock_overhead_measurement()
+{
+#ifdef LOG_LISTENER_LOCK_OVERHEAD
+	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
+}
+
 /**
  * @brief Execution Loop of the listener core, io_handles HTTP requests, allocates sandbox request objects, and pushes
  * the sandbox object to the global dequeue
@@ -95,6 +114,7 @@ listener_thread_main(void *dummy)
 		assert(descriptor_count > 0);
 
 		uint64_t request_arrival_timestamp = __getcycles();
+		listener_thread_start_lock_overhead_measurement(request_arrival_timestamp);
 		for (int i = 0; i < descriptor_count; i++) {
 			/* Check Event to determine if epoll returned an error */
 			if ((epoll_events[i].events & EPOLLERR) == EPOLLERR) {
@@ -175,7 +195,8 @@ listener_thread_main(void *dummy)
 
 			} /* while true */
 		}         /* for loop */
-	}                 /* while true */
+		listener_thread_stop_lock_overhead_measurement();
+	} /* while true */
 
 	panic("Listener thread unexpectedly broke loop\n");