Page MenuHomeFreeBSD

boottrace: trace annotations for startup and shutdown
Needs ReviewPublic

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

Details

Reviewers
kevans
trasz
Summary

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

Diff Detail

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

Event Timeline

My experience from TSLOG is that a very large proportion of the kernel boot time is spent in a single SYSINIT, namely the one during which all the devices are probed and attached. Maybe worth following TSLOG's example and adding that level of granularity? I found that it helped a lot with tracking down slow device drivers.

Also, a more general comment on this work -- can you make sure there's an easy way to record the userland init but *not* the kernel init? I'd like to be able to take this and splice it onto my loader+kernel TSLOG output.

Simplify the trace calls somewhat with the BOOTTRACE() macro. Now, printf-like arguments are supported.

Hi Colin, thanks for the comments and apologies that it has taken some time for me to update this patch.

My experience from TSLOG is that a very large proportion of the kernel boot time is spent in a single SYSINIT, namely the one during which all the devices are probed and attached. Maybe worth following TSLOG's example and adding that level of granularity? I found that it helped a lot with tracking down slow device drivers.

This is still TODO, but shouldn't take long to add, so I'll add it in the next update.

Also, a more general comment on this work -- can you make sure there's an easy way to record the userland init but *not* the kernel init? I'd like to be able to take this and splice it onto my loader+kernel TSLOG output.

Great suggestion, I added this in D30184 with the kern.boottrace.dotrace_user and kern.boottrace.dotrace_kernel tunables.

Is there anything boottrace gets you which TSLOG doesn't with my addition of userland TSLOG (https://reviews.freebsd.org/D32493)?

Is there anything boottrace gets you which TSLOG doesn't with my addition of userland TSLOG (https://reviews.freebsd.org/D32493)?

Yes, it captures some different ancillary information, namely, the resource usage of the process at the time it generates the trace entry, and the CPU that it was executing on.

It also captures trace entries (and optionally prints them) at shutdown time, so you might see e.g. how long it takes to sync the filesystems.

I would say that the goals of the two frameworks seem to be different. boottrace is intended mainly to produce a human-readable log of events, to be consumed or compared by a sysadmin, for example. Your tslog has better granularity wrt the boot-time entries it captures, and being able to programmatically convert the output into flamegraphs is obviously highly valuable in reducing overall boot time. I think the two can coexist, but I plan to open this up for discussion on the mailing lists.

sys/kern/kern_shutdown.c
441

style(9): !(flags) -> (flags) == 0 (and below)