Add userland boot profiling to TSLOG

On kernels compiled with 'options TSLOG', record for each process ID:
* The timestamp of the fork() which creates it and the parent
process ID,
* The first path passed to execve(), if any,
* The first path resolved by namei, if any, and
* The timestamp of the exit() which terminates the process.

Expose this information via a new sysctl, debug.tslog_user.

On kernels lacking 'options TSLOG' (the default), no information is
recorded and the sysctl does not exist.

Note that recording namei is needed in order to obtain the names of
rc.d scripts being launched, as the rc system sources them in a
subshell rather than execing the scripts.

With this commit it is now possible to generate flamecharts of the
entire boot process from the start of the loader to the end of
/etc/rc.  The code needed to perform this processing is currently
found in github: https://github.com/cperciva/freebsd-boot-profiling

Reviewed by:	mhorne
Sponsored by:	https://www.patreon.com/cperciva
Differential Revision: https://reviews.freebsd.org/D32493

sys/kern/kern_exec.c

@@ -381,6 +381,7 @@ kern_execve(struct thread *td, struct image_args *args, struct mac *mac_p,
     struct vmspace *oldvmspace)
 {
 
+	TSEXEC(td->td_proc->p_pid, args->begin_argv);
 	AUDIT_ARG_ARGV(args->begin_argv, args->argc,
 	    exec_args_get_begin_envv(args) - args->begin_argv);
 	AUDIT_ARG_ENVV(exec_args_get_begin_envv(args), args->envc,

sys/kern/kern_exit.c

@@ -228,6 +228,7 @@ exit1(struct thread *td, int rval, int signo)
 
 	mtx_assert(&Giant, MA_NOTOWNED);
 	KASSERT(rval == 0 || signo == 0, ("exit1 rv %d sig %d", rval, signo));
+	TSPROCEXIT(td->td_proc->p_pid);
 
 	p = td->td_proc;
 	/*

sys/kern/kern_fork.c

@@ -392,6 +392,7 @@ do_fork(struct thread *td, struct fork_req *fr, struct proc *p2, struct thread *
 	p2->p_state = PRS_NEW;		/* protect against others */
 	p2->p_pid = fork_findpid(fr->fr_flags);
 	AUDIT_ARG_PID(p2->p_pid);
+	TSFORK(p2->p_pid, p1->p_pid);
 
 	sx_xlock(&allproc_lock);
 	LIST_INSERT_HEAD(&allproc, p2, p_list);

sys/kern/kern_tslog.c

@@ -30,6 +30,8 @@ __FBSDID("$FreeBSD$");
 #include <sys/param.h>
 #include <sys/kernel.h>
 #include <sys/linker.h>
+#include <sys/malloc.h>
+#include <sys/proc.h>
 #include <sys/sbuf.h>
 #include <sys/sysctl.h>
 #include <sys/systm.h>
@@ -131,3 +133,86 @@ sysctl_debug_tslog(SYSCTL_HANDLER_ARGS)
 
 SYSCTL_PROC(_debug, OID_AUTO, tslog, CTLTYPE_STRING|CTLFLAG_RD|CTLFLAG_MPSAFE,
     0, 0, sysctl_debug_tslog, "", "Dump recorded event timestamps");
+
+MALLOC_DEFINE(M_TSLOGUSER, "tsloguser", "Strings used by userland tslog");
+static struct procdata {
+	pid_t ppid;
+	uint64_t tsc_forked;
+	uint64_t tsc_exited;
+	char * execname;
+	char * namei;
+	int reused;
+} procs[PID_MAX + 1];
+
+void
+tslog_user(pid_t pid, pid_t ppid, const char * execname, const char * namei)
+{
+	uint64_t tsc = get_cyclecount();
+
+	/* If we wrapped, do nothing. */
+	if (procs[pid].reused)
+		return;
+
+	/* If we have a ppid, we're recording a fork. */
+	if (ppid != (pid_t)(-1)) {
+		/* If we have a ppid already, we wrapped. */
+		if (procs[pid].ppid) {
+			procs[pid].reused = 1;
+			return;
+		}
+
+		/* Fill in some fields. */
+		procs[pid].ppid = ppid;
+		procs[pid].tsc_forked = tsc;
+		return;
+	}
+
+	/* If we have an execname, record it. */
+	if (execname != NULL) {
+		if (procs[pid].execname == NULL)
+			procs[pid].execname = strdup(execname, M_TSLOGUSER);
+		return;
+	}
+
+	/* Record the first namei for the process. */
+	if (namei != NULL) {
+		if (procs[pid].namei == NULL)
+			procs[pid].namei = strdup(namei, M_TSLOGUSER);
+		return;
+	}
+
+	/* Otherwise we're recording an exit. */
+	procs[pid].tsc_exited = tsc;
+}
+
+static int
+sysctl_debug_tslog_user(SYSCTL_HANDLER_ARGS)
+{
+	int error;
+	struct sbuf *sb;
+	pid_t pid;
+
+	sb = sbuf_new_for_sysctl(NULL, NULL, 1024, req);
+
+	/* Export the data we logged. */
+	for (pid = 0; pid <= PID_MAX; pid++) {
+		sbuf_printf(sb, "%zu", (size_t)pid);
+		sbuf_printf(sb, " %zu", (size_t)procs[pid].ppid);
+		sbuf_printf(sb, " %llu",
+		    (unsigned long long)procs[pid].tsc_forked);
+		sbuf_printf(sb, " %llu",
+		    (unsigned long long)procs[pid].tsc_exited);
+		sbuf_printf(sb, " \"%s\"", procs[pid].execname ?
+		    procs[pid].execname : "");
+		sbuf_printf(sb, " \"%s\"", procs[pid].namei ?
+		    procs[pid].namei : "");
+		sbuf_printf(sb, "\n");
+	}
+	error = sbuf_finish(sb);
+	sbuf_delete(sb);
+	return (error);
+}
+
+SYSCTL_PROC(_debug, OID_AUTO, tslog_user,
+    CTLTYPE_STRING|CTLFLAG_RD|CTLFLAG_MPSAFE, 0, 0, sysctl_debug_tslog_user,
+    "", "Dump recorded userland event timestamps");

sys/kern/vfs_lookup.c

@@ -611,6 +611,7 @@ namei(struct nameidata *ndp)
 		ktrnamei(cnp->cn_pnbuf);
 	}
 #endif
+	TSNAMEI(curthread->td_proc->p_pid, cnp->cn_pnbuf);
 
 	/*
 	 * First try looking up the target without locking any vnodes.

sys/sys/tslog.h

@@ -51,12 +51,19 @@
 #define TSUNWAIT(x) TSEVENT2("UNWAIT", x);
 #define TSHOLD(x) TSEVENT2("HOLD", x);
 #define TSRELEASE(x) TSEVENT2("RELEASE", x);
+#define TSFORK(p, pp) TSRAW_USER(p, pp, NULL, NULL)
+#define TSEXEC(p, name) TSRAW_USER(p, (pid_t)(-1), name, NULL)
+#define TSNAMEI(p, name) TSRAW_USER(p, (pid_t)(-1), NULL, name)
+#define TSPROCEXIT(p) TSRAW_USER(p, (pid_t)(-1), NULL, NULL)
 
 #ifdef TSLOG
 #define TSRAW(a, b, c, d) tslog(a, b, c, d)
 void tslog(void *, int, const char *, const char *);
+#define TSRAW_USER(a, b, c, d) tslog_user(a, b, c, d)
+void tslog_user(pid_t, pid_t, const char *, const char *);
 #else
 #define TSRAW(a, b, c, d)		/* Timestamp logging disabled */
+#define TSRAW_USER(a, b, c, d)		/* Timestamp logging disabled */
 #endif
 
 #endif /* _TSLOG_H_ */