Re: [Request for review] Profiling the FreeBSD kernel boot

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
  ...