Date: Fri, 22 Dec 2017 12:08:18 -0500 From: Mark Johnston <markj@FreeBSD.org> To: Colin Percival <cperciva@tarsnap.com> Cc: "freebsd-current@freebsd.org" <freebsd-current@freebsd.org> Subject: Re: [Request for review] Profiling the FreeBSD kernel boot Message-ID: <20171222170818.GA39071@raichu> In-Reply-To: <010001607d9c59d5-15b6b788-a7ea-4edf-96e4-1235dd1a5c26-000000@email.amazonses.com> References: <010001607d9c59d5-15b6b788-a7ea-4edf-96e4-1235dd1a5c26-000000@email.amazonses.com>
next in thread | previous in thread | raw e-mail | index | archive | help
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
...
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20171222170818.GA39071>