git: 5a8fceb3bd9f - main - boottrace: trace annotations for startup and shutdown
- Go to: [ bottom of page ] [ top of archives ] [ this month ]
Date: Tue, 22 Feb 2022 00:17:19 UTC
The branch main has been updated by mhorne:
URL: https://cgit.FreeBSD.org/src/commit/?id=5a8fceb3bd9f478d66dcaa4582a4faa989d66a97
commit 5a8fceb3bd9f478d66dcaa4582a4faa989d66a97
Author: Mitchell Horne <mhorne@FreeBSD.org>
AuthorDate: 2022-02-22 00:15:57 +0000
Commit: Mitchell Horne <mhorne@FreeBSD.org>
CommitDate: 2022-02-22 00:15:57 +0000
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 | 11 +++++++---
sys/kern/kern_linker.c | 15 ++++++++++++++
sys/kern/kern_shutdown.c | 53 ++++++++++++++++++++++++++++++++++++++++++++----
sys/kern/vfs_bio.c | 6 +++++-
4 files changed, 77 insertions(+), 8 deletions(-)
diff --git a/sys/kern/init_main.c b/sys/kern/init_main.c
index 32cb2100dc17..52a0aae6de71 100644
--- a/sys/kern/init_main.c
+++ b/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);
diff --git a/sys/kern/kern_linker.c b/sys/kern/kern_linker.c
index e5efe2302c11..f28fd30cf209 100644
--- a/sys/kern/kern_linker.c
+++ b/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);
diff --git a/sys/kern/kern_shutdown.c b/sys/kern/kern_shutdown.c
index efd7009df8f6..fb764550d229 100644
--- a/sys/kern/kern_shutdown.c
+++ b/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 */
diff --git a/sys/kern/vfs_bio.c b/sys/kern/vfs_bio.c
index af89f11a30f0..5c42f00809b8 100644
--- a/sys/kern/vfs_bio.c
+++ b/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 */
}