[Request for review] Profiling the FreeBSD kernel boot
Mark Johnston
markj at FreeBSD.org
Fri Dec 22 17:08:25 UTC 2017
On Fri, Dec 22, 2017 at 09:44:46AM +0000, Colin Percival wrote:
> Hi everyone,
>
> For the past few months I've been working on code for profiling the FreeBSD
> "kernel boot", i.e., everything between when kernel code starts running and
> when we first enter userland as init(8). This is not trivial since it's
> impossible to use tools like dtrace to monitor things prior to when said
> tools are running.
In the case of DTrace, this isn't quite true. We support so-called
boot-time DTrace on x86. The caveat is that we can only start tracing
after the SI_SUB_DTRACE_ANON sysinit has been executed. That sysinit
can't come earlier than SI_SUB_SMP, since it needs to be able to measure
TSC skew between CPUs in order to initialize DTrace's high-resolution
timer.
I don't think boot-time DTrace is quite what you want for this exercise,
but it does come in handy sometimes.
In case it's of interest: to use boot-time DTrace, invoke dtrace(1) as
you normally would and add -A. Rather than starting to trace, dtrace(1)
will save a representation of the D script to a file which gets read by
the loader during the next boot. The results of the trace can be fetched
with "dtrace -a". For instance, to print the amount of time elapsed in
microseconds during each vprintf() call, along with a stack:
# dtrace -A -n 'fbt::vprintf:entry {self->ts = timestamp;}
fbt::vprintf:return /self->ts/
{
printf("%d", (timestamp - self->ts) / 1000);
self->ts = 0;
stack();
}'
...
<reboot>
# dtrace -a -e
CPU ID FUNCTION:NAME
0 17161 vprintf:return 419
kernel`printf+0x43
kernel`randomdev_modevent+0x26
kernel`module_register_init+0xc0
kernel`mi_startup+0x9c
kernel`0xffffffff8028656c
...
More information about the freebsd-current
mailing list