Annotate parts of SYSINIT cpu with tslog

[cperciva]

Summary

Booting an amd64 kernel on Firecracker with 1 CPU and 128 MB of RAM,
SYSINIT cpu takes roughly 2770 us:

• 2280 us in vm_ksubmap_init
  • 535 us in kmem_malloc
    • 450 us in pmap_zero_page
  • 1720 us in pmap_growkernel
    • 1620 us in pmap_zero_page
• 80 us in bufinit
• 480 us in cpu_setregs
  • 430 us in cpu_setregs calling load_cr0

Much of this is hypervisor overhead: load_cr0 is slow because it traps
to the hypervisor, and 99% of the time in pmap_zero_page is spent when
we first touch the page, presumably due to the host Linux kernel
faulting in backing pages one by one.

[mjg]

i wonder if this is the right approach to begin with

have you considered a different take on it: instrument all functions with a timestamp grab on entry/exit. this will have to make sure tail call is disabled. that what you will get an almost complete picture who takes time, but in some cases it may still require extra effort to find out why (say a func is long and is doing a bunch of unrelated ops).

sys/vm/vm_kern.c

747–748

missing tsexit

[cperciva]

In D40327#918269, @mjg wrote:

i wonder if this is the right approach to begin with

have you considered a different take on it: instrument all functions with a timestamp grab on entry/exit. this will have to make sure tail call is disabled. that what you will get an almost complete picture who takes time, but in some cases it may still require extra effort to find out why (say a func is long and is doing a bunch of unrelated ops).

I considered that, but (quite apart from not being sure how to get the compiler to add that) there are functions which are called far too many times to be usefully logged (we only have a fixed size buffer). Annotating functions of interest has worked pretty well.

[cperciva]

Add missing TSEXIT