From nobody Tue Feb 22 00:17:19 2022 X-Original-To: dev-commits-src-main@mlmmj.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mlmmj.nyi.freebsd.org (Postfix) with ESMTP id 5F9BE19DF10D; Tue, 22 Feb 2022 00:17:20 +0000 (UTC) (envelope-from git@FreeBSD.org) Received: from mxrelay.nyi.freebsd.org (mxrelay.nyi.freebsd.org [IPv6:2610:1c1:1:606c::19:3]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256 client-signature RSA-PSS (4096 bits) client-digest SHA256) (Client CN "mxrelay.nyi.freebsd.org", Issuer "R3" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 4K2fqz6qjVz3LWw; Tue, 22 Feb 2022 00:17:19 +0000 (UTC) (envelope-from git@FreeBSD.org) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=freebsd.org; s=dkim; t=1645489040; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding; bh=cLSHqfCMnxEftHU3EOu2AXzbHLnwTgf/S6SmxYvKg9Y=; b=dFYZF41G4GUeIYluqbtXesSvjQ6tGlT4K3Zf9AfvySBeVFjzfGZ/VNz1NKGd0QXvPL40Bh ZoXfC3dI5fH5Yn+ENeRjnHM2tzATJOyLm7gHl30QBvwAN43eS7fSYR6As5cb6I7iyHQin0 aQbM8YJONh8BqHCMIZmNKb8Ps0nHORaJmtBBRQoEzlW3O0SYJFxE7fTcszLyOBJO0sd/Kq duyRLF9YtqUNI8y510SSk/ZcBoPI2GlBQYNMdhL8hfWW8Q/colIJ7Uex/o4zO1EHuXoiMJ UamLEFvZs+HgemBL3I17rDw7wAjk1rRvVQgm68iipdHGba8Ka0TuTpYCIT62pg== Received: from gitrepo.freebsd.org (gitrepo.freebsd.org [IPv6:2610:1c1:1:6068::e6a:5]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256) (Client did not present a certificate) by mxrelay.nyi.freebsd.org (Postfix) with ESMTPS id C5AA219F57; Tue, 22 Feb 2022 00:17:19 +0000 (UTC) (envelope-from git@FreeBSD.org) Received: from gitrepo.freebsd.org ([127.0.1.44]) by gitrepo.freebsd.org (8.16.1/8.16.1) with ESMTP id 21M0HJKq041182; Tue, 22 Feb 2022 00:17:19 GMT (envelope-from git@gitrepo.freebsd.org) Received: (from git@localhost) by gitrepo.freebsd.org (8.16.1/8.16.1/Submit) id 21M0HJak041181; Tue, 22 Feb 2022 00:17:19 GMT (envelope-from git) Date: Tue, 22 Feb 2022 00:17:19 GMT Message-Id: <202202220017.21M0HJak041181@gitrepo.freebsd.org> To: src-committers@FreeBSD.org, dev-commits-src-all@FreeBSD.org, dev-commits-src-main@FreeBSD.org From: Mitchell Horne Subject: git: 5a8fceb3bd9f - main - boottrace: trace annotations for startup and shutdown List-Id: Commit messages for the main branch of the src repository List-Archive: https://lists.freebsd.org/archives/dev-commits-src-main List-Help: List-Post: List-Subscribe: List-Unsubscribe: Sender: owner-dev-commits-src-main@freebsd.org X-BeenThere: dev-commits-src-main@freebsd.org MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 8bit X-Git-Committer: mhorne X-Git-Repository: src X-Git-Refname: refs/heads/main X-Git-Reftype: branch X-Git-Commit: 5a8fceb3bd9f478d66dcaa4582a4faa989d66a97 Auto-Submitted: auto-generated ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=freebsd.org; s=dkim; t=1645489040; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding; bh=cLSHqfCMnxEftHU3EOu2AXzbHLnwTgf/S6SmxYvKg9Y=; b=sSPY8yRbRjE1mmEa0mFSZZDMiD85Rg78bCfyjIsAiT0Le1+1W9A5IHFvp/NLqKltnbzNeB wRNperCFjuhftPLB6tYJNd4JvaSHd4Phkg006LYeNh/T8GUrZigYnGI00ZlnBdJLU3GZ/L XZQlCQcaW4qiCeaEP59ymahjxpfoBZtVlgucDvwAyWm7y5mNEDsgXcQFRWrPoS2vyMEYv+ 0NuIphyNfb51FL/lVKxBSbq0zuxZv4ksXCtafoafmMUbHUeqDhBZ90KQViZoWm2nIkDBR8 dRGGt1mZ/YroSHDu7ZnshAEpL/3NbDn++/cTiteJSTCOannkoaPZltd5mpMgkg== ARC-Seal: i=1; s=dkim; d=freebsd.org; t=1645489040; a=rsa-sha256; cv=none; b=MZWQ/Q+LrAdDskXA4hHSRGgUkAjdW6GcKAhPoWD61ADNlIkEoL/q+CfeWe5NY8dss8g9vp d35TRGyp3H/6FUXepQDhiJNfcQqcQT7ckFqEWreupumKocfcWBkzqG44vJ5wJlyxTf84eQ /ODa7rI3aoENG0rAhIfYCxbEugzQQo6zWCshMojHSoWeFIfFwof503amVIC7F11RBcTEIo pnmS5f6A9rBsF+PyYx7QKicc1xkfRBKUzqPH5cBlO0N4Cj0v3OOi8RSlfbry1NlIZSEmST VrgWkQQYo+oLt+xePDOuzqBEv24pN3RLEZ7CNu4BNc9RswE2ZJJsF8x9Qbtfag== ARC-Authentication-Results: i=1; mx1.freebsd.org; none X-ThisMailContainsUnwantedMimeParts: N The branch main has been updated by mhorne: URL: https://cgit.FreeBSD.org/src/commit/?id=5a8fceb3bd9f478d66dcaa4582a4faa989d66a97 commit 5a8fceb3bd9f478d66dcaa4582a4faa989d66a97 Author: Mitchell Horne AuthorDate: 2022-02-22 00:15:57 +0000 Commit: Mitchell Horne 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 #include +#include #include #include #include @@ -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 #include +#include #include #include #include @@ -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 #include #include +#include #include #include #include @@ -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 #include #include +#include +#include #include #include -#include #include #include #include @@ -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 */ }