From 661748afe413fe0444956aa4b953a854e46e96e1 Mon Sep 17 00:00:00 2001 From: Sean McBride Date: Tue, 6 Apr 2021 18:39:30 -0400 Subject: [PATCH] feat: Basic memory profiling --- runtime/Makefile | 4 ++++ runtime/include/sandbox.h | 35 +++++++++++++++++++++++++++++++++- runtime/src/memory/64bit_nix.c | 10 ++++++++++ runtime/src/sandbox.c | 9 +++++++++ 4 files changed, 57 insertions(+), 1 deletion(-) diff --git a/runtime/Makefile b/runtime/Makefile index 29e7ea3..52ba746 100644 --- a/runtime/Makefile +++ b/runtime/Makefile @@ -40,6 +40,10 @@ CFLAGS += -DNDEBUG # CFLAGS += -DLOG_PREEMPTION # CFLAGS += -DLOG_MODULE_LOADING +# This dumps per module *.csv files containing the cycle a sandbox has been in RUNNING when each +# page is allocated. This helps understand the relationship to memory allocation and execution time. +# CFLAGS += -DLOG_SANDBOX_MEMORY_PROFILE + # This flag dumps totals of incoming requests and outgoing responses, broken out by status code # family, such as 2XX, 4XX, 5XX. It is useful to debug clients hanging waiting for a response. # To log, run `call http_total_log()` while in GDB diff --git a/runtime/include/sandbox.h b/runtime/include/sandbox.h index b44a2e2..885cb32 100644 --- a/runtime/include/sandbox.h +++ b/runtime/include/sandbox.h @@ -18,6 +18,10 @@ #define SANDBOX_MAX_IO_HANDLE_COUNT 32 #define SANDBOX_MAX_MEMORY (1L << 32) /* 4GB */ +#ifdef LOG_SANDBOX_MEMORY_PROFILE +#define SANDBOX_PAGE_ALLOCATION_TIMESTAMP_COUNT 1024 +#endif + /********************* * Structs and Types * ********************/ @@ -46,7 +50,10 @@ struct sandbox { uint64_t response_timestamp; /* Timestamp when response is sent */ uint64_t completion_timestamp; /* Timestamp when sandbox runs to completion */ uint64_t last_state_change_timestamp; /* Used for bookkeeping of actual execution time */ - +#ifdef LOG_SANDBOX_MEMORY_PROFILE + uint32_t page_allocation_timestamps[SANDBOX_PAGE_ALLOCATION_TIMESTAMP_COUNT]; + size_t page_allocation_timestamps_size; +#endif /* Duration of time (in cycles) that the sandbox is in each state */ uint64_t initializing_duration; uint64_t runnable_duration; @@ -256,6 +263,32 @@ sandbox_print_perf(struct sandbox *sandbox) running_us, blocked_us, returned_us, sandbox->linear_memory_size); } +static inline void +sandbox_summarize_page_allocations(struct sandbox *sandbox) +{ +#ifdef LOG_SANDBOX_MEMORY_PROFILE + // TODO: Handle interleavings + char sandbox_page_allocations_log_path[100] = {}; + sandbox_page_allocations_log_path[99] = '\0'; + snprintf(sandbox_page_allocations_log_path, 99, "%s_%d_page_allocations.csv", sandbox->module->name, + sandbox->module->port); + + debuglog("Logging to %s", sandbox_page_allocations_log_path); + + FILE *sandbox_page_allocations_log = fopen(sandbox_page_allocations_log_path, "a"); + + fprintf(sandbox_page_allocations_log, "%lu,%lu,%s", sandbox->id, sandbox->running_duration, + sandbox_state_stringify(sandbox->state)); + for (size_t i = 0; i < sandbox->page_allocation_timestamps_size; i++) + fprintf(sandbox_page_allocations_log, "%u,", sandbox->page_allocation_timestamps[i]); + + fprintf(sandbox_page_allocations_log, "\n"); +#else + return; +#endif +} + + static inline void sandbox_close_http(struct sandbox *sandbox) { diff --git a/runtime/src/memory/64bit_nix.c b/runtime/src/memory/64bit_nix.c index 0b8a312..7d2233d 100644 --- a/runtime/src/memory/64bit_nix.c +++ b/runtime/src/memory/64bit_nix.c @@ -30,6 +30,7 @@ expand_memory(void) // FIXME: max_pages = 0 => no limit. Issue #103. assert((sandbox->sandbox_size + local_sandbox_context_cache.linear_memory_size) / WASM_PAGE_SIZE < WASM_MAX_PAGES); + assert(sandbox->state = SANDBOX_RUNNING); // Remap the relevant wasm page to readable char *mem_as_chars = local_sandbox_context_cache.linear_memory_start; char *page_address = &mem_as_chars[local_sandbox_context_cache.linear_memory_size]; @@ -43,6 +44,15 @@ expand_memory(void) panic("expand_memory - Out of Memory!\n"); local_sandbox_context_cache.linear_memory_size += WASM_PAGE_SIZE; + +#ifdef LOG_SANDBOX_MEMORY_PROFILE + // Cache the runtime of the first N page allocations + if (likely(sandbox->page_allocation_timestamps_size < SANDBOX_PAGE_ALLOCATION_TIMESTAMP_COUNT)) { + sandbox->page_allocation_timestamps[sandbox->page_allocation_timestamps_size++] = + sandbox->running_duration + (uint32_t)(__getcycles() - sandbox->last_state_change_timestamp); + } +#endif + // local_sandbox_context_cache is "forked state", so update authoritative member sandbox->linear_memory_size = local_sandbox_context_cache.linear_memory_size; } diff --git a/runtime/src/sandbox.c b/runtime/src/sandbox.c index 3eff92d..a6fcd83 100644 --- a/runtime/src/sandbox.c +++ b/runtime/src/sandbox.c @@ -749,6 +749,9 @@ sandbox_set_as_error(struct sandbox *sandbox, sandbox_state_t last_state) uint64_t sandbox_id = sandbox->id; sandbox->state = SANDBOX_ERROR; sandbox_print_perf(sandbox); +#ifdef LOG_SANDBOX_MEMORY_PROFILE + sandbox_summarize_page_allocations(sandbox); +#endif sandbox_free_linear_memory(sandbox); admissions_control_substract(sandbox->admissions_estimate); /* Do not touch sandbox after adding to completion queue to avoid use-after-free bugs */ @@ -793,6 +796,9 @@ sandbox_set_as_complete(struct sandbox *sandbox, sandbox_state_t last_state) uint64_t sandbox_id = sandbox->id; sandbox->state = SANDBOX_COMPLETE; sandbox_print_perf(sandbox); +#ifdef LOG_SANDBOX_MEMORY_PROFILE + sandbox_summarize_page_allocations(sandbox); +#endif /* Admissions Control Post Processing */ admissions_info_update(&sandbox->module->admissions_info, sandbox->running_duration); admissions_control_substract(sandbox->admissions_estimate); @@ -852,6 +858,9 @@ err_stack_allocation_failed: */ sandbox->state = SANDBOX_SET_AS_INITIALIZED; sandbox->last_state_change_timestamp = now; +#ifdef LOG_SANDBOX_MEMORY_PROFILE + sandbox->page_allocation_timestamps_size = 0; +#endif ps_list_init_d(sandbox); err_memory_allocation_failed: err: