chore: better debugging and small socket fixes

runtime/Makefile

@@ -35,6 +35,7 @@ CFLAGS += -DDEBUG
 # CFLAGS += -DLOG_REQUEST_ALLOCATION
 # CFLAGS += -DLOG_PREEMPTION
 # CFLAGS += -DLOG_MODULE_LOADING
+# CFLAGS += -DLOG_TOTAL_REQS_RESPS
 
 # System Configuraiton Flags
 

runtime/include/runtime.h

@@ -6,6 +6,11 @@
 
 #include "types.h"
 
+#ifdef LOG_TOTAL_REQS_RESPS
+#include <stdatomic.h>
+#include "debuglog.h"
+#endif
+
 #define LISTENER_THREAD_CORE_ID          0 /* Dedicated Listener Core */
 #define LISTENER_THREAD_MAX_EPOLL_EVENTS 1024
 
@@ -29,6 +34,14 @@ extern float runtime_processor_speed_MHz;
 extern pthread_t runtime_worker_threads[];
 extern uint32_t  runtime_worker_threads_count;
 
+#ifdef LOG_TOTAL_REQS_RESPS
+/* Counts to track requests and responses */
+extern _Atomic uint32_t runtime_total_requests;
+extern _Atomic uint32_t runtime_total_2XX_responses;
+extern _Atomic uint32_t runtime_total_4XX_responses;
+extern _Atomic uint32_t runtime_total_5XX_responses;
+#endif
+
 /*
  * Unitless estimate of the instantaneous fraction of system capacity required to complete all previously
  * admitted work. This is used to calculate free capacity as part of admissions control
@@ -65,3 +78,14 @@ runtime_is_worker()
 
 	return false;
 }
+
+#ifdef LOG_TOTAL_REQS_RESPS
+static inline void
+runtime_log_requests_responses()
+{
+	debuglog("Requests: %u\n2XX: %u\n4XX: %u\n5XX: %u\nOutstanding Requests: %u\n", runtime_total_requests,
+	         runtime_total_2XX_responses, runtime_total_4XX_responses, runtime_total_5XX_responses,
+	         runtime_total_requests - runtime_total_2XX_responses - runtime_total_4XX_responses
+	           - runtime_total_5XX_responses);
+};
+#endif

runtime/src/runtime.c

@@ -4,6 +4,7 @@
 #include <uv.h>
 
 #include "arch/context.h"
+#include "debuglog.h"
 #include "global_request_scheduler_deque.h"
 #include "global_request_scheduler_minheap.h"
 #include "http_parser_settings.h"
@@ -20,6 +21,13 @@
 int    runtime_epoll_file_descriptor;
 double runtime_admitted;
 
+#ifdef LOG_TOTAL_REQS_RESPS
+_Atomic uint32_t runtime_total_requests;
+_Atomic uint32_t runtime_total_2XX_responses;
+_Atomic uint32_t runtime_total_4XX_responses;
+_Atomic uint32_t runtime_total_5XX_responses;
+#endif
+
 /******************************************
  * Shared Process / Listener Thread Logic *
  *****************************************/
@@ -34,6 +42,15 @@ runtime_initialize(void)
 	runtime_epoll_file_descriptor = epoll_create1(0);
 	assert(runtime_epoll_file_descriptor >= 0);
 
+
+#ifdef LOG_TOTAL_REQS_RESPS
+	/* Setup Counts */
+	runtime_total_requests      = 0;
+	runtime_total_2XX_responses = 0;
+	runtime_total_4XX_responses = 0;
+	runtime_total_5XX_responses = 0;
+#endif
+
 	/* Allocate and Initialize the global deque
 	TODO: Improve to expose variant as a config #Issue 93
 	*/
@@ -54,6 +71,32 @@ runtime_initialize(void)
  * Listener Thread Logic *
  ************************/
 
+/**
+ * Rejects Requests as determined by admissions control
+ * @param socket_descriptor - the client we are rejecting
+ */
+static inline void
+listener_thread_reject(int socket_descriptor)
+{
+	assert(socket_descriptor >= 0);
+
+	int send_rc = send(socket_descriptor, HTTP_RESPONSE_504_SERVICE_UNAVAILABLE,
+	                   strlen(HTTP_RESPONSE_504_SERVICE_UNAVAILABLE), 0);
+	if (send_rc < 0) goto send_504_err;
+
+#ifdef LOG_TOTAL_REQS_RESPS
+	runtime_total_5XX_responses++;
+	runtime_log_requests_responses();
+#endif
+
+close:
+	if (close(socket_descriptor) < 0) panic("Error closing client socket - %s", strerror(errno));
+	return;
+send_504_err:
+	debuglog("Error sending 504: %s", strerror(errno));
+	goto close;
+}
+
 /**
  * @brief Execution Loop of the listener core, io_handles HTTP requests, allocates sandbox request objects, and pushes
  * the sandbox object to the global dequeue
@@ -64,12 +107,11 @@ runtime_initialize(void)
  * runtime_epoll_file_descriptor - the epoll file descriptor
  *
  */
-void *
+__attribute__((noreturn)) void *
 listener_thread_main(void *dummy)
 {
 	struct epoll_event *epoll_events = (struct epoll_event *)malloc(LISTENER_THREAD_MAX_EPOLL_EVENTS
 	                                                                * sizeof(struct epoll_event));
-	int                 total_requests = 0;
 
 	while (true) {
 		int request_count = epoll_wait(runtime_epoll_file_descriptor, epoll_events,
@@ -94,7 +136,10 @@ listener_thread_main(void *dummy)
 				perror("accept");
 				assert(false);
 			}
-			total_requests++;
+#ifdef LOG_TOTAL_REQS_RESPS
+			runtime_total_requests++;
+			runtime_log_requests_responses();
+#endif
 
 			/* Perform Admission Control */
 
@@ -108,31 +153,30 @@ listener_thread_main(void *dummy)
 			double admissions_estimate = (double)estimated_execution / module->relative_deadline;
 
 			if (runtime_admitted + admissions_estimate >= runtime_worker_threads_count) {
-				/* Reject Requests that exceed system capacity */
+				listener_thread_reject(socket_descriptor);
-				send(socket_descriptor, HTTP_RESPONSE_504_SERVICE_UNAVAILABLE,
+				continue;
-				     strlen(HTTP_RESPONSE_504_SERVICE_UNAVAILABLE), 0);
+			}
-			} else {
+
 			/* Allocate a Sandbox Request */
 			struct sandbox_request *sandbox_request =
 			  sandbox_request_allocate(module, module->name, socket_descriptor,
-				                           (const struct sockaddr *)&client_address,
+			                           (const struct sockaddr *)&client_address, request_arrival_timestamp,
-				                           request_arrival_timestamp, admissions_estimate);
+			                           admissions_estimate);
-				assert(sandbox_request);
 
 			/* Add to the Global Sandbox Request Scheduler */
 			global_request_scheduler_add(sandbox_request);
 
 			/* Add to work accepted by the runtime */
 			runtime_admitted += admissions_estimate;
+
 #ifdef LOG_ADMISSIONS_CONTROL
 			debuglog("Runtime Admitted: %f / %u\n", runtime_admitted, runtime_worker_threads_count);
 #endif
 		}
 	}
-	}
 
 	free(epoll_events);
-	return NULL;
+	panic("Listener thread unexpectedly broke loop\n");
 }
 
 /**

runtime/src/sandbox.c

@@ -81,7 +81,7 @@ sandbox_receive_and_parse_client_request(struct sandbox *sandbox)
 	r = recv(sandbox->client_socket_descriptor, (sandbox->request_response_data), sandbox->module->max_request_size,
 	         0);
 	if (r < 0) {
-		perror("Error reading request data from client socket");
+		debuglog("Error reading request data from client socket - %s", strerror(errno));
 		return r;
 	}
 	while (r > 0) {
@@ -94,7 +94,7 @@ sandbox_receive_and_parse_client_request(struct sandbox *sandbox)
 		         (sandbox->request_response_data + sandbox->request_response_data_length),
 		         sandbox->module->max_request_size - sandbox->request_response_data_length, 0);
 		if (r < 0) {
-			perror("recv2");
+			debuglog("Error reading request data from client socket - %s", strerror(errno));
 			return r;
 		}
 	}
@@ -228,7 +228,9 @@ sandbox_close_http(struct sandbox *sandbox)
 	uv_close((uv_handle_t *)&sandbox->client_libuv_stream, libuv_callbacks_on_close_wakeup_sakebox);
 	worker_thread_process_io();
 #else
-	close(sandbox->client_socket_descriptor);
+	if (close(sandbox->client_socket_descriptor) < 0) {
+		panic("Error closing client socket - %s", strerror(errno));
+	}
 #endif
 }
 
@@ -322,16 +324,21 @@ current_sandbox_main(void)
 		goto err;
 	};
 
+#ifdef LOG_TOTAL_REQS_RESPS
+	runtime_total_2XX_responses++;
+	runtime_log_requests_responses();
+#endif
+
 	sandbox->response_timestamp = __getcycles();
 
 	software_interrupt_disable();
 
 	assert(sandbox->state == SANDBOX_RUNNING);
+	sandbox_close_http(sandbox);
 	sandbox_set_as_returned(sandbox, SANDBOX_RUNNING);
 
 done:
 	/* Cleanup connection and exit sandbox */
-	sandbox_close_http(sandbox);
 	worker_thread_on_sandbox_exit(sandbox);
 
 	/* This assert prevents a segfault discussed in
@@ -343,7 +350,14 @@ err:
 	assert(sandbox->state == SANDBOX_RUNNING);
 	send(sandbox->client_socket_descriptor, HTTP_RESPONSE_400_BAD_REQUEST, strlen(HTTP_RESPONSE_400_BAD_REQUEST),
 	     0);
+
+#ifdef LOG_TOTAL_REQS_RESPS
+	runtime_total_4XX_responses++;
+	debuglog("At %llu, Sandbox %lu - 4XX\n", __getcycles(), sandbox->request_arrival_timestamp);
+	runtime_log_requests_responses();
+#endif
 	software_interrupt_disable();
+	sandbox_close_http(sandbox);
 	sandbox_set_as_error(sandbox, SANDBOX_RUNNING);
 	goto done;
 }
@@ -751,7 +765,6 @@ sandbox_set_as_error(struct sandbox *sandbox, sandbox_state_t last_state)
 #endif
 
 	runtime_admitted -= sandbox->admissions_estimate;
-	assert(runtime_admitted >= 0);
 
 #ifdef LOG_ADMISSIONS_CONTROL
 	debuglog("Runtime Admitted: %f / %u\n", runtime_admitted, runtime_worker_threads_count);

runtime/tests/preemption/client1.sh

@@ -1,4 +1,4 @@
 #!/bin/bash
 # fib(20)
 # Perhaps this can be improved to pass a body without an additional file
-ab -n 100000 -c 100 -p client1_body.txt -v 4 localhost:10000/
+ab -n 100000 -c 100 -p client1_body.txt -v 4 -r localhost:10000/

runtime/tests/preemption/client2.sh

@@ -1,4 +1,4 @@
 #!/bin/bash
 # fib(10)
 # Perhaps this can be improved to pass a body without an additional file
-ab -n 100000 -c 100 -p client2_body.txt -v 4 localhost:10001/
+ab -n 100000 -c 100 -p client2_body.txt -v 4 -r localhost:10001/