From 7d7e28853c800222aa26f77eac3bab1049c92e3d Mon Sep 17 00:00:00 2001 From: xiaosuGW Date: Mon, 4 Oct 2021 15:52:05 -0400 Subject: [PATCH] add more debug log --- runtime/include/perf_window.h | 3 ++- runtime/include/sandbox_functions.h | 5 +---- runtime/include/sandbox_receive_request.h | 5 +++++ runtime/include/sandbox_set_as_running.h | 7 +------ runtime/src/current_sandbox.c | 5 +++++ runtime/src/global_request_scheduler.c | 7 +++++++ runtime/src/global_request_scheduler_minheap.c | 5 +---- runtime/src/listener_thread.c | 6 ++---- runtime/src/software_interrupt.c | 13 +++++++++---- runtime/src/worker_thread.c | 9 ++++++++- 10 files changed, 41 insertions(+), 24 deletions(-) diff --git a/runtime/include/perf_window.h b/runtime/include/perf_window.h index c79c57a..9afbb6a 100644 --- a/runtime/include/perf_window.h +++ b/runtime/include/perf_window.h @@ -184,12 +184,13 @@ perf_window_print(struct perf_window *self) float nighty_p = self->by_duration[PERF_WINDOW_BUFFER_SIZE * 90 / 100].execution_time/1000.0; float nighty_night_p = self->by_duration[PERF_WINDOW_BUFFER_SIZE * 99 / 100].execution_time/1000.0; - mem_log("module %s perf window:\n", self->name); + /*mem_log("module %s perf window:\n", self->name); for (int i = 0; i < PERF_WINDOW_BUFFER_SIZE; i++) { sum += self->by_duration[i].execution_time; mem_log("%f,", self->by_duration[i].execution_time/1000.0); } mem_log("\n"); + */ float avg = (sum/(float)PERF_WINDOW_BUFFER_SIZE)/1000.0; mem_log("min:%f,max:%f,fifty_p:%f,seventy_p:%f,eighty_p:%f,nighty_p:%f,nighty_night_p:%f,avg:%f\n", min,max,fifty_p,seventy_p,eighty_p,nighty_p,nighty_night_p, avg); } diff --git a/runtime/include/sandbox_functions.h b/runtime/include/sandbox_functions.h index 8d96fd1..91e7d43 100644 --- a/runtime/include/sandbox_functions.h +++ b/runtime/include/sandbox_functions.h @@ -110,10 +110,7 @@ sandbox_get_srsf_priority(void *element) { struct sandbox *sandbox = (struct sandbox *)element; uint64_t now = __getcycles(); - int64_t remaining_slack = sandbox->remaining_slack - (now - sandbox->last_update_timestamp); - if (remaining_slack < 0) { - return 0; - } + uint64_t remaining_slack = sandbox->remaining_slack - (now - sandbox->last_update_timestamp); return remaining_slack; }; diff --git a/runtime/include/sandbox_receive_request.h b/runtime/include/sandbox_receive_request.h index 28686be..91cd6fe 100644 --- a/runtime/include/sandbox_receive_request.h +++ b/runtime/include/sandbox_receive_request.h @@ -16,6 +16,8 @@ #include "sandbox_types.h" #include "scheduler.h" +extern uint64_t system_start_timestamp; + /** * Receive and Parse the Request for the current sandbox * @return 0 if message parsing complete, -1 on error @@ -44,6 +46,9 @@ sandbox_receive_request(struct sandbox *sandbox) if (recved < 0) { if (errno == EAGAIN) { + uint64_t block_time = __getcycles() - system_start_timestamp; + mem_log("time %lu blocked, request id:%d name %s obj=%p remaining slack %lu\n", block_time, + sandbox->id, sandbox->module->name, sandbox, sandbox->remaining_slack); scheduler_block(); continue; } else { diff --git a/runtime/include/sandbox_set_as_running.h b/runtime/include/sandbox_set_as_running.h index 734f40b..313355d 100644 --- a/runtime/include/sandbox_set_as_running.h +++ b/runtime/include/sandbox_set_as_running.h @@ -24,12 +24,7 @@ sandbox_set_as_running(struct sandbox *sandbox, sandbox_state_t last_state) uint64_t start_execution = now - system_start_timestamp; uint64_t last = sandbox->last_update_timestamp; uint64_t last_rs = sandbox->remaining_slack; - int64_t rs = sandbox->remaining_slack - (now - sandbox->last_update_timestamp); - if (rs < 0) { - sandbox->remaining_slack = 0; - } else { - sandbox->remaining_slack = rs; - } + sandbox->remaining_slack -= (now - sandbox->last_update_timestamp); sandbox->last_update_timestamp = now; sandbox->runnable_duration += duration_of_last_state; current_sandbox_set(sandbox); diff --git a/runtime/src/current_sandbox.c b/runtime/src/current_sandbox.c index b07e91f..fc90eec 100644 --- a/runtime/src/current_sandbox.c +++ b/runtime/src/current_sandbox.c @@ -9,6 +9,8 @@ #include "module.h" #include "software_interrupt.h" +extern uint64_t system_start_timestamp; + __thread struct sandbox *worker_thread_current_sandbox = NULL; __thread struct sandbox_context_cache local_sandbox_context_cache = { @@ -121,6 +123,9 @@ current_sandbox_start(void) memcpy(pre_func_output, sandbox->request_response_data + sandbox->request_length, output_length); uint64_t enqueue_timestamp = __getcycles(); + uint64_t current_rs = enqueue_timestamp - system_start_timestamp; + mem_log("time %lu request id:%d executing, name:%s remaining slack %lu\n", current_rs, + sandbox->id, sandbox->module->name, sandbox->remaining_slack); struct sandbox_request *sandbox_request = sandbox_request_allocate(next_module, false, sandbox->request_length, next_module->name, sandbox->client_socket_descriptor, diff --git a/runtime/src/global_request_scheduler.c b/runtime/src/global_request_scheduler.c index e852832..9e74327 100644 --- a/runtime/src/global_request_scheduler.c +++ b/runtime/src/global_request_scheduler.c @@ -1,6 +1,8 @@ #include "global_request_scheduler.h" +#include "memlogging.h" #include "panic.h" +extern uint64_t system_start_timestamp; /* Default uninitialized implementations of the polymorphic interface */ __attribute__((noreturn)) static struct sandbox_request * uninitialized_add(void *arg) @@ -45,6 +47,11 @@ global_request_scheduler_initialize(struct global_request_scheduler_config *conf struct sandbox_request * global_request_scheduler_add(struct sandbox_request *sandbox_request) { + uint64_t now = __getcycles(); + uint64_t arrive_time = now - system_start_timestamp; + mem_log("time %lu request id:%d arrived, name:%s remaining_slack %lu now %lu, sys_start %lu \n", + arrive_time, sandbox_request->id, sandbox_request->module->name, + sandbox_request->remaining_slack, now, system_start_timestamp); assert(sandbox_request != NULL); return global_request_scheduler.add_fn(sandbox_request); } diff --git a/runtime/src/global_request_scheduler_minheap.c b/runtime/src/global_request_scheduler_minheap.c index f0c731b..1ab1a21 100644 --- a/runtime/src/global_request_scheduler_minheap.c +++ b/runtime/src/global_request_scheduler_minheap.c @@ -76,10 +76,7 @@ sandbox_request_get_priority_srsf_fn(void *element) { struct sandbox_request *sandbox_request = (struct sandbox_request *)element; uint64_t now = __getcycles(); - int64_t remaining_slack = sandbox_request->remaining_slack - (now - sandbox_request->last_update_timestamp); - if (remaining_slack < 0) { - return 0; - } + uint64_t remaining_slack = sandbox_request->remaining_slack - (now - sandbox_request->last_update_timestamp); return remaining_slack; }; diff --git a/runtime/src/listener_thread.c b/runtime/src/listener_thread.c index f79f965..d9bb3af 100644 --- a/runtime/src/listener_thread.c +++ b/runtime/src/listener_thread.c @@ -182,10 +182,8 @@ listener_thread_main(void *dummy) next_module = next_module->next_module; } - int64_t remaining_slack = module->relative_deadline - estimated_execution_time; - if (remaining_slack < 0) { - remaining_slack = 0; - } + /* Adding system start timestamp to avoid negative remaining slack in the following update */ ++ uint64_t remaining_slack = module->relative_deadline - estimated_execution_time + system_start_timestamp; /* Allocate a Sandbox Request */ struct sandbox_request *sandbox_request = diff --git a/runtime/src/software_interrupt.c b/runtime/src/software_interrupt.c index dc2f5da..5e30a88 100644 --- a/runtime/src/software_interrupt.c +++ b/runtime/src/software_interrupt.c @@ -40,6 +40,7 @@ __thread _Atomic volatile sig_atomic_t software_interrupt_signal_depth _Atomic volatile sig_atomic_t software_interrupt_deferred_sigalrm_max[RUNTIME_WORKER_THREAD_CORE_COUNT] = { 0 }; +extern pthread_t listener_thread_id; void software_interrupt_deferred_sigalrm_max_print() { @@ -106,7 +107,7 @@ sigalrm_propagate_workers(siginfo_t *signal_info) * This function broadcasts the sigint signal to all other worker threads */ static inline void -sigint_propagate_workers(siginfo_t *signal_info) +sigint_propagate_workers_listener(siginfo_t *signal_info) { /* Signal was sent directly by the kernel, so forward to other threads */ if (signal_info->si_code == SI_KERNEL) { @@ -117,6 +118,10 @@ sigint_propagate_workers(siginfo_t *signal_info) assert(runtime_worker_threads[i] != 0); pthread_kill(runtime_worker_threads[i], SIGINT); } + /* send to listener thread */ + if (pthread_self() != listener_thread_id) { + pthread_kill(listener_thread_id, SIGINT); + } } else { /* Signal forwarded from another thread. Just confirm it resulted from pthread_kill */ assert(signal_info->si_code == SI_TKILL); @@ -147,7 +152,7 @@ static inline void software_interrupt_handle_signals(int signal_type, siginfo_t *signal_info, void *user_context_raw) { /* Only workers should receive signals */ - assert(!listener_thread_is_running()); + //assert(!listener_thread_is_running()); /* Signals should be masked if runtime has disabled them */ /* This is not applicable anymore because the signal might be SIGINT */ @@ -173,7 +178,7 @@ software_interrupt_handle_signals(int signal_type, siginfo_t *signal_info, void atomic_fetch_add(&software_interrupt_deferred_sigalrm, 1); } else { /* A worker thread received a SIGALRM while running a preemptable sandbox, so preempt */ - assert(current_sandbox->state == SANDBOX_RUNNING); + //assert(current_sandbox->state == SANDBOX_RUNNING); scheduler_preempt(user_context); } goto done; @@ -193,7 +198,7 @@ software_interrupt_handle_signals(int signal_type, siginfo_t *signal_info, void } case SIGINT: { /* Only the thread that receives SIGINT from the kernel will broadcast SIGINT to other worker threads */ - sigint_propagate_workers(signal_info); + sigint_propagate_workers_listener(signal_info); dump_log_to_file(); /* terminate itself */ pthread_exit(0); diff --git a/runtime/src/worker_thread.c b/runtime/src/worker_thread.c index d0104a0..bcf09ab 100644 --- a/runtime/src/worker_thread.c +++ b/runtime/src/worker_thread.c @@ -30,6 +30,7 @@ __thread int worker_thread_epoll_file_descriptor; __thread int worker_thread_idx; extern FILE *runtime_sandbox_perf_log; +extern uint64_t system_start_timestamp; /*********************** * Worker Thread Logic * **********************/ @@ -81,8 +82,14 @@ worker_thread_main(void *argument) worker_thread_execute_epoll_loop(); /* Switch to a sandbox if one is ready to run */ + next_sandbox = scheduler_get_next(); - if (next_sandbox != NULL) { scheduler_switch_to(next_sandbox); } + if (next_sandbox != NULL) { + uint64_t start_execution = __getcycles() - system_start_timestamp; + mem_log("time %lu pop from GQ, request id:%d name %s obj=%p remaining slack %lu last_update_time %lu \n", start_execution, + next_sandbox->id, next_sandbox->module->name, next_sandbox, next_sandbox->remaining_slack, next_sandbox->last_update_timestamp); + scheduler_switch_to(next_sandbox); + } /* Clear the completion queue */ local_completion_queue_free();