The branch main has been updated by mhorne: URL: https://cgit.FreeBSD.org/src/commit/?id=5a8fceb3bd9f478d66dcaa4582a4faa989d66a97
commit 5a8fceb3bd9f478d66dcaa4582a4faa989d66a97 Author: Mitchell Horne <[email protected]> AuthorDate: 2022-02-22 00:15:57 +0000 Commit: Mitchell Horne <[email protected]> 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 */ }
