Page MenuHomeFreeBSD

boottrace: a simple boot and shutdown-time tracing facility
ClosedPublic

Authored by mhorne on May 10 2021, 3:14 PM.

Details

Summary

Feature Overview

Boottrace is a facility for capturing trace events during boot and
shutdown. This includes kernel initialization, as well as rc. It has
been used by NetApp internally for several years, for catching
and diagnosing slow devices or subsystems.

Event annotations will be added to the boot/shutdown paths in the
kernel, to some key system utilities (init(8), shutdown(8), reboot(8)),
and surrounding the execution of individual rc(8) scripts. This gives a
holistic log of events covering the entire boot process.

A sample output is available at: P531

Events are stored into three tables: boot-time events, run-time events,
and shutdown-events. Events are stored in the boot-time table, until the
time that control is handed over to init(8). After this point, events
are stored in the run-time table, which will wrap around if it fills.
Upon initiating a shutdown, reboot, or panic, events will be stored in
the shutdown-time table.

For now, boottrace is unconditionally compiled into the kernel but
disabled by default.

There is some overlap in functionality between boottrace and the
existing boot-time event tracing facility, TSLOG. TSLOG captures
kernel events from early boot (hammer_time) to mountroot, at a
slightly finer granularity.. Boottrace's scope is wider, and it is currently
initialized slightly later, at SI_SUB_CPU. For this reason, I think it's fine
for the two to co-exist. TSLog is nicely self-contained, and extending it
beyond its initial purpose would likely be messier than adding this as
a separate facility.

sysctl interface

Userland is expected to create/query events via sysctl. This module
introduces the following:

kern.boottrace.enabled (read-only tunable): enable/disable tracing. Default: false.

kern.boottrace.shutdown_trace: log shutdown-events to console before the system halts

kern.boottrace.shutdown_trace_threshold: Set to a millisecond value. Events that occur (as compared to the previous) within less time than this value will not be printed. The default of zero logs all events.

kern.boottrace.log (read-only, CTLFLAG_SKIP): print the boot-time and run-time tables.

kern.boottrace.boottrace (write-only): Accepts a string, which creates a new boot-time trace event. The event will be logged as ${procname}: name.

kern.boottrace.runtrace (write-only): Same as kern.boottrace.boottrace, but writes to the runtime table.

kern.boottrace.shuttrace (write-only): Same as above, but writes to the shutdown table.

This Patch

This revision adds the core boottrace facility implementing these
interfaces. Adding the trace annotations themselves to kernel and
userland will happen in follow-up reviews.

Diff Detail

Repository
rS FreeBSD src repository - subversion
Lint
Lint OK
Unit
No Unit Test Coverage
Build Status
Buildable 42343
Build 39231: arc lint + arc unit

Event Timeline

Rebase and update after a few rounds of cleanups and testing.

Rebase once more after some furthre light refactoring.

sys/kern/kern_boottrace.c
88
119

Shouldn't boottimes be boottrace instead according to the sysctl description in the commit message?

sys/kern/kern_boottrace.c
322

You might assert boottrace_enabled here, we're a couple callers deep at points

421

I don't see where this is used in this or follow-up patches?

Fix sysctl naming to match description. Handle comments from @kevans.

mhorne added inline comments.
sys/kern/kern_boottrace.c
421

Indeed, it was but is no longer used anywhere.

Would also be nice to start sysctl descriptions wit a capital letter for consistency.

sys/kern/kern_boottrace.c
60
62
66
67

Minor capitalization fixes, add missing semicolon.

This revision was not accepted when it landed; it landed in state Needs Review.Feb 22 2022, 12:18 AM
This revision was automatically updated to reflect the committed changes.