Merge pull request #182 from gwsystems/memory-profiling

feat: Basic memory profiling

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

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)
 {

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;
 }

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: