boottrace: trace annotations for startup and shutdown

Add trace events for execution of SYSINITs (both static and dynamically
loaded), and to the various steps in the shutdown/panic/reboot paths.

Sponsored by:	NetApp, Inc.
Sponsored by:	Klara, Inc.
X-NetApp-PR:	#23
Differential Revision:	https://reviews.freebsd.org/D30187

sys/kern/init_main.c

@@ -53,6 +53,7 @@ __FBSDID("$FreeBSD$");
 
 #include <sys/param.h>
 #include <sys/systm.h>
+#include <sys/boottrace.h>
 #include <sys/conf.h>
 #include <sys/cpuset.h>
 #include <sys/dtrace_bsd.h>
@@ -234,8 +235,8 @@ mi_startup(void)
 	struct sysinit **xipp;	/* interior loop of sort*/
 	struct sysinit *save;	/* bubble*/
 
-#if defined(VERBOSE_SYSINIT)
 	int last;
+#if defined(VERBOSE_SYSINIT)
 	int verbose;
 #endif
 
@@ -266,8 +267,8 @@ restart:
 		}
 	}
 
-#if defined(VERBOSE_SYSINIT)
 	last = SI_SUB_COPYRIGHT;
+#if defined(VERBOSE_SYSINIT)
 	verbose = 0;
 #if !defined(DDB)
 	printf("VERBOSE_SYSINIT: DDB not enabled, symbol lookups disabled.\n");
@@ -285,10 +286,12 @@ restart:
 		if ((*sipp)->subsystem == SI_SUB_DONE)
 			continue;
 
+		if ((*sipp)->subsystem > last)
+			BOOTTRACE_INIT("sysinit 0x%7x", (*sipp)->subsystem);
+
 #if defined(VERBOSE_SYSINIT)
 		if ((*sipp)->subsystem > last && verbose_sysinit != 0) {
 			verbose = 1;
-			last = (*sipp)->subsystem;
 			printf("subsystem %x\n", last);
 		}
 		if (verbose) {
@@ -319,6 +322,7 @@ restart:
 #endif
 
 		/* Check off the one we're just done */
+		last = (*sipp)->subsystem;
 		(*sipp)->subsystem = SI_SUB_DONE;
 
 		/* Check if we've installed more sysinit items via KLD */
@@ -334,6 +338,7 @@ restart:
 	}
 
 	TSEXIT();	/* Here so we don't overlap with start_init. */
+	BOOTTRACE("mi_startup done");
 
 	mtx_assert(&Giant, MA_OWNED | MA_NOTRECURSED);
 	mtx_unlock(&Giant);

sys/kern/kern_linker.c

@@ -35,6 +35,7 @@ __FBSDID("$FreeBSD$");
 
 #include <sys/param.h>
 #include <sys/systm.h>
+#include <sys/boottrace.h>
 #include <sys/eventhandler.h>
 #include <sys/fcntl.h>
 #include <sys/jail.h>
@@ -196,6 +197,7 @@ static void
 linker_file_sysinit(linker_file_t lf)
 {
 	struct sysinit **start, **stop, **sipp, **xipp, *save;
+	int last;
 
 	KLD_DPF(FILE, ("linker_file_sysinit: calling SYSINITs for %s\n",
 	    lf->filename));
@@ -227,14 +229,20 @@ linker_file_sysinit(linker_file_t lf)
 	 * Traverse the (now) ordered list of system initialization tasks.
 	 * Perform each task, and continue on to the next task.
 	 */
+	last = SI_SUB_DUMMY;
 	sx_xunlock(&kld_sx);
 	mtx_lock(&Giant);
 	for (sipp = start; sipp < stop; sipp++) {
 		if ((*sipp)->subsystem == SI_SUB_DUMMY)
 			continue;	/* skip dummy task(s) */
 
+		if ((*sipp)->subsystem > last)
+			BOOTTRACE("%s: sysinit 0x%7x", lf->filename,
+			    (*sipp)->subsystem);
+
 		/* Call function */
 		(*((*sipp)->func)) ((*sipp)->udata);
+		last = (*sipp)->subsystem;
 	}
 	mtx_unlock(&Giant);
 	sx_xlock(&kld_sx);
@@ -244,6 +252,7 @@ static void
 linker_file_sysuninit(linker_file_t lf)
 {
 	struct sysinit **start, **stop, **sipp, **xipp, *save;
+	int last;
 
 	KLD_DPF(FILE, ("linker_file_sysuninit: calling SYSUNINITs for %s\n",
 	    lf->filename));
@@ -279,12 +288,18 @@ linker_file_sysuninit(linker_file_t lf)
 	 */
 	sx_xunlock(&kld_sx);
 	mtx_lock(&Giant);
+	last = SI_SUB_DUMMY;
 	for (sipp = start; sipp < stop; sipp++) {
 		if ((*sipp)->subsystem == SI_SUB_DUMMY)
 			continue;	/* skip dummy task(s) */
 
+		if ((*sipp)->subsystem > last)
+			BOOTTRACE("%s: sysuninit 0x%7x", lf->filename,
+			    (*sipp)->subsystem);
+
 		/* Call function */
 		(*((*sipp)->func)) ((*sipp)->udata);
+		last = (*sipp)->subsystem;
 	}
 	mtx_unlock(&Giant);
 	sx_xlock(&kld_sx);

sys/kern/kern_shutdown.c

@@ -50,6 +50,7 @@ __FBSDID("$FreeBSD$");
 #include <sys/param.h>
 #include <sys/systm.h>
 #include <sys/bio.h>
+#include <sys/boottrace.h>
 #include <sys/buf.h>
 #include <sys/conf.h>
 #include <sys/compressor.h>
@@ -323,14 +324,19 @@ shutdown_nice_task_fn(void *arg, int pending __unused)
 	howto = (uintptr_t)arg;
 	/* Send a signal to init(8) and have it shutdown the world. */
 	PROC_LOCK(initproc);
-	if (howto & RB_POWEROFF)
+	if ((howto & RB_POWEROFF) != 0) {
+		BOOTTRACE("SIGUSR2 to init(8)");
 		kern_psignal(initproc, SIGUSR2);
-	else if (howto & RB_POWERCYCLE)
+	} else if ((howto & RB_POWERCYCLE) != 0) {
+		BOOTTRACE("SIGWINCH to init(8)");
 		kern_psignal(initproc, SIGWINCH);
-	else if (howto & RB_HALT)
+	} else if ((howto & RB_HALT) != 0) {
+		BOOTTRACE("SIGUSR1 to init(8)");
 		kern_psignal(initproc, SIGUSR1);
-	else
+	} else {
+		BOOTTRACE("SIGINT to init(8)");
 		kern_psignal(initproc, SIGINT);
+	}
 	PROC_UNLOCK(initproc);
 }
 
@@ -345,6 +351,7 @@ shutdown_nice(int howto)
 {
 
 	if (initproc != NULL && !SCHEDULER_STOPPED()) {
+		BOOTTRACE("shutdown initiated");
 		shutdown_nice_task.ta_context = (void *)(uintptr_t)howto;
 		taskqueue_enqueue(taskqueue_fast, &shutdown_nice_task);
 	} else {
@@ -420,6 +427,29 @@ doadump(boolean_t textdump)
 	return (error);
 }
 
+/*
+ * Trace the shutdown reason.
+ */
+static void
+reboottrace(int howto)
+{
+	if ((howto & RB_DUMP) != 0) {
+		if ((howto & RB_HALT) != 0)
+			BOOTTRACE("system panic: halting...");
+		if ((howto & RB_POWEROFF) != 0)
+			BOOTTRACE("system panic: powering off...");
+		if ((howto & (RB_HALT|RB_POWEROFF)) == 0)
+			BOOTTRACE("system panic: rebooting...");
+	} else {
+		if ((howto & RB_HALT) != 0)
+			BOOTTRACE("system halting...");
+		if ((howto & RB_POWEROFF) != 0)
+			BOOTTRACE("system powering off...");
+		if ((howto & (RB_HALT|RB_POWEROFF)) == 0)
+			BOOTTRACE("system rebooting...");
+	}
+}
+
 /*
  * kern_reboot(9): Shut down the system cleanly to prepare for reboot, halt, or
  * power off.
@@ -429,6 +459,11 @@ kern_reboot(int howto)
 {
 	static int once = 0;
 
+	if (initproc != NULL && curproc != initproc)
+		BOOTTRACE("kernel shutdown (dirty) started");
+	else
+		BOOTTRACE("kernel shutdown (clean) started");
+
 	/*
 	 * Normal paths here don't hold Giant, but we can wind up here
 	 * unexpectedly with it held.  Drop it now so we don't have to
@@ -456,6 +491,7 @@ kern_reboot(int howto)
 #endif
 	/* We're in the process of rebooting. */
 	rebooting = 1;
+	reboottrace(howto);
 
 	/* We are out of the debugger now. */
 	kdb_active = 0;
@@ -464,13 +500,16 @@ kern_reboot(int howto)
 	 * Do any callouts that should be done BEFORE syncing the filesystems.
 	 */
 	EVENTHANDLER_INVOKE(shutdown_pre_sync, howto);
+	BOOTTRACE("shutdown pre sync complete");
 
 	/* 
 	 * Now sync filesystems
 	 */
 	if (!cold && (howto & RB_NOSYNC) == 0 && once == 0) {
 		once = 1;
+		BOOTTRACE("bufshutdown begin");
 		bufshutdown(show_busybufs);
+		BOOTTRACE("bufshutdown end");
 	}
 
 	print_uptime();
@@ -482,11 +521,17 @@ kern_reboot(int howto)
 	 * been completed.
 	 */
 	EVENTHANDLER_INVOKE(shutdown_post_sync, howto);
+	BOOTTRACE("shutdown post sync complete");
 
 	if ((howto & (RB_HALT|RB_DUMP)) == RB_DUMP && !cold && !dumping) 
 		doadump(TRUE);
 
 	/* Now that we're going to really halt the system... */
+	BOOTTRACE("shutdown final begin");
+
+	if (shutdown_trace)
+		boottrace_dump_console();
+
 	EVENTHANDLER_INVOKE(shutdown_final, howto);
 
 	for(;;) ;	/* safety against shutdown_reset not working */

sys/kern/vfs_bio.c

@@ -52,9 +52,10 @@ __FBSDID("$FreeBSD$");
 #include <sys/asan.h>
 #include <sys/bio.h>
 #include <sys/bitset.h>
+#include <sys/boottrace.h>
+#include <sys/buf.h>
 #include <sys/conf.h>
 #include <sys/counter.h>
-#include <sys/buf.h>
 #include <sys/devicestat.h>
 #include <sys/eventhandler.h>
 #include <sys/fail.h>
@@ -1466,10 +1467,12 @@ bufshutdown(int show_busybufs)
 		 * Failed to sync all blocks. Indicate this and don't
 		 * unmount filesystems (thus forcing an fsck on reboot).
 		 */
+		BOOTTRACE("shutdown failed to sync buffers");
 		printf("Giving up on %d buffers\n", nbusy);
 		DELAY(5000000);	/* 5 seconds */
 		swapoff_all();
 	} else {
+		BOOTTRACE("shutdown sync complete");
 		if (!first_buf_printf)
 			printf("Final sync complete\n");
 
@@ -1489,6 +1492,7 @@ bufshutdown(int show_busybufs)
 			swapoff_all();
 			vfs_unmountall();
 		}
+		BOOTTRACE("shutdown unmounted all filesystems");
 	}
 	DELAY(100000);		/* wait for console output to finish */
 }