kernel: profiling infrastructure

.gitignore

@@ -28,8 +28,11 @@ tools/init/reboot
 tools/init/reboot.o
 tools/init/acpid
 tools/init/acpid.o
+tools/prof/astral-prof
+tools/prof/main.o
 initrds
 hdd.img
 netdump.dat
 build-*
 graph_kernel_deps.png
+profiler.out

kernel-src/arch/x86-64/apic.c

@@ -129,6 +129,10 @@ static void writeiored(void *ioapic, uint8_t entry, uint8_t vector, uint8_t deli
 	writeioapic(ioapic, 0x11 + entry * 2, (uint32_t)dest << 24);
 }
 
+void arch_apic_init_perf(void) {
+	writelapic(APIC_LVT_PERFORMANCE, LVT_DELIVERY_NMI);
+}
+
 void arch_ioapic_setirq(uint8_t irq, uint8_t vector, uint8_t proc, bool masked) {
 	// default settings for ISA irqs
 	uint8_t polarity = 1; // active high

kernel-src/arch/x86-64/arch_prof.c

@@ -0,0 +1,144 @@
+#include <kernel/init.h>
+#include <string.h>
+#include <arch/cpu.h>
+#include <arch/cpuid.h>
+#include <kernel/prof.h>
+#include <logging.h>
+
+#ifdef ENABLE_PROFILING
+
+#define INTEL_TSC_INDEX 2
+#define INTEL_TSC_INDEX_OFFSET (1lu << 34)
+#define INTEL_TSC_FIXED_CTR_CTRL_OFFSET 8
+#define INTEL_TSC_FIXED_CTR_CTRL_ENABLE (1 << (11))
+#define INTEL_PERF_FIXED_CTR_CTRL_USER 1
+#define INTEL_PERF_FIXED_CTR_CTRL_SUPERVISOR 2
+
+#define TICK_COUNT 3200000
+
+static int intel_get_max_size(void) {
+	cpuid_results_t cpuid_results;
+	cpuid(0xa, &cpuid_results);
+	return 1 << ((cpuid_results.eax >> 16) & 0xff);
+}
+
+static int intel_get_version(void) {
+	cpuid_results_t cpuid_results;
+	cpuid(0xa, &cpuid_results);
+	return cpuid_results.eax & 0xff;
+}
+
+static bool intel_check_tsc_fixed(void) {
+	cpuid_results_t cpuid_results;
+	cpuid(0xa, &cpuid_results);
+
+	int fixed_count = cpuid_results.edx & 0x1f;
+	return fixed_count > INTEL_TSC_INDEX;
+}
+
+static void reset_intel_pmc(void) {
+	// disable PMCs
+	wrmsr(MSR_PERF_FIXED_CTR_CTRL, 0);
+
+	// clear overflow
+	wrmsr(MSR_PERF_GLOBAL_OVF_CTRL, INTEL_TSC_INDEX_OFFSET);
+
+	// program PMC
+	wrmsr(MSR_PERF_FIXED_CTR2, intel_get_max_size() - TICK_COUNT);
+
+	// enable the PMC
+	wrmsr(MSR_PERF_FIXED_CTR_CTRL,
+		((INTEL_PERF_FIXED_CTR_CTRL_USER | INTEL_PERF_FIXED_CTR_CTRL_SUPERVISOR) << INTEL_TSC_FIXED_CTR_CTRL_OFFSET) |
+		INTEL_TSC_FIXED_CTR_CTRL_ENABLE);
+}
+
+static void init_intel_pmc(void) {
+	// check for version 2 PMC
+	if (intel_get_version() < 2) {
+		__assert(!"Profiling is not supported on Intel CPUs without at least a version 2 PMC. Recompile without profiling.");
+	}
+
+	// check for support for the tsc fixed counter
+	__assert(intel_check_tsc_fixed());
+
+	// enable fixed PMC
+	wrmsr(MSR_PERF_GLOBAL_CTRL, rdmsr(MSR_PERF_GLOBAL_CTRL) | INTEL_TSC_INDEX_OFFSET);
+
+	reset_intel_pmc();
+	arch_apic_init_perf();
+}
+
+static uint8_t get_backtrace(context_t *context, uintptr_t *data) {
+	if (IS_USER_ADDRESS(context->rip))
+		return 0;
+
+	uint64_t *rbp = (uint64_t *)context->rbp;
+	uint8_t done = 0;
+
+	for (;;) {
+		if (IS_USER_ADDRESS(rbp) || done == 255)
+			break;
+
+		uint64_t rip = *(rbp + 1);
+		if (IS_USER_ADDRESS(rip))
+			break;
+
+		data[done++] = rip;
+		rbp = (uint64_t *)*rbp;
+	}
+
+	return done;
+}
+
+static bool intel_irq(context_t *context) {
+	if ((rdmsr(MSR_PERF_GLOBAL_STATUS) & INTEL_TSC_INDEX_OFFSET) == 0)
+		return false;
+
+	uint8_t data[1 + sizeof(uintptr_t) * 256];
+
+	uint8_t size = get_backtrace(context, (uintptr_t *)(data + 1));
+	if (size) {
+		*data = size;
+		profiling_insert(size, data);
+	}
+
+	arch_apic_init_perf(); // SDM LVT figure says a PMC irq masks itself, so unmask it
+	reset_intel_pmc();
+	return true;
+}
+
+static bool amd_irq(context_t *context) {
+	__assert(!"Unimplemented");
+}
+
+
+static void init_amd_pmc(void) {
+	__assert(!"Unimplemented");
+}
+
+
+
+bool arch_profiling_irq(context_t *context) {
+	if (!strcmp(current_cpu()->vendor, "AuthenticAMD"))
+		return amd_irq(context);
+	else if (!strcmp(current_cpu()->vendor, "GenuineIntel"))
+		return intel_irq(context);
+
+	__assert(!"unreachable");
+}
+
+
+void arch_profiling_init(void) {
+	arch_apic_init_perf();
+
+	if (!strcmp(current_cpu()->vendor, "AuthenticAMD"))
+		init_amd_pmc();
+	else if (!strcmp(current_cpu()->vendor, "GenuineIntel"))
+		init_intel_pmc();
+	else
+		printf("arch_prof: no PMC for this vendor\n");
+}
+
+INIT_ROUTINE_DEFINE(arch_profiling, INIT_ROUTINE_FLAGS_NONE, arch_profiling_init, profiling, cpu);
+
+#endif

kernel-src/arch/x86-64/smp.c

@@ -49,6 +49,10 @@ static void cpuwakeup(struct limine_smp_info *info) {
 	
 	timekeeper_init();
 
+#ifdef ENABLE_PROFILING
+	arch_profiling_init();
+#endif
+
 	__atomic_add_fetch(&arch_smp_cpusawake, 1, __ATOMIC_SEQ_CST);
 	sched_ap_entry();
 }

kernel-src/include/kernel/devfs.h

@@ -20,6 +20,7 @@
 #define DEV_MAJOR_MOUSE 11
 #define DEV_MAJOR_PTY 12
 #define DEV_MAJOR_ACPI 13
+#define DEV_MAJOR_PROF 14
 
 typedef struct {
 	int (*open)(int minor, vnode_t **vnode, int flags);

kernel-src/include/kernel/prof.h

@@ -0,0 +1,6 @@
+#ifndef _PROF_H
+#define _PROF_H
+
+void profiling_insert(uint8_t size, void *data);
+
+#endif

kernel-src/include/x86-64/arch/apic.h

@@ -7,6 +7,7 @@ void arch_apic_timerinit();
 void arch_apic_init();
 void arch_apic_initap();
 void arch_apic_eoi();
+void arch_apic_init_perf(void);
 void arch_ioapic_setirq(uint8_t gsi, uint8_t vector, uint8_t proc, bool masked);
 void arch_apic_sendipi(uint8_t cpu, uint8_t vec, uint8_t dest, uint8_t mode, uint8_t level);
 

kernel-src/include/x86-64/arch/cpu.h

@@ -13,6 +13,7 @@
 #include <kernel/dpc.h>
 #include <arch/apic.h>
 #include <kernel/timekeeper.h>
+#include <ringbuffer.h>
 
 #define ARCH_EOI arch_apic_eoi
 
@@ -68,6 +69,10 @@ typedef struct cpu_t {
 	spinlock_t shootdown_lock;
 	int *shootdown_done;
 
+#ifdef ENABLE_PROFILING
+	ringbuffer_t *prof_ringbuffer;
+#endif
+
 	// architecture specific, does not need to be exposed
 
 	uint64_t gdt[7];

kernel-src/include/x86-64/arch/msr.h

@@ -4,6 +4,11 @@
 #include <stdint.h>
 
 #define MSR_IA32APICBASE 0x1B
+#define MSR_PERF_FIXED_CTR2 0x30b
+#define MSR_PERF_FIXED_CTR_CTRL 0x38d
+#define MSR_PERF_GLOBAL_STATUS 0x38e
+#define MSR_PERF_GLOBAL_CTRL 0x38f
+#define MSR_PERF_GLOBAL_OVF_CTRL 0x390
 #define MSR_EFER 0xC0000080
 #define MSR_STAR 0xC0000081
 #define MSR_LSTAR 0xC0000082

kernel-src/include/x86-64/arch/prof.h

@@ -0,0 +1,9 @@
+#ifndef ARCH_PROF_H
+#define ARCH_PROF_H
+
+#include <arch/context.h>
+#include <stdbool.h>
+
+bool arch_profiling_irq(context_t *ctx);
+
+#endif

kernel-src/sys/prof.c

@@ -0,0 +1,197 @@
+#include <kernel/init.h>
+#include <kernel/devfs.h>
+#include <mutex.h>
+#include <ringbuffer.h>
+#include <semaphore.h>
+#include <kernel/thread.h>
+#include <kernel/scheduler.h>
+#include <kernel/vfs.h>
+#include <arch/smp.h>
+#include <logging.h>
+
+#ifdef ENABLE_PROFILING
+
+#define PROFILING_GLOBAL_BUFFER_SIZE (256 * 1024)
+#define PROFILING_PRIVATE_BUFFER_SIZE (256 * 1024) // the size of each cpu's private ring buffer
+
+static ringbuffer_t global_ringbuffer;
+static MUTEX_DEFINE(mutex);
+static pollheader_t pollheader;
+static semaphore_t wait_sem;
+static int remaining;
+
+// called from a possibly NMI context!
+void profiling_insert(uint8_t size, void *data) {
+	size_t write_size = sizeof(uint8_t) + sizeof(uintptr_t) * size;
+	if (current_cpu()->prof_ringbuffer && RINGBUFFER_FREESPACE(current_cpu()->prof_ringbuffer) >= write_size) {
+		size_t written = ringbuffer_write(current_cpu()->prof_ringbuffer, data, write_size);
+		if (write_size != written) for (;;);
+	}
+}
+
+static void profiling_thread() {
+	// this will be shared between the cpu and this thread
+	ringbuffer_t ringbuffer;
+	cpu_t *cpu = current_thread()->kernelarg;
+	__assert(ringbuffer_init(&ringbuffer, PROFILING_PRIVATE_BUFFER_SIZE) == 0);
+	sched_target_cpu(cpu);
+	cpu->prof_ringbuffer = &ringbuffer;
+
+	if (__atomic_sub_fetch(&remaining, 1, __ATOMIC_SEQ_CST) == 0)
+		semaphore_signal(&wait_sem);
+
+	for (;;) {
+		// profiling uses a NMI, which means that the handler cannot call into the scheduler
+		// without the possibility of a deadlock. for this reason, this thread will sleep for a set
+		// amount of time and only wake up to insert the data into a more reasonable place.
+		// by default, sleep for 10 ms
+		sched_sleep_us(10000);
+
+		MUTEX_ACQUIRE(&mutex);
+
+		int read = 0;
+
+		for (;;) {
+			uint8_t data[1 + sizeof(uintptr_t) * 256];
+			size_t read_count = ringbuffer_read(&ringbuffer, data, 1);
+			if (read_count == 0)
+				break;
+
+			read_count = ringbuffer_read(&ringbuffer, data + 1, data[0] * sizeof(uintptr_t));
+			__assert(read_count == data[0] * sizeof(uintptr_t));
+			size_t write_size = 1 + data[0] * sizeof(uintptr_t);
+
+			if (RINGBUFFER_FREESPACE(&global_ringbuffer) >= write_size) {
+				size_t written = ringbuffer_write(&global_ringbuffer, data, write_size);
+				__assert(write_size == written);
+				read = 1;
+			}
+
+		}
+
+		if (read)
+			poll_event(&pollheader, POLLIN);
+
+		MUTEX_RELEASE(&mutex);
+	}
+}
+
+static int internal_poll(polldata_t *data, int events) {
+	int revents = 0;
+
+	if (events & POLLOUT)
+		revents |= POLLERR;
+
+	if ((events & POLLIN) && RINGBUFFER_DATACOUNT(&global_ringbuffer))
+		revents |= POLLIN;
+
+	if (revents == 0 && data)
+		poll_add(&pollheader, data, events);
+
+	return revents;
+}
+
+static int device_poll(int minor, polldata_t *data, int events) {
+	(void)minor;
+	MUTEX_ACQUIRE(&mutex);
+
+	int revents = internal_poll(data, events);
+
+	MUTEX_RELEASE(&mutex);
+
+	return revents;
+}
+
+static int device_read(int minor, iovec_iterator_t *iovec_iterator, size_t size, uintmax_t offset, int flags, size_t *readc) {
+	(void)minor;
+	if (unlikely(size == 0)) {
+		*readc = 0;
+		return 0;
+	}
+
+	polldesc_t desc;
+	int error = poll_initdesc(&desc, 1);
+	if (error)
+		return error;
+
+	MUTEX_ACQUIRE(&mutex);
+
+	for (;;) {
+		int revents = internal_poll(&desc.data[0], POLLIN);
+		if (revents)
+			break;
+
+		if (flags & V_FFLAGS_NONBLOCKING) {
+			error = EAGAIN;
+			goto leave;
+		}
+
+		MUTEX_RELEASE(&mutex);
+		error = poll_dowait(&desc, 0);
+
+		if (error)
+			goto leave_nolock;
+		poll_leave(&desc);
+		MUTEX_ACQUIRE(&mutex);
+	}
+
+	*readc = iovec_iterator_read_from_ringbuffer(iovec_iterator, &global_ringbuffer, size);
+	if (*readc == RINGBUFFER_USER_COPY_FAILED)
+		error = EFAULT;
+
+	__assert(*readc);
+
+	leave:
+	MUTEX_RELEASE(&mutex);
+	leave_nolock:
+	poll_leave(&desc);
+	poll_destroydesc(&desc);
+	return error;
+}
+
+static int device_ioctl(int, unsigned long request, void *, int *result, cred_t *cred) {
+	if (request != 12345678)
+		return ENOTTY;
+
+	// only supported ioctl is a truncation one: remove all previous data
+
+	MUTEX_ACQUIRE(&mutex);
+
+	ringbuffer_truncate(&global_ringbuffer, PROFILING_GLOBAL_BUFFER_SIZE);
+
+	MUTEX_RELEASE(&mutex);
+
+	*result = 0;
+	return 0;
+}
+
+static devops_t devops = {
+	.read = device_read,
+	.poll = device_poll,
+	.ioctl = device_ioctl
+};
+
+static void profiling_init() {
+	// initialize global profiling data
+	POLL_INITHEADER(&pollheader);
+	__assert(ringbuffer_init(&global_ringbuffer, PROFILING_GLOBAL_BUFFER_SIZE) == 0);
+	__assert(devfs_register(&devops, "prof", V_TYPE_CHDEV, DEV_MAJOR_PROF, 0, 0400, NULL) == 0);
+
+	// start a thread for each cpu
+	SEMAPHORE_INIT(&wait_sem, 0);
+	remaining = arch_smp_cpusawake;
+
+	for (int i = 0; i < arch_smp_cpusawake; ++i) {
+		thread_t *thread = sched_newthread(profiling_thread, PAGE_SIZE * 2, -100, NULL, NULL);
+		__assert(thread);
+
+		thread->kernelarg = smp_cpus[i];
+		sched_queue(thread);
+	}
+
+	semaphore_wait(&wait_sem, false);
+}
+
+INIT_ROUTINE_DEFINE(profiling, INIT_ROUTINE_FLAGS_NONE, profiling_init, devfs, smp);
+
+#endif

prof/.gitignore

@@ -0,0 +1 @@
+flamegraph.pl

prof/prof.py

@@ -0,0 +1,102 @@
+#!/usr/bin/env python3
+
+# This script takes data generated by the profiler in Astral and creates a flamegraph out of it.
+# Format of the profiler file:
+# 1 byte indicating the number of calls in the backtrace
+# 8-byte Pointers starting by deepest call in the stack
+# Repeat until EOF
+
+import sys
+import os
+import subprocess
+
+if len(sys.argv) != 3:
+    print(sys.argv[0] + ": usage: " + sys.argv[0] + " INPUT_FILE OUTPUT_FILE")
+    exit(1)
+
+# Open needed files
+in_file = open(sys.argv[1], "rb")
+out_file = open(sys.argv[2], "w")
+
+# Download the flamegraph script if nescessary
+os.chdir(os.path.dirname(__file__))
+
+if not os.access("flamegraph.pl", os.R_OK):
+    os.system("wget https://raw.githubusercontent.com/brendangregg/FlameGraph/refs/heads/master/flamegraph.pl")
+    os.system("chmod +x flamegraph.pl")
+
+print("Starting subprocesses")
+# Start addr2line TODO: other architectures
+proc_a2l = subprocess.Popen(
+        ["addr2line", "-s", "-f", "-e", "../build-x86_64/iso/astral"],
+        stdin=subprocess.PIPE,
+        stdout=subprocess.PIPE,
+        text=True
+)
+
+# Start the flamegraph renderer
+proc_fg = subprocess.Popen(
+    ["./flamegraph.pl"],
+    stdin=subprocess.PIPE,
+    stdout=out_file,
+    text=True
+)
+
+traces = {}
+
+print("Getting function information")
+# get info out of addr2line
+while True:
+    backtrace_size = in_file.read(1)
+    if not backtrace_size:
+        # EOF
+        break
+
+    backtrace_size = int.from_bytes(backtrace_size, byteorder='little', signed=False)
+
+    # Send the addresses to addr2line
+    i = backtrace_size
+    while i > 0:
+        i -= 1
+
+        addr = in_file.read(8)
+        if not addr:
+            print(("Corrupted file (unexpected EOF, reading %d entries)" % (backtrace_size)), file=sys.stderr)
+            exit(1)
+
+        addr = hex(int.from_bytes(addr, byteorder='little', signed=False))
+
+        proc_a2l.stdin.write(addr + "\n")
+        proc_a2l.stdin.flush()
+
+    # Read back the lines from addr2line and format them in a way flamegraph expects
+    i = backtrace_size
+    formatted_str = ""
+    while i > 0:
+        i -= 1
+
+        function = proc_a2l.stdout.readline().replace('\n', '')
+        file, line = proc_a2l.stdout.readline().replace('\n', '').split(":")
+
+        formatted_str = file + "`" + function + ";" + formatted_str
+
+    formatted_str = formatted_str[:-1] # remove ;
+
+    if not formatted_str in traces:
+        traces[formatted_str] = 0
+
+    traces[formatted_str] += 1
+        
+proc_a2l.stdin.close()
+
+print("Generating flamegraph")
+# send the trace over to flamegraph
+for trace in traces:
+    final_string = trace + " " + str(traces[trace])
+    proc_fg.stdin.write(final_string + "\n")
+    proc_fg.stdin.flush()
+
+print("Waiting...");
+# wait until it is done with its thing
+proc_fg.stdin.close()
+proc_fg.wait()

prof/test

@@ -0,0 +1,2 @@
+pfisr
+mmu.c:338

recipes/prof

@@ -0,0 +1,14 @@
+name=prof
+revision=1
+from_source=prof
+imagedeps="build-essential"
+hostdeps="xbinutils xgcc"
+deps="base"
+
+build() {
+	make -C ${source_dir} -j ${parallelism}
+}
+
+package() {
+	make -C ${source_dir} install PREFIX=${prefix} DESTDIR=${dest_dir}
+}

source-recipes/prof

@@ -0,0 +1,7 @@
+name=prof
+version=0
+source_dir="tools/prof"
+
+prepare() {
+	true
+}

tools/init/main.c

@@ -343,11 +343,11 @@ int main(int argc, char *argv[]) {
 		return EXIT_FAILURE;
 	}
 
-	// start a login shell in /dev/com0 if it exists
-	if (access("/dev/com0", F_OK) == 0)
+	// start a login shell in /dev/com0 if it exists and kernel does not enable profiling
+	if (access("/dev/com0", F_OK) == 0 && access("/dev/prof", F_OK))
 		spawn_login_prompt("/dev/com0");
 
-	if (argc >1 && strcmp(argv[1], "withlogin") == 0)
+	if (argc > 1 && strcmp(argv[1], "withlogin") == 0)
 		dologinprompt("/dev/console");
 
 	// open /dev/console as the controlling terminal if we're not doing login

tools/prof/Makefile

@@ -0,0 +1,14 @@
+.phony: all install
+CC=x86_64-astral-gcc
+LD=x86_64-astral-gcc
+all: astral-prof
+
+install:
+	mkdir -p "$(DESTDIR)/$(PREFIX)/bin/"
+	cp astral-prof "$(DESTDIR)/$(PREFIX)/bin/astral-prof"
+
+astral-prof: main.o
+	$(LD) $(LDFLAGS) -g -o $@ $^
+
+main.o: main.c
+	$(CC) -c $(CFLAGS) -g -o $@ $<

tools/prof/main.c

@@ -0,0 +1,73 @@
+#include <stdio.h>
+#include <unistd.h>
+#include <fcntl.h>
+#include <sys/poll.h>
+#include <errno.h>
+#include <stdlib.h>
+#include <string.h>
+#include <sys/ioctl.h>
+#include <termios.h>
+
+static char *progname;
+
+static int open_or_die(const char *name, int flag, mode_t mode) {
+	int fd = open(name, flag, mode);
+	if (fd < 0) {
+		fprintf(stderr, "%s: open %s: %s\n", progname, name, strerror(errno));
+		exit(EXIT_FAILURE);
+	}
+	return fd;
+}
+
+int main(int argc, char *argv[]) {
+	progname = argv[0];
+	if (argc != 2) {
+		fprintf(stderr, "%s: usage: %s FILE\n", argv[0], argv[0]);
+		return EXIT_FAILURE;
+	}
+
+	// right now the limit for each trace is 256
+	uintptr_t buf[256];
+
+	int infd = open_or_die("/dev/prof", O_RDONLY | O_NONBLOCK, 0);
+	int outfd = open_or_die(argv[1], O_WRONLY | O_CREAT, 0644);
+
+	// enable raw mode
+	if (isatty(outfd)) {
+		struct termios termios;
+		tcgetattr(outfd, &termios);
+		cfmakeraw(&termios);
+		termios.c_oflag &= ~ONLCR;
+		tcsetattr(outfd, TCSANOW, &termios);
+	}
+
+	printf("%s: draining /dev/prof\n", argv[0]);
+	// empty it
+	if (ioctl(infd, 12345678, NULL) > 0)
+		return EXIT_FAILURE;
+
+	struct pollfd pollfd[2];
+
+	pollfd[0].fd = 0;
+	pollfd[0].events = POLLIN;
+	pollfd[0].revents = 0;
+	pollfd[1].fd = infd;
+	pollfd[1].events = POLLIN;
+	pollfd[1].revents = 0;
+
+	printf("%s: working...\n", argv[0]);
+	while (poll(pollfd, 2, -1)) {
+		if (pollfd[0].revents)
+			break;
+
+		uint8_t count;
+		read(infd, &count, 1);
+		read(infd, buf, 8 * count);
+		write(outfd, &count, 1);
+		write(outfd, buf, 8 * count);
+	}
+
+	printf("%s: done\n", argv[0]);
+
+	return EXIT_SUCCESS;
+}