profiling to kcachegrind format, with callers and call counts

Author: braindigitalis

include/kernel.h

@@ -81,8 +81,16 @@ void validate_limine_page_tables_and_gdt(void);
 		uint64_t calls;
 	} profile_entry;
 
-	#define PROFILE_MAX_FUNCS   8192
+	typedef struct profile_edge {
+		void *parent;
+		void *child;
+		uint64_t calls;
+		uint64_t total_cycles;
+	} profile_edge;
+
+	#define PROFILE_MAX_FUNCS 8192
+	#define PROFILE_MAX_EDGES 32768
 
 	void profile_dump(void);
-	void profile_init(uint8_t* pre_allocated);
+	void profile_init(uint8_t* pre_allocated_funcs, uint8_t* pre_allocated_edges);
 #endif

src/init.c

@@ -38,7 +38,7 @@ void init()
 	kprintf("THIS IS A PROFILING BUILD - Expect things to run slower!\n");
 	setforeground(current_console, COLOUR_WHITE);
 	serial_init(COM1);
-	profile_init(kmalloc(sizeof(profile_entry) * PROFILE_MAX_FUNCS));
+	profile_init(kmalloc(sizeof(profile_entry) * PROFILE_MAX_FUNCS), kmalloc(sizeof(profile_edge) * PROFILE_MAX_EDGES));
 	dprintf("Initialising profiler done!\n");
 #endif
 

src/keyboard.c

@@ -270,8 +270,9 @@ bool caps_lock_on()
 static void push_to_buffer(char x) {
 #ifdef PROFILE_KERNEL
 	if (ctrl_held() && alt_held() && shift_held() && x == 'P') {
-		dprintf("Dumping callgrind.out to serial port...\n");
+		kprintf("\nDumping callgrind.out to serial port...\n");
 		profile_dump();
+		kprintf("Profile written.\n");
 		return;
 	}
 #endif

src/profiler.c

@@ -6,20 +6,24 @@
 
 const char* findsymbol(uint64_t address, uint64_t* offset) __attribute__((no_instrument_function));
 
-static struct profile_entry* profile_table = NULL;
+static profile_entry* profile_table = NULL;
 static size_t profile_entry_count = 0;
 
+static profile_edge* edge_table = NULL;
+static size_t edge_count = 0;
+
 struct call_frame {
 	void *fn;
 	uint64_t enter_time;
 };
 static struct call_frame call_stack[PROFILE_STACK_DEPTH];
 static int call_sp = 0;
 
-static struct profile_entry *profile_find_or_add(void *fn) __attribute__((no_instrument_function));
+static profile_entry *profile_find_or_add(void *fn) __attribute__((no_instrument_function));
+static profile_edge *edge_find_or_add(void *parent, void *child) __attribute__((no_instrument_function));
 
-/* Find existing entry or allocate a new one */
-static struct profile_entry *profile_find_or_add(void *fn) {
+/* Find or add a function entry */
+static profile_entry *profile_find_or_add(void *fn) {
 	for (size_t i = 0; i < profile_entry_count; i++) {
 		if (profile_table[i].fn == fn) {
 			return &profile_table[i];
@@ -35,15 +39,41 @@ static struct profile_entry *profile_find_or_add(void *fn) {
 	return NULL; // out of slots
 }
 
-/* Called at kernel startup */
-__attribute__((no_instrument_function)) void profile_init(uint8_t* pre_allocated) {
-	profile_table = (profile_entry*)pre_allocated;
+/* Find or add an edge */
+static profile_edge *edge_find_or_add(void *parent, void *child) {
+	for (size_t i = 0; i < edge_count; i++) {
+		if (edge_table[i].parent == parent && edge_table[i].child == child) {
+			return &edge_table[i];
+		}
+	}
+	if (edge_count < PROFILE_MAX_EDGES) {
+		profile_edge *e = &edge_table[edge_count++];
+		e->parent = parent;
+		e->child = child;
+		e->calls = 0;
+		e->total_cycles = 0;
+		return e;
+	}
+	return NULL;
+}
+
+/* Called at kernel startup: caller allocates memory for profile + edge tables */
+__attribute__((no_instrument_function)) void profile_init(uint8_t* pre_allocated_funcs, uint8_t* pre_allocated_edges) {
+	profile_table = (profile_entry*)pre_allocated_funcs;
+	edge_table = (profile_edge*)pre_allocated_edges;
+	/* Intentionally NOT using memcpy here, as it is profiled */
 	if (profile_table) {
 		for (uint64_t n = 0; n < sizeof(profile_entry) * PROFILE_MAX_FUNCS; ++n) {
-			pre_allocated[n] = 0;
+			pre_allocated_funcs[n] = 0;
 		}
 		profile_entry_count = 0;
 	}
+	if (edge_table) {
+		for (uint64_t n = 0; n < sizeof(profile_edge) * PROFILE_MAX_EDGES; ++n) {
+			pre_allocated_edges[n] = 0;
+		}
+		edge_count = 0;
+	}
 }
 
 __attribute__((no_instrument_function)) void __cyg_profile_func_enter(void *this_fn, void *call_site) {
@@ -52,6 +82,14 @@ __attribute__((no_instrument_function)) void __cyg_profile_func_enter(void *this
 	}
 	uint64_t t = rdtsc();
 	if (call_sp < PROFILE_STACK_DEPTH) {
+		/* record edge from parent -> this_fn */
+		if (call_sp > 0) {
+			void *parent = call_stack[call_sp - 1].fn;
+			profile_edge *edge = edge_find_or_add(parent, this_fn);
+			if (edge) {
+				edge->calls++;
+			}
+		}
 		call_stack[call_sp].fn = this_fn;
 		call_stack[call_sp].enter_time = t;
 		call_sp++;
@@ -69,8 +107,17 @@ __attribute__((no_instrument_function)) void __cyg_profile_func_exit(void *this_
 		uint64_t enter = call_stack[call_sp].enter_time;
 		profile_entry *e = profile_find_or_add(fn);
 		if (e) {
-			e->total_cycles += (t - enter);
+			uint64_t delta = (t - enter);
+			e->total_cycles += delta;
 			e->calls++;
+			/* attribute to parent edge as well */
+			if (call_sp > 0) {
+				void *parent = call_stack[call_sp - 1].fn;
+				profile_edge *edge = edge_find_or_add(parent, fn);
+				if (edge) {
+					edge->total_cycles += delta;
+				}
+			}
 		}
 	}
 }
@@ -82,21 +129,32 @@ __attribute__((no_instrument_function)) void profile_dump(void) {
 	}
 	serial_printf(COM1, "version: 1\n");
 	serial_printf(COM1, "creator: RetroRocketProfiler\n");
-	serial_printf(COM1, "events: Cycles\n");
+	serial_printf(COM1, "events: Cycles\n\n");
 
 	for (size_t i = 0; i < profile_entry_count; i++) {
 		profile_entry *e = &profile_table[i];
-		if (!e->fn) {
-			continue;
-		}
+		if (!e->fn) continue;
+
 		uint64_t offset;
-		const char *name = findsymbol((uint64_t) e->fn, &offset);
-		if (!name) {
-			serial_printf(COM1, "fn=0x%p\n", e->fn);
-		} else {
-			serial_printf(COM1, "fn=%s\n", name);
+		const char *name = findsymbol((uint64_t)e->fn, &offset);
+		serial_printf(COM1, "fn=%s\n", name ? name : "unknown");
+
+		// function self-cost
+		serial_printf(COM1, "1 %llu\n", (unsigned long long)e->total_cycles);
+
+		// child edges
+		for (size_t j = 0; j < edge_count; j++) {
+			profile_edge *edge = &edge_table[j];
+			if (edge->parent == e->fn) {
+				const char *cname = findsymbol((uint64_t)edge->child, &offset);
+				serial_printf(COM1, "cfn=%s\n", cname ? cname : "unknown");
+				serial_printf(COM1, "calls=%llu 1\n", (unsigned long long)edge->calls);
+				serial_printf(COM1, "1 %llu\n", (unsigned long long)edge->total_cycles);
+			}
 		}
-		serial_printf(COM1, "1 %lu\n", (uint64_t) (e->total_cycles));
+
+		// terminate block
+		serial_printf(COM1, "\n");
 	}
 }