nijinlong1
/
sledge-1
forked from haiwan/sledge
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

chore: improved logging

Browse Source
main
Sean McBride 4 years ago
parent 465b820326
commit eca1546f7a
10 changed files with 54 additions and 64 deletions
Show Stats Download Patch File Download Diff File

1
runtime/include/libuv_callbacks.h
Unescape View File

@ -2,7 +2,6 @@
#include <assert.h> #include <assert.h>
#include <sys/mman.h> #include <sys/mman.h>
#include <pthread.h>
#include <signal.h> #include <signal.h>
#include <uv.h> #include <uv.h>

7
runtime/include/module.h
Unescape View File

@ -137,12 +137,11 @@ module_validate(struct module *module)
assert(!software_interrupt_is_enabled()); assert(!software_interrupt_is_enabled());
if (!module) { if (!module) {
panic("%lu | module %p | module is unexpectedly NULL\n", pthread_self(), module); panic("module %p | module is unexpectedly NULL\n", module);
} else if (!module->dynamic_library_handle) { } else if (!module->dynamic_library_handle) {
panic("%lu | module %p | module->dynamic_library_handle is unexpectedly NULL\n", pthread_self(), panic("module %p | module->dynamic_library_handle is unexpectedly NULL\n", module);
module);
} else if (!module->main) { } else if (!module->main) {
panic("%lu | module %p | module->main is unexpectedly NULL\n", pthread_self(), module); panic("module %p | module->main is unexpectedly NULL\n", module);
} }
} }

19
runtime/include/panic.h
Unescape View File

@ -1,16 +1,13 @@
#pragma once #pragma once
#include <assert.h> #include <assert.h>
#include <pthread.h>
#include <sched.h>
#include <stdio.h> #include <stdio.h>
#include <stdarg.h>
#include <stdlib.h>
__attribute__((noreturn, format(printf, 1, 2))) static inline void #define panic(fmt, ...) \
panic(const char *format, ...) { \
{ fprintf(stderr, "C: %02d, T: 0x%lx, F: %s> PANIC! \n\t" fmt "\n", sched_getcpu(), pthread_self(), \
va_list args; __func__, ##__VA_ARGS__); \
va_start(args, format); exit(EXIT_FAILURE); \
vfprintf(stderr, format, args); }
va_end(args);
assert(0);
}

8
runtime/include/sandbox.h
Unescape View File

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

3
runtime/include/sandbox_request.h
Unescape View File

@ -43,6 +43,7 @@ sandbox_request_allocate(struct module *module, char *arguments, int socket_desc
sandbox_request->absolute_deadline = request_arrival_timestamp sandbox_request->absolute_deadline = request_arrival_timestamp
+ module->relative_deadline_us * runtime_processor_speed_MHz; + module->relative_deadline_us * runtime_processor_speed_MHz;
debuglog("%s:%d @ %p\n", sandbox_request->module->name, sandbox_request->module->port, sandbox_request); debuglog("Allocating %lu of %s:%d\n", sandbox_request->request_arrival_timestamp, sandbox_request->module->name,
sandbox_request->module->port);
return sandbox_request; return sandbox_request;
} }

1
runtime/include/software_interrupt.h
Unescape View File

@ -2,6 +2,7 @@
#include <assert.h> #include <assert.h>
#include <panic.h> #include <panic.h>
#include <pthread.h>
#include <signal.h> #include <signal.h>
#include <stdbool.h> #include <stdbool.h>
#include <stdio.h> #include <stdio.h>

12
runtime/include/types.h
Unescape View File

@ -6,6 +6,7 @@
#include <limits.h> #include <limits.h>
#include <math.h> #include <math.h>
#include <printf.h> #include <printf.h>
#include <pthread.h>
#include <stdbool.h> #include <stdbool.h>
#include <stdlib.h> #include <stdlib.h>
#include <stdint.h> #include <stdint.h>
@ -89,12 +90,13 @@ typedef void (*mod_libc_fn_t)(int32_t, int32_t);
*/ */
#ifdef DEBUG #ifdef DEBUG
#ifdef LOG_TO_FILE #ifdef LOG_TO_FILE
#define debuglog(fmt, ...) \ #define debuglog(fmt, ...) \
dprintf(runtime_log_file_descriptor, "CPU: %02d, Thread: %x> %s: " fmt, sched_getcpu(), pthread_self(), \ dprintf(runtime_log_file_descriptor, "C: %02d, T: 0x%lx, F: %s> \n\t" fmt "\n", sched_getcpu(), \
__func__, ##__VA_ARGS__) pthread_self(), __func__, ##__VA_ARGS__);
#else /* !LOG_TO_FILE */ #else /* !LOG_TO_FILE */
#define debuglog(fmt, ...) \ #define debuglog(fmt, ...) \
printf("CPU: %02d, Thread: 0x%lx> %s: " fmt, sched_getcpu(), pthread_self(), __func__, ##__VA_ARGS__) fprintf(stderr, "C: %02d, T: 0x%lx, F: %s> \n\t" fmt "\n", sched_getcpu(), pthread_self(), __func__, \
##__VA_ARGS__);
#endif /* LOG_TO_FILE */ #endif /* LOG_TO_FILE */
#else /* !DEBUG */ #else /* !DEBUG */
#define debuglog(fmt, ...) #define debuglog(fmt, ...)

3
runtime/src/local_runqueue_list.c
Unescape View File

@ -71,7 +71,6 @@ local_runqueue_list_get_next()
assert(next_sandbox->state != SANDBOX_RETURNED); assert(next_sandbox->state != SANDBOX_RETURNED);
local_runqueue_add(next_sandbox); local_runqueue_add(next_sandbox);
debuglog("[%p: %s]\n", next_sandbox, next_sandbox->module->name);
return next_sandbox; return next_sandbox;
} }
@ -84,8 +83,6 @@ void
local_runqueue_list_append(struct sandbox *sandbox_to_append) local_runqueue_list_append(struct sandbox *sandbox_to_append)
{ {
assert(ps_list_singleton_d(sandbox_to_append)); assert(ps_list_singleton_d(sandbox_to_append));
debuglog("(%d,%lu) %s: run %p, %s\n", sched_getcpu(), pthread_self(), __func__, sandbox_to_append,
sandbox_to_append->module->name);
ps_list_head_append_d(&local_runqueue_list, sandbox_to_append); ps_list_head_append_d(&local_runqueue_list, sandbox_to_append);
} }

4
runtime/src/local_runqueue_minheap.c
Unescape View File

@ -55,8 +55,8 @@ local_runqueue_minheap_delete(struct sandbox *sandbox)
assert(sandbox != NULL); assert(sandbox != NULL);
int rc = priority_queue_delete(&local_runqueue_minheap, sandbox); int rc = priority_queue_delete(&local_runqueue_minheap, sandbox);
if (rc == -1) { if (rc == -1) {
panic("Err: Thread Local %lu tried to delete sandbox %lu from runqueue, but was not present\n", panic("Tried to delete sandbox %lu from runqueue, but was not present\n",
pthread_self(), sandbox->request_arrival_timestamp); sandbox->request_arrival_timestamp);
} }
} }

60
runtime/src/sandbox.c
Unescape View File

@ -192,9 +192,6 @@ sandbox_build_and_send_client_response(struct sandbox *sandbox)
sandbox->total_time = end_time - sandbox->request_arrival_timestamp; sandbox->total_time = end_time - sandbox->request_arrival_timestamp;
uint64_t total_time_us = sandbox->total_time / runtime_processor_speed_MHz; uint64_t total_time_us = sandbox->total_time / runtime_processor_speed_MHz;
debuglog("%s():%d, %u, %lu\n", sandbox->module->name, sandbox->module->port,
sandbox->module->relative_deadline_us, total_time_us);
#ifndef USE_HTTP_UVIO #ifndef USE_HTTP_UVIO
int r = send(sandbox->client_socket_descriptor, sandbox->request_response_data, response_cursor, 0); int r = send(sandbox->client_socket_descriptor, sandbox->request_response_data, response_cursor, 0);
if (r < 0) { if (r < 0) {
@ -387,6 +384,7 @@ sandbox_allocate_memory(struct module *module)
} }
/* Populate Sandbox members */ /* Populate Sandbox members */
sandbox->state = SANDBOX_UNINITIALIZED;
sandbox->linear_memory_start = (char *)addr + sandbox_size; sandbox->linear_memory_start = (char *)addr + sandbox_size;
sandbox->linear_memory_size = linear_memory_size; sandbox->linear_memory_size = linear_memory_size;
sandbox->linear_memory_max_size = linear_memory_max_size; sandbox->linear_memory_max_size = linear_memory_max_size;
@ -427,8 +425,7 @@ err_stack_allocation_failed:
} }
/** /**
* Transitions a sandbox to the SANDBOX_INITIALIZED state. Because this is the initial state of a new sandbox, we have * Transitions a sandbox to the SANDBOX_INITIALIZED state.
* to assume that sandbox->state is garbage.
* @param sandbox an uninitialized sandbox * @param sandbox an uninitialized sandbox
* @param sandbox_request the request we are initializing the sandbox from * @param sandbox_request the request we are initializing the sandbox from
* @param allocation_timestamp timestamp of allocation * @param allocation_timestamp timestamp of allocation
@ -448,7 +445,7 @@ sandbox_set_as_initialized(struct sandbox *sandbox, struct sandbox_request *sand
assert(allocation_timestamp > 0); assert(allocation_timestamp > 0);
debuglog("Thread %lu | Sandbox %lu | Uninitialized => Initialized\n", pthread_self(), allocation_timestamp); debuglog("Sandbox %lu | Uninitialized => Initialized\n", sandbox->request_arrival_timestamp);
sandbox->request_arrival_timestamp = sandbox_request->request_arrival_timestamp; sandbox->request_arrival_timestamp = sandbox_request->request_arrival_timestamp;
sandbox->allocation_timestamp = allocation_timestamp; sandbox->allocation_timestamp = allocation_timestamp;
@ -504,7 +501,7 @@ sandbox_set_as_runnable(struct sandbox *sandbox)
uint64_t duration_of_last_state = now - sandbox->last_state_change_timestamp; uint64_t duration_of_last_state = now - sandbox->last_state_change_timestamp;
sandbox_state_t last_state = sandbox->state; sandbox_state_t last_state = sandbox->state;
sandbox->state = SANDBOX_SET_AS_RUNNABLE; sandbox->state = SANDBOX_SET_AS_RUNNABLE;
debuglog("Thread %lu | Sandbox %lu | %s => Runnable\n", pthread_self(), sandbox->allocation_timestamp, debuglog("Sandbox %lu | %s => Runnable\n", sandbox->request_arrival_timestamp,
sandbox_state_stringify(last_state)); sandbox_state_stringify(last_state));
switch (last_state) { switch (last_state) {
@ -517,8 +514,8 @@ sandbox_set_as_runnable(struct sandbox *sandbox)
break; break;
} }
default: { default: {
panic("Thread %lu | Sandbox %lu | Illegal transition from %s to Runnable\n", pthread_self(), panic("Sandbox %lu | Illegal transition from %s to Runnable\n", sandbox->request_arrival_timestamp,
sandbox->allocation_timestamp, sandbox_state_stringify(last_state)); sandbox_state_stringify(last_state));
} }
} }
@ -549,7 +546,7 @@ sandbox_set_as_running(struct sandbox *sandbox)
sandbox_state_t last_state = sandbox->state; sandbox_state_t last_state = sandbox->state;
sandbox->state = SANDBOX_SET_AS_RUNNING; sandbox->state = SANDBOX_SET_AS_RUNNING;
debuglog("Thread %lu | Sandbox %lu | %s => Running\n", pthread_self(), sandbox->allocation_timestamp, debuglog("Sandbox %lu | %s => Running\n", sandbox->request_arrival_timestamp,
sandbox_state_stringify(last_state)); sandbox_state_stringify(last_state));
switch (last_state) { switch (last_state) {
@ -562,8 +559,8 @@ sandbox_set_as_running(struct sandbox *sandbox)
break; break;
} }
default: { default: {
panic("Thread %lu | Sandbox %lu | Illegal transition from %s to Running\n", pthread_self(), panic("Sandbox %lu | Illegal transition from %s to Running\n", sandbox->request_arrival_timestamp,
sandbox->allocation_timestamp, sandbox_state_stringify(last_state)); sandbox_state_stringify(last_state));
} }
} }
@ -590,7 +587,7 @@ sandbox_set_as_preempted(struct sandbox *sandbox)
uint64_t duration_of_last_state = now - sandbox->last_state_change_timestamp; uint64_t duration_of_last_state = now - sandbox->last_state_change_timestamp;
sandbox_state_t last_state = sandbox->state; sandbox_state_t last_state = sandbox->state;
sandbox->state = SANDBOX_SET_AS_PREEMPTED; sandbox->state = SANDBOX_SET_AS_PREEMPTED;
debuglog("Thread %lu | Sandbox %lu | %s => Preempted\n", pthread_self(), sandbox->allocation_timestamp, debuglog("Sandbox %lu | %s => Preempted\n", sandbox->request_arrival_timestamp,
sandbox_state_stringify(last_state)); sandbox_state_stringify(last_state));
switch (last_state) { switch (last_state) {
@ -599,8 +596,8 @@ sandbox_set_as_preempted(struct sandbox *sandbox)
break; break;
} }
default: { default: {
panic("Thread %lu | Sandbox %lu | Illegal transition from %s to Preempted\n", pthread_self(), panic("Sandbox %lu | Illegal transition from %s to Preempted\n", sandbox->request_arrival_timestamp,
sandbox->allocation_timestamp, sandbox_state_stringify(last_state)); sandbox_state_stringify(last_state));
} }
} }
@ -624,8 +621,7 @@ sandbox_set_as_blocked(struct sandbox *sandbox)
uint64_t duration_of_last_state = now - sandbox->last_state_change_timestamp; uint64_t duration_of_last_state = now - sandbox->last_state_change_timestamp;
sandbox_state_t last_state = sandbox->state; sandbox_state_t last_state = sandbox->state;
sandbox->state = SANDBOX_SET_AS_BLOCKED; sandbox->state = SANDBOX_SET_AS_BLOCKED;
debuglog("Thread %lu | Sandbox %lu | %s => Blocked\n", pthread_self(), sandbox->allocation_timestamp, debuglog("Sandbox %lu | %s => Blocked\n", sandbox->request_arrival_timestamp, sandbox_state_stringify(last_state));
sandbox_state_stringify(last_state));
switch (last_state) { switch (last_state) {
case SANDBOX_RUNNING: { case SANDBOX_RUNNING: {
@ -634,8 +630,8 @@ sandbox_set_as_blocked(struct sandbox *sandbox)
break; break;
} }
default: { default: {
panic("Thread %lu | Sandbox %lu | Illegal transition from %s to Blocked\n", pthread_self(), panic("Sandbox %lu | Illegal transition from %s to Blocked\n", sandbox->request_arrival_timestamp,
sandbox->allocation_timestamp, sandbox_state_stringify(last_state)); sandbox_state_stringify(last_state));
} }
} }
@ -660,8 +656,7 @@ sandbox_set_as_returned(struct sandbox *sandbox)
uint64_t duration_of_last_state = now - sandbox->last_state_change_timestamp; uint64_t duration_of_last_state = now - sandbox->last_state_change_timestamp;
sandbox_state_t last_state = sandbox->state; sandbox_state_t last_state = sandbox->state;
sandbox->state = SANDBOX_SET_AS_RETURNED; sandbox->state = SANDBOX_SET_AS_RETURNED;
debuglog("Thread %lu | Sandbox %lu | %s => Returned\n", pthread_self(), sandbox->allocation_timestamp, debuglog("Sandbox %lu | %s => Returned\n", sandbox->request_arrival_timestamp, sandbox_state_stringify(last_state));
sandbox_state_stringify(last_state));
switch (last_state) { switch (last_state) {
case SANDBOX_RUNNING: { case SANDBOX_RUNNING: {
@ -673,8 +668,8 @@ sandbox_set_as_returned(struct sandbox *sandbox)
break; break;
} }
default: { default: {
panic("Thread %lu | Sandbox %lu | Illegal transition from %s to Returned\n", pthread_self(), panic("Sandbox %lu | Illegal transition from %s to Returned\n", sandbox->request_arrival_timestamp,
sandbox->allocation_timestamp, sandbox_state_stringify(last_state)); sandbox_state_stringify(last_state));
} }
} }
@ -700,8 +695,7 @@ sandbox_set_as_error(struct sandbox *sandbox)
uint64_t duration_of_last_state = now - sandbox->last_state_change_timestamp; uint64_t duration_of_last_state = now - sandbox->last_state_change_timestamp;
sandbox_state_t last_state = sandbox->state; sandbox_state_t last_state = sandbox->state;
sandbox->state = SANDBOX_SET_AS_ERROR; sandbox->state = SANDBOX_SET_AS_ERROR;
debuglog("Thread %lu | Sandbox %lu | %s => Error\n", pthread_self(), sandbox->allocation_timestamp, debuglog("Sandbox %lu | %s => Error\n", sandbox->request_arrival_timestamp, sandbox_state_stringify(last_state));
sandbox_state_stringify(last_state));
switch (last_state) { switch (last_state) {
case SANDBOX_SET_AS_INITIALIZED: case SANDBOX_SET_AS_INITIALIZED:
@ -714,8 +708,8 @@ sandbox_set_as_error(struct sandbox *sandbox)
break; break;
} }
default: { default: {
panic("Thread %lu | Sandbox %lu | Illegal transition from %s to Error\n", pthread_self(), panic("Sandbox %lu | Illegal transition from %s to Error\n", sandbox->request_arrival_timestamp,
sandbox->allocation_timestamp, sandbox_state_stringify(last_state)); sandbox_state_stringify(last_state));
} }
} }
@ -742,7 +736,7 @@ sandbox_set_as_complete(struct sandbox *sandbox)
uint64_t duration_of_last_state = now - sandbox->last_state_change_timestamp; uint64_t duration_of_last_state = now - sandbox->last_state_change_timestamp;
sandbox_state_t last_state = sandbox->state; sandbox_state_t last_state = sandbox->state;
sandbox->state = SANDBOX_SET_AS_COMPLETE; sandbox->state = SANDBOX_SET_AS_COMPLETE;
debuglog("Thread %lu | Sandbox %lu | %s => Complete\n", pthread_self(), sandbox->allocation_timestamp, debuglog("Sandbox %lu | %s => Complete\n", sandbox->request_arrival_timestamp,
sandbox_state_stringify(last_state)); sandbox_state_stringify(last_state));
switch (last_state) { switch (last_state) {
@ -752,8 +746,8 @@ sandbox_set_as_complete(struct sandbox *sandbox)
break; break;
} }
default: { default: {
panic("Thread %lu | Sandbox %lu | Illegal transition from %s to Error\n", pthread_self(), panic("Sandbox %lu | Illegal transition from %s to Error\n", sandbox->request_arrival_timestamp,
sandbox->allocation_timestamp, sandbox_state_stringify(last_state)); sandbox_state_stringify(last_state));
} }
} }
@ -857,7 +851,7 @@ sandbox_free(struct sandbox *sandbox)
errno = 0; errno = 0;
rc = munmap(stkaddr, stksz); rc = munmap(stkaddr, stksz);
if (rc == -1) { if (rc == -1) {
fprintf(stderr, "Thread %lu | Failed to unmap stack %p\n", pthread_self(), sandbox); debuglog("Failed to unmap stack of Sandbox %lu\n", sandbox->request_arrival_timestamp);
goto err_free_stack_failed; goto err_free_stack_failed;
}; };
@ -871,7 +865,7 @@ sandbox_free(struct sandbox *sandbox)
errno = 0; errno = 0;
rc = munmap(sandbox, sandbox_address_space_size); rc = munmap(sandbox, sandbox_address_space_size);
if (rc == -1) { if (rc == -1) {
fprintf(stderr, "Thread %lu | Failed to unmap sanbox %p\n", pthread_self(), sandbox); debuglog("Failed to unmap Sandbox %lu\n", sandbox->request_arrival_timestamp);
goto err_free_sandbox_failed; goto err_free_sandbox_failed;
}; };
@ -881,5 +875,5 @@ err_free_sandbox_failed:
err_free_stack_failed: err_free_stack_failed:
err: err:
/* Errors freeing memory is a fatal error */ /* Errors freeing memory is a fatal error */
panic("Thread %lu | Failed to free sandbox %p\n", pthread_self(), sandbox); panic("Failed to free Sandbox %lu\n", sandbox->request_arrival_timestamp);
} }

Write Preview
Loading…
Cancel
Save