Benchmarking NetBSD/amd64 with tslog(4)

[Emile `iMil' Heitor <imil%home.imil.net@localhost>]

If anyone is interested in benchmarking parts of the NetBSD/amd64 kernel,
I have included the tslog(4) feature in my PVH/performance patchset.
This feature was originally written by cperciva@freebsd and is available
as a self-applicable patch:

https://github.com/NetBSD/src/commit/78e5ba0ad7287f7560d0e658aa035a43f08db30c

I've also modified Colin's flamegraph generator so it can be used on
NetBSD:
https://github.com/NetBSDfr/freebsd-boot-profiling/tree/netbsd

To use tslog(4), build the kernel with option TSLOG, and place TS*()
defines where you want to get speed informations, I've attached an
example diff to this email.

Once the kernel is built, boot it, and you will see TSC timestamps for
kernel functions with the command sysctl debug.tslog, and for userland
with sysctl debug.tslog_user.

To generate a shiny flamegraph, after cloning the mentioned netbsd
branch, run:

$ sh mkflame.sh --scale 0.5 > tslog.svg

You may need to toy around with the scaling factor.
Exemple output: https://imil.net/NetBSD/tslog.svg

HTH,

------------------------------------------------------------------------
Emile `iMil' Heitor <imil@{home.imil.net,NetBSD.org}> | https://imil.net

diff --git a/sys/kern/init_main.c b/sys/kern/init_main.c
index 69f132d59a9..0fc6386736c 100644
--- a/sys/kern/init_main.c
+++ b/sys/kern/init_main.c
@@ -236,6 +236,8 @@ extern void *_binary_splash_image_end;
 #include <sys/bootcyclecount.h>
 #endif
 
+#include <x86/tslog.h>
+
 extern time_t rootfstime;
 
 #ifndef curlwp
@@ -279,6 +281,7 @@ main(void)
 	uint64_t bootccount;
 #endif
 
+	TSENTER();
 #ifdef DIAGNOSTIC
 	/*
 	 * Verify that CPU_INFO_FOREACH() knows about the boot CPU
@@ -641,6 +644,7 @@ main(void)
 
 	scdebug_init();
 
+	TSEXIT();
 	/*
 	 * Create process 1 (init(8)).  We do this now, as Unix has
 	 * historically had init be process 1, and changing this would
@@ -988,6 +992,7 @@ start_init(void *arg)
 	char ipath[129];
 	int ipx, len;
 
+	TSENTER();
 	/*
 	 * Now in process 1.
 	 */
@@ -1133,6 +1138,7 @@ start_init(void *arg)
 		error = sys_execve(l, &args, retval);
 		if (error == 0 || error == EJUSTRETURN) {
 			KERNEL_UNLOCK_LAST(l);
+			TSEXIT();
 			return;
 		}
 		printf("exec %s: error %d\n", path, error);
diff --git a/sys/kern/kern_exec.c b/sys/kern/kern_exec.c
index a45322c3d16..5b39d598865 100644
--- a/sys/kern/kern_exec.c
+++ b/sys/kern/kern_exec.c
@@ -126,6 +126,8 @@ __KERNEL_RCSID(0, "$NetBSD: kern_exec.c,v 1.521 2023/10/08 12:38:58 ad Exp $");
 #endif
 #endif
 
+#include <x86/tslog.h>
+
 struct execve_data;
 
 extern int user_va0_disable;
@@ -1480,6 +1482,9 @@ execve1(struct lwp *l, bool has_path, const char *path, int fd,
 	    &data);
 	if (error)
 		return error;
+
+	TSEXEC(l->l_proc->p_pid, data.ed_pathstring);
+
 	error = execve_runproc(l, &data, false, false);
 	return error;
 }
diff --git a/sys/kern/kern_exit.c b/sys/kern/kern_exit.c
index e11b711e01b..96869a3abfa 100644
--- a/sys/kern/kern_exit.c
+++ b/sys/kern/kern_exit.c
@@ -118,6 +118,8 @@ int debug_exit = 0;
 #define DPRINTF(x)
 #endif
 
+#include <x86/tslog.h>
+
 static int find_stopped_child(struct proc *, idtype_t, id_t, int,
     struct proc **, struct wrusage *, siginfo_t *);
 static void proc_free(struct proc *, struct wrusage *);
@@ -204,6 +206,8 @@ exit1(struct lwp *l, int exitcode, int signo)
 	ksiginfoq_t	kq;
 	int		wakeinit;
 
+	TSPROCEXIT(l->l_proc->p_pid);
+
 	p = l->l_proc;
 
 	/* Verify that we hold no locks other than p->p_lock. */
diff --git a/sys/kern/kern_fork.c b/sys/kern/kern_fork.c
index 23169dd9130..4e778fe1b40 100644
--- a/sys/kern/kern_fork.c
+++ b/sys/kern/kern_fork.c
@@ -95,6 +95,7 @@ __KERNEL_RCSID(0, "$NetBSD: kern_fork.c,v 1.231 2024/05/14 19:00:44 andvar Exp $
 #include <sys/uidinfo.h>
 #include <sys/sdt.h>
 #include <sys/ptrace.h>
+#include <x86/tslog.h>
 
 /*
  * DTrace SDT provider definitions
@@ -317,6 +318,7 @@ fork1(struct lwp *l1, int flags, int exitsig, void *stack, size_t stacksize,
 		atomic_dec_uint(&nprocs);
 		return EAGAIN;
 	}
+	TSFORK(p2->p_pid, p1->p_pid);
 
 	/*
 	 * We are now committed to the fork.  From here on, we may
diff --git a/sys/kern/kern_kthread.c b/sys/kern/kern_kthread.c
index f182d764b6c..9fe3aae0c5d 100644
--- a/sys/kern/kern_kthread.c
+++ b/sys/kern/kern_kthread.c
@@ -43,6 +43,7 @@ __KERNEL_RCSID(0, "$NetBSD: kern_kthread.c,v 1.49 2023/09/23 14:40:42 ad Exp $")
 #include <sys/sched.h>
 #include <sys/kmem.h>
 #include <sys/msan.h>
+#include <x86/tslog.h>
 
 #include <uvm/uvm_extern.h>
 
@@ -96,6 +97,7 @@ kthread_create(pri_t pri, int flag, struct cpu_info *ci,
 		va_end(ap);
 	}
 
+	TSTHREAD(l, l->l_name); 
 	/*
 	 * Set parameters.
 	 */
diff --git a/sys/kern/subr_autoconf.c b/sys/kern/subr_autoconf.c
index 5ee8a7998b0..4c3cf0d25fe 100644
--- a/sys/kern/subr_autoconf.c
+++ b/sys/kern/subr_autoconf.c
@@ -110,6 +110,7 @@ __KERNEL_RCSID(0, "$NetBSD: subr_autoconf.c,v 1.314 2023/07/18 11:57:37 riastrad
 #include <sys/sysctl.h>
 #include <sys/stdarg.h>
 #include <sys/localcount.h>
+#include <x86/tslog.h>
 
 #include <sys/disk.h>
 
@@ -1758,6 +1759,8 @@ config_attach_internal(device_t parent, cfdata_t cf, void *aux, cfprint_t print,
 
 	KASSERT(KERNEL_LOCKED_P());
 
+	TSENTER2(cf->cf_name);
+
 	dev = config_devalloc(parent, cf, args);
 	if (!dev)
 		panic("config_attach: allocation of device softc failed");
@@ -1853,6 +1856,7 @@ config_attach_internal(device_t parent, cfdata_t cf, void *aux, cfprint_t print,
 
 	device_register_post_config(dev, aux);
 	rnd_add_uint32(&rnd_autoconf_source, 0);
+	TSEXIT2(cf->cf_name);
 	return dev;
 }
 
diff --git a/tsenable.py b/tsenable.py
new file mode 100755
index 00000000000..310c4048925
--- /dev/null
+++ b/tsenable.py
@@ -0,0 +1,42 @@
+import re
+import sys
+
+keywords = ["defined", "sizeof", "return", "while", "panic"]
+multiline = [ "calc_cache_size", "fork1", "ctob"]
+
+with open(sys.argv[1], 'r') as file:
+   lines = file.readlines()
+
+in_section = False
+exit_func = None
+for line in lines:
+    if exit_func:
+        print(line.rstrip())
+        print(exit_func)
+        exit_func = None
+        continue
+    elif 'TSENTER()' in line:
+        in_section = True
+        print(line.rstrip())
+    elif 'TSEXIT()' in line:
+        in_section = False
+        print(line.rstrip())
+    elif in_section and re.match(r'[^\w]+\s*/?\*+/?\s*.*', line):
+        print(line.rstrip())
+    elif in_section and any(k in line for k in keywords):
+        print(line.rstrip())
+    elif in_section and re.match(r'.+[a-z0-9_]+\([^\)]*\)', line):
+        m = re.findall(r'(\s*)([a-z0-9_]+)\([^\)]*\)', line)
+        if m:
+            s, f = m[0]
+            print(f'{s}TSENTER2("{f}");')
+            print(line.rstrip())
+            exit_func = f'{s}TSEXIT2("{f}");\n'
+            if any(l in line for l in multiline):
+                continue;
+            print(exit_func)
+            exit_func = None
+        else:
+            print(line.rstrip())
+    else:
+        print(line.rstrip())