From 9ead528dfcc7f03bc09202e7e5fd5e21b99c06db Mon Sep 17 00:00:00 2001 From: Sean McBride Date: Wed, 12 Aug 2020 22:20:25 -0400 Subject: [PATCH] chore: better debugging and small socket fixes --- runtime/Makefile | 1 + runtime/include/runtime.h | 24 ++++++++ runtime/src/runtime.c | 92 +++++++++++++++++++++-------- runtime/src/sandbox.c | 23 ++++++-- runtime/tests/preemption/client1.sh | 2 +- runtime/tests/preemption/client2.sh | 2 +- 6 files changed, 113 insertions(+), 31 deletions(-) diff --git a/runtime/Makefile b/runtime/Makefile index 2e21468..c83dc17 100644 --- a/runtime/Makefile +++ b/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 diff --git a/runtime/include/runtime.h b/runtime/include/runtime.h index b5ca726..485858c 100644 --- a/runtime/include/runtime.h +++ b/runtime/include/runtime.h @@ -6,6 +6,11 @@ #include "types.h" +#ifdef LOG_TOTAL_REQS_RESPS +#include +#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 diff --git a/runtime/src/runtime.c b/runtime/src/runtime.c index c0af303..49770a9 100644 --- a/runtime/src/runtime.c +++ b/runtime/src/runtime.c @@ -4,6 +4,7 @@ #include #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; + struct epoll_event *epoll_events = (struct epoll_event *)malloc(LISTENER_THREAD_MAX_EPOLL_EVENTS + * sizeof(struct epoll_event)); 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 */ - send(socket_descriptor, HTTP_RESPONSE_504_SERVICE_UNAVAILABLE, - 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, - request_arrival_timestamp, 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; + listener_thread_reject(socket_descriptor); + continue; + } + + /* Allocate a Sandbox Request */ + struct sandbox_request *sandbox_request = + sandbox_request_allocate(module, module->name, socket_descriptor, + (const struct sockaddr *)&client_address, request_arrival_timestamp, + admissions_estimate); + + /* 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); + 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"); } /** diff --git a/runtime/src/sandbox.c b/runtime/src/sandbox.c index 77ca29f..1dc52cf 100644 --- a/runtime/src/sandbox.c +++ b/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); diff --git a/runtime/tests/preemption/client1.sh b/runtime/tests/preemption/client1.sh index 4a26867..53aab66 100755 --- a/runtime/tests/preemption/client1.sh +++ b/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/ diff --git a/runtime/tests/preemption/client2.sh b/runtime/tests/preemption/client2.sh index d38e10a..d028742 100755 --- a/runtime/tests/preemption/client2.sh +++ b/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/