haiwan
/
sledge
0
0
Fork 1
Code Issues Pull Requests Packages Projects Releases Wiki Activity

chore: enhance log granularity

Browse Source
main
Sean McBride 4 years ago
parent 9749299672
commit 9bed646e3b
10 changed files with 83 additions and 14 deletions
Show Stats Download Patch File Download Diff File

28
runtime/Makefile
Unescape View File

@ -14,10 +14,32 @@ NCORES = ${TOTAL_CORES}
# Options: {USE_MEM_GENERIC, USE_MEM_VM}
USE_MEM = USE_MEM_VM
# Flags
# Debugging Flags
# Strips out calls to assert()
# 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)
# CFLAGS += -DLOG_TO_FILE
# Various Informational Logs for Debugging
# CFLAGS += -DLOG_STATE_CHANGES
# CFLAGS += -DLOG_LOCK_OVERHEAD
# CFLAGS += -DLOG_CONTEXT_SWITCHES
# CFLAGS += -DLOG_ADMISSIONS_CONTROL
# CFLAGS += -DLOG_SANDBOX_PERF
# CFLAGS += -DLOG_REQUEST_ALLOCATION
# CFLAGS += -DLOG_PREEMPTION
# CFLAGS += -DLOG_MODULE_LOADING
# System Configuraiton Flags
# Sets a flag equal to the processor architecture
CFLAGS += -D${ARCH}
#CFLAGS += -DDEBUG
#CFLAGS += -DLOG_TO_FILE
CFLAGS += -DNCORES=${NCORES}
CFLAGS += -DPAGE_SIZE=$(PAGE_SIZE)
#CFLAGS += -DPREEMPT_DISABLE

5
runtime/include/sandbox.h
Unescape View File

@ -325,10 +325,11 @@ sandbox_print_perf(struct sandbox *sandbox)
uint32_t running_us = sandbox->running_duration / runtime_processor_speed_MHz;
uint32_t blocked_us = sandbox->blocked_duration / runtime_processor_speed_MHz;
uint32_t returned_us = sandbox->returned_duration / runtime_processor_speed_MHz;
debuglog("%lu, %s():%d, state: %s, deadline: %u, actual: %u, queued: %u, initializing: %u, runnable: %u, "
debuglog("%lu, %s():%d, state: %s, deadline: %u, actual: %u, queued: %u, initializing: %u, "
"runnable: %u, "
"running: %u, "
"blocked: %u, "
"returned %u\n",
"returned: %u\n",
sandbox->request_arrival_timestamp, sandbox->module->name, sandbox->module->port,
sandbox_state_stringify(sandbox->state), sandbox->module->relative_deadline_us, total_time_us,
queued_us, initializing_us, runnable_us, running_us, blocked_us, returned_us);

2
runtime/include/sandbox_request.h
Unescape View File

@ -48,7 +48,9 @@ sandbox_request_allocate(struct module *module, char *arguments, int socket_desc
sandbox_request->absolute_deadline = request_arrival_timestamp + module->relative_deadline;
sandbox_request->admissions_estimate = admissions_estimate;
#ifdef LOG_REQUEST_ALLOCATION
debuglog("Allocating %lu of %s:%d\n", sandbox_request->request_arrival_timestamp, sandbox_request->module->name,
sandbox_request->module->port);
#endif
return sandbox_request;
}

4
runtime/src/local_runqueue_minheap.c
Unescape View File

@ -137,15 +137,19 @@ local_runqueue_minheap_preempt(ucontext_t *user_context)
/* If we're able to get a sandbox request with a tighter deadline, preempt the current context and run it */
struct sandbox_request *sandbox_request;
if (global_deadline < local_deadline) {
#ifdef LOG_PREEMPTION
debuglog("Sandbox %lu has deadline of %lu. Trying to preempt for request with %lu\n",
current_sandbox->request_arrival_timestamp, local_deadline, global_deadline);
#endif
int return_code = global_request_scheduler_remove(&sandbox_request);
/* If we were unable to get a sandbox_request, exit */
if (return_code != 0) goto done;
#ifdef LOG_PREEMPTION
debuglog("Preempted %lu for %lu\n", local_deadline, sandbox_request->absolute_deadline);
#endif
/* Allocate the request */
struct sandbox *next_sandbox = sandbox_allocate(sandbox_request);

9
runtime/src/main.c
Unescape View File

@ -87,9 +87,9 @@ runtime_allocate_available_cores()
assert(runtime_worker_threads_count == WORKER_THREAD_CORE_COUNT);
printf("Number of cores %u, sandboxing cores %u (start: %u) and module reqs %u\n",
runtime_total_online_processors, runtime_worker_threads_count, runtime_first_worker_processor,
LISTENER_THREAD_CORE_ID);
debuglog("Number of cores %u, sandboxing cores %u (start: %u) and module reqs %u\n",
runtime_total_online_processors, runtime_worker_threads_count, runtime_first_worker_processor,
LISTENER_THREAD_CORE_ID);
}
/**
@ -210,8 +210,9 @@ main(int argc, char **argv)
runtime_set_resource_limits_to_max();
runtime_allocate_available_cores();
runtime_initialize();
#ifdef LOG_MODULE_LOADING
debuglog("Parsing modules file [%s]\n", argv[1]);
#endif
if (module_new_from_json(argv[1])) panic("failed to parse modules file[%s]\n", argv[1]);
debuglog("Starting listener thread\n");

5
runtime/src/module.c
Unescape View File

@ -261,7 +261,9 @@ module_new_from_json(char *file_name)
/* Read the file into the buffer and check that the buffer size equals the file size */
errno = 0;
int total_chars_read = fread(file_buffer, sizeof(char), stat_buffer.st_size, module_file);
#ifdef LOG_MODULE_LOADING
debuglog("size read: %d content: %s\n", total_chars_read, file_buffer);
#endif
if (total_chars_read != stat_buffer.st_size) {
fprintf(stderr, "Attempt to read %s into buffer failed: %s\n", file_name, strerror(errno));
goto fread_err;
@ -417,8 +419,9 @@ module_new_from_json(char *file_name)
}
if (module_count == 0) fprintf(stderr, "%s contained no active modules\n", file_name);
#ifdef LOG_MODULE_LOADING
debuglog("Loaded %d module%s!\n", module_count, module_count > 1 ? "s" : "");
#endif
free(file_buffer);
return_code = 0;

2
runtime/src/runtime.c
Unescape View File

@ -124,7 +124,9 @@ listener_thread_main(void *dummy)
/* 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
}
}
}

29
runtime/src/sandbox.c
Unescape View File

@ -453,9 +453,9 @@ sandbox_set_as_initialized(struct sandbox *sandbox, struct sandbox_request *sand
assert(sandbox_request->socket_descriptor > 0);
assert(allocation_timestamp > 0);
#ifdef LOG_STATE_CHANGES
debuglog("Sandbox %lu | Uninitialized => Initialized\n", sandbox_request->request_arrival_timestamp);
#endif
sandbox->admissions_estimate = sandbox_request->admissions_estimate;
sandbox->request_arrival_timestamp = sandbox_request->request_arrival_timestamp;
@ -503,8 +503,11 @@ sandbox_set_as_runnable(struct sandbox *sandbox, sandbox_state_t last_state)
uint32_t duration_of_last_state = now - sandbox->last_state_change_timestamp;
sandbox->state = SANDBOX_SET_AS_RUNNABLE;
#ifdef LOG_STATE_CHANGES
debuglog("Sandbox %lu | %s => Runnable\n", sandbox->request_arrival_timestamp,
sandbox_state_stringify(last_state));
#endif
switch (last_state) {
case SANDBOX_INITIALIZED: {
@ -549,8 +552,10 @@ sandbox_set_as_running(struct sandbox *sandbox, sandbox_state_t last_state)
uint32_t duration_of_last_state = now - sandbox->last_state_change_timestamp;
sandbox->state = SANDBOX_SET_AS_RUNNING;
#ifdef LOG_STATE_CHANGES
debuglog("Sandbox %lu | %s => Running\n", sandbox->request_arrival_timestamp,
sandbox_state_stringify(last_state));
#endif
switch (last_state) {
case SANDBOX_RUNNABLE: {
@ -592,8 +597,10 @@ sandbox_set_as_preempted(struct sandbox *sandbox, sandbox_state_t last_state)
uint32_t duration_of_last_state = now - sandbox->last_state_change_timestamp;
sandbox->state = SANDBOX_SET_AS_PREEMPTED;
#ifdef LOG_STATE_CHANGES
debuglog("Sandbox %lu | %s => Preempted\n", sandbox->request_arrival_timestamp,
sandbox_state_stringify(last_state));
#endif
switch (last_state) {
case SANDBOX_RUNNING: {
@ -628,8 +635,10 @@ sandbox_set_as_blocked(struct sandbox *sandbox, sandbox_state_t last_state)
uint32_t duration_of_last_state = now - sandbox->last_state_change_timestamp;
sandbox->state = SANDBOX_SET_AS_BLOCKED;
#ifdef LOG_STATE_CHANGES
debuglog("Sandbox %lu | %s => Blocked\n", sandbox->request_arrival_timestamp,
sandbox_state_stringify(last_state));
#endif
switch (last_state) {
case SANDBOX_RUNNING: {
@ -666,8 +675,10 @@ sandbox_set_as_returned(struct sandbox *sandbox, sandbox_state_t last_state)
uint32_t duration_of_last_state = now - sandbox->last_state_change_timestamp;
sandbox->state = SANDBOX_SET_AS_RETURNED;
#ifdef LOG_STATE_CHANGES
debuglog("Sandbox %lu | %s => Returned\n", sandbox->request_arrival_timestamp,
sandbox_state_stringify(last_state));
#endif
switch (last_state) {
case SANDBOX_RUNNING: {
@ -709,8 +720,10 @@ sandbox_set_as_error(struct sandbox *sandbox, sandbox_state_t last_state)
uint32_t duration_of_last_state = now - sandbox->last_state_change_timestamp;
sandbox->state = SANDBOX_SET_AS_ERROR;
#ifdef LOG_STATE_CHANGES
debuglog("Sandbox %lu | %s => Error\n", sandbox->request_arrival_timestamp,
sandbox_state_stringify(last_state));
#endif
switch (last_state) {
case SANDBOX_SET_AS_INITIALIZED:
@ -733,12 +746,16 @@ sandbox_set_as_error(struct sandbox *sandbox, sandbox_state_t last_state)
sandbox->last_state_change_timestamp = now;
sandbox->state = SANDBOX_ERROR;
#ifdef LOG_SANDBOX_PERF
sandbox_print_perf(sandbox);
#endif
runtime_admitted -= sandbox->admissions_estimate;
assert(runtime_admitted >= 0);
debuglog("Runtime Utilization: %f%%\n", runtime_admitted / runtime_worker_threads_count * 100);
#ifdef LOG_ADMISSIONS_CONTROL
debuglog("Runtime Admitted: %f / %u\n", runtime_admitted, runtime_worker_threads_count);
#endif
/* Do not touch sandbox state after adding to the completion queue to avoid use-after-free bugs */
local_completion_queue_add(sandbox);
@ -759,8 +776,10 @@ sandbox_set_as_complete(struct sandbox *sandbox, sandbox_state_t last_state)
uint32_t duration_of_last_state = now - sandbox->last_state_change_timestamp;
sandbox->state = SANDBOX_SET_AS_COMPLETE;
#ifdef LOG_STATE_CHANGES
debuglog("Sandbox %lu | %s => Complete\n", sandbox->request_arrival_timestamp,
sandbox_state_stringify(last_state));
#endif
switch (last_state) {
case SANDBOX_RETURNED: {
@ -785,9 +804,13 @@ sandbox_set_as_complete(struct sandbox *sandbox, sandbox_state_t last_state)
runtime_admitted -= sandbox->admissions_estimate;
#ifdef LOG_ADMISSIONS_CONTROL
debuglog("Runtime Admitted: %f / %u\n", runtime_admitted, runtime_worker_threads_count);
#endif
#ifdef LOG_SANDBOX_PERF
sandbox_print_perf(sandbox);
#endif
/* Do not touch sandbox state after adding to the completion queue to avoid use-after-free bugs */
local_completion_queue_add(sandbox);

5
runtime/src/software_interrupt.c
Unescape View File

@ -126,7 +126,10 @@ sigusr1_handler(siginfo_t *signal_info, ucontext_t *user_context, struct sandbox
assert(current_sandbox->ctxt.variant == ARCH_CONTEXT_VARIANT_SLOW);
software_interrupt_SIGUSR_count++;
debuglog("usr1:%d\n", software_interrupt_SIGUSR_count);
#ifdef LOG_PREEMPTION
debuglog("Total SIGUSR1 Received: %d\n", software_interrupt_SIGUSR_count);
#endif
arch_mcontext_restore(&user_context->uc_mcontext, &current_sandbox->ctxt);

8
runtime/src/worker_thread.c
Unescape View File

@ -47,10 +47,12 @@ static inline void
worker_thread_dump_lock_overhead()
{
#ifdef DEBUG
#ifdef LOG_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
#endif
}
/**
@ -100,9 +102,11 @@ worker_thread_switch_to_sandbox(struct sandbox *next_sandbox)
sandbox_set_as_running(next_sandbox, next_sandbox->state);
#ifdef LOG_CONTEXT_SWITCHES
debuglog("Base Context (%s) > Sandbox %lu (%s)\n",
arch_context_variant_print(worker_thread_base_context.variant),
next_sandbox->request_arrival_timestamp, arch_context_variant_print(next_context->variant));
#endif
arch_context_switch(NULL, next_context);
} else {
@ -115,8 +119,10 @@ worker_thread_switch_to_sandbox(struct sandbox *next_sandbox)
struct arch_context *current_context = &current_sandbox->ctxt;
#ifdef LOG_CONTEXT_SWITCHES
debuglog("Sandbox %lu > Sandbox %lu\n", current_sandbox->request_arrival_timestamp,
next_sandbox->request_arrival_timestamp);
#endif
/* Switch to the associated context. */
arch_context_switch(current_context, next_context);
@ -143,9 +149,11 @@ worker_thread_switch_to_base_context()
current_sandbox_set(NULL);
#ifdef LOG_CONTEXT_SWITCHES
debuglog("Sandbox %lu (%s) > Base Context (%s)\n", current_sandbox->request_arrival_timestamp,
arch_context_variant_print(current_sandbox->ctxt.variant),
arch_context_variant_print(worker_thread_base_context.variant));
#endif
arch_context_switch(&current_sandbox->ctxt, &worker_thread_base_context);

Write Preview
Loading…
Cancel
Save