tslog: Annotate some early boot functions

Booting an amd64 kernel on Firecracker with 1 CPU and 128 MB of RAM,
hammer_time takes roughly 2740 us:
* 55 us in xen_pvh_parse_preload_data
  * 20 us in boot_parse_cmdline_delim
  * 20 us in boot_env_to_howto
* 15 us in identify_hypervisor
* 1320 us in link_elf_reloc
  * 1310 us in relocate_file1 handling ef->rela
* 25 us in init_param1
* 30 us in dpcpu_init
* 355 us in initializecpu
  * 255 us in initializecpu calling load_cr4
* 425 us in getmemsize
  * 280 us in pmap_bootstrap
    * 205 us in create_pagetables
* 10 us in init_param2
* 25 us in pci_early_quirks
* 60 us in cninit
* 90 us in kdb_init
* 105 us in msgbufinit
* 20 us in fpuinit
* 205 us elsewhere in hammer_time

Some of these are unavoidable (e.g. identify_hypervisor uses CPUID and
load_cr4 loads the CR4 register, both of which trap to the hypervisor)
but others may deserve attention.

Sponsored by:	https://www.patreon.com/cperciva
Differential Revision:	https://reviews.freebsd.org/D40325

sys/amd64/amd64/fpu.c

@@ -48,6 +48,7 @@ __FBSDID("$FreeBSD$");
 #include <sys/proc.h>
 #include <sys/sysctl.h>
 #include <sys/sysent.h>
+#include <sys/tslog.h>
 #include <machine/bus.h>
 #include <sys/rman.h>
 #include <sys/signalvar.h>
@@ -360,6 +361,7 @@ fpuinit(void)
 	u_int mxcsr;
 	u_short control;
 
+	TSENTER();
 	if (IS_BSP())
 		fpuinit_bsp1();
 
@@ -401,6 +403,7 @@ fpuinit(void)
 	ldmxcsr(mxcsr);
 	start_emulating();
 	intr_restore(saveintr);
+	TSEXIT();
 }
 
 /*

sys/amd64/amd64/initcpu.c

@@ -276,6 +276,7 @@ initializecpu(void)
 	uint64_t msr;
 	uint32_t cr4;
 
+	TSENTER();
 	cr4 = rcr4();
 	if ((cpu_feature & CPUID_XMM) && (cpu_feature & CPUID_FXSR)) {
 		cr4 |= CR4_FXSR | CR4_XMM;
@@ -311,7 +312,9 @@ initializecpu(void)
 		if (cpu_stdext_feature & CPUID_STDEXT_SMAP)
 			cr4 |= CR4_SMAP;
 	}
+	TSENTER2("load_cr4");
 	load_cr4(cr4);
+	TSEXIT2("load_cr4");
 	/* Reload cpu ext features to reflect cr4 changes */
 	if (IS_BSP() && cold)
 		identify_cpu_ext_features();
@@ -340,6 +343,7 @@ initializecpu(void)
 
 	if (!IS_BSP())
 		cpu_init_small_core();
+	TSEXIT();
 }
 
 void

sys/amd64/amd64/machdep.c

@@ -870,6 +870,7 @@ getmemsize(caddr_t kmdp, u_int64_t first)
 	quad_t dcons_addr, dcons_size;
 	int page_counter;
 
+	TSENTER();
 	/*
 	 * Tell the physical memory allocator about pages used to store
 	 * the kernel and preloaded data.  See kmem_bootstrap_free().
@@ -1125,6 +1126,7 @@ getmemsize(caddr_t kmdp, u_int64_t first)
 
 	/* Map the message buffer. */
 	msgbufp = (struct msgbuf *)PHYS_TO_DMAP(phys_avail[pa_indx]);
+	TSEXIT();
 }
 
 static caddr_t

sys/amd64/amd64/pmap.c

@@ -1668,6 +1668,7 @@ create_pagetables(vm_paddr_t *firstaddr)
 #endif
 	int i, j, ndm1g, nkpdpe, nkdmpde;
 
+	TSENTER();
 	/* Allocate page table pages for the direct map */
 	ndmpdp = howmany(ptoa(Maxmem), NBPDP);
 	if (ndmpdp < 4)		/* Minimum 4GB of dirmap */
@@ -1884,6 +1885,7 @@ create_pagetables(vm_paddr_t *firstaddr)
 	}
 
 	kernel_pml4 = (pml4_entry_t *)PHYS_TO_DMAP(KPML4phys);
+	TSEXIT();
 }
 
 /*
@@ -1906,6 +1908,7 @@ pmap_bootstrap(vm_paddr_t *firstaddr)
 	u_long res;
 	int i;
 
+	TSENTER();
 	KERNend = *firstaddr;
 	res = atop(KERNend - (vm_paddr_t)kernphys);
 
@@ -2061,6 +2064,7 @@ pmap_bootstrap(vm_paddr_t *firstaddr)
 		 */
 		load_cr4(rcr4() | CR4_PCIDE);
 	}
+	TSEXIT();
 }
 
 /*

sys/kern/kern_cons.c

@@ -64,6 +64,7 @@ __FBSDID("$FreeBSD$");
 #include <sys/reboot.h>
 #include <sys/sysctl.h>
 #include <sys/sbuf.h>
+#include <sys/tslog.h>
 #include <sys/tty.h>
 #include <sys/uio.h>
 #include <sys/vnode.h>
@@ -134,6 +135,7 @@ cninit(void)
 {
 	struct consdev *best_cn, *cn, **list;
 
+	TSENTER();
 	/*
 	 * Check if we should mute the console (for security reasons perhaps)
 	 * It can be changes dynamically using sysctl kern.consmute
@@ -195,6 +197,7 @@ cninit(void)
 	 */
 	early_putc = NULL;
 #endif
+	TSEXIT();
 }
 
 void

sys/kern/link_elf.c

@@ -49,6 +49,7 @@ __FBSDID("$FreeBSD$");
 #include <sys/vnode.h>
 #include <sys/linker.h>
 #include <sys/sysctl.h>
+#include <sys/tslog.h>
 
 #include <machine/elf.h>
 
@@ -1431,6 +1432,7 @@ relocate_file1(elf_file_t ef, elf_lookup_fn lookup, elf_reloc_fn reloc,
 	const Elf_Rela *rela;
 	const char *symname;
 
+	TSENTER();
 #define	APPLY_RELOCS(iter, tbl, tblsize, type) do {			\
 	for ((iter) = (tbl); (iter) != NULL &&				\
 	    (iter) < (tbl) + (tblsize) / sizeof(*(iter)); (iter)++) {	\
@@ -1449,12 +1451,15 @@ relocate_file1(elf_file_t ef, elf_lookup_fn lookup, elf_reloc_fn reloc,
 } while (0)
 
 	APPLY_RELOCS(rel, ef->rel, ef->relsize, ELF_RELOC_REL);
+	TSENTER2("ef->rela");
 	APPLY_RELOCS(rela, ef->rela, ef->relasize, ELF_RELOC_RELA);
+	TSEXIT2("ef->rela");
 	APPLY_RELOCS(rel, ef->pltrel, ef->pltrelsize, ELF_RELOC_REL);
 	APPLY_RELOCS(rela, ef->pltrela, ef->pltrelasize, ELF_RELOC_RELA);
 
 #undef APPLY_RELOCS
 
+	TSEXIT();
 	return (0);
 }
 
@@ -1950,6 +1955,7 @@ link_elf_ireloc(caddr_t kmdp)
 	struct elf_file eff;
 	elf_file_t ef;
 
+	TSENTER();
 	ef = &eff;
 
 	bzero_early(ef, sizeof(*ef));
@@ -1966,6 +1972,7 @@ link_elf_ireloc(caddr_t kmdp)
 
 	link_elf_preload_parse_symbols(ef);
 	relocate_file1(ef, elf_lookup_ifunc, elf_reloc, true);
+	TSEXIT();
 }
 
 #if defined(__aarch64__) || defined(__amd64__)

sys/kern/subr_boot.c

@@ -48,6 +48,7 @@ __FBSDID("$FreeBSD$");
 #endif
 #include <sys/reboot.h>
 #include <sys/boot.h>
+#include <sys/tslog.h>
 
 #ifdef _KERNEL
 #define SETENV(k, v)	kern_setenv(k, v)
@@ -95,12 +96,14 @@ boot_env_to_howto(void)
 	int i, howto;
 	char *val;
 
+	TSENTER();
 	for (howto = 0, i = 0; howto_names[i].ev != NULL; i++) {
 		val = GETENV(howto_names[i].ev);
 		if (val != NULL && strcasecmp(val, "no") != 0)
 			howto |= howto_names[i].mask;
 		FREE(val);
 	}
+	TSEXIT();
 	return (howto);
 }
 
@@ -193,12 +196,14 @@ boot_parse_cmdline_delim(char *cmdline, const char *delim)
 	char *v;
 	int howto;
 
+	TSENTER();
 	howto = 0;
 	while ((v = strsep(&cmdline, delim)) != NULL) {
 		if (*v == '\0')
 			continue;
 		howto |= boot_parse_arg(v);
 	}
+	TSEXIT();
 	return (howto);
 }
 

sys/kern/subr_kdb.c

@@ -46,6 +46,7 @@ __FBSDID("$FreeBSD$");
 #include <sys/smp.h>
 #include <sys/stack.h>
 #include <sys/sysctl.h>
+#include <sys/tslog.h>
 
 #include <machine/kdb.h>
 #include <machine/pcb.h>
@@ -559,6 +560,7 @@ kdb_init(void)
 	struct kdb_dbbe *be, **iter;
 	int cur_pri, pri;
 
+	TSENTER();
 	kdb_active = 0;
 	kdb_dbbe = NULL;
 	cur_pri = -1;
@@ -582,6 +584,7 @@ kdb_init(void)
 		printf("KDB: current backend: %s\n",
 		    kdb_dbbe->dbbe_name);
 	}
+	TSEXIT();
 }
 
 /*

sys/kern/subr_param.c

@@ -171,6 +171,7 @@ void
 init_param1(void)
 {
 
+	TSENTER();
 #if !defined(__arm64__)
 	TUNABLE_INT_FETCH("kern.kstack_pages", &kstack_pages);
 #endif
@@ -245,6 +246,7 @@ init_param1(void)
 		pid_max = 300;
 
 	TUNABLE_INT_FETCH("vfs.unmapped_buf_allowed", &unmapped_buf_allowed);
+	TSEXIT();
 }
 
 /*
@@ -254,6 +256,7 @@ void
 init_param2(long physpages)
 {
 
+	TSENTER();
 	/* Base parameters */
 	maxusers = MAXUSERS;
 	TUNABLE_INT_FETCH("kern.maxusers", &maxusers);
@@ -335,6 +338,7 @@ init_param2(long physpages)
 	if (maxpipekva > (VM_MAX_KERNEL_ADDRESS - VM_MIN_KERNEL_ADDRESS) / 64)
 		maxpipekva = (VM_MAX_KERNEL_ADDRESS - VM_MIN_KERNEL_ADDRESS) /
 		    64;
+	TSEXIT();
 }
 
 /*

sys/kern/subr_pcpu.c

@@ -103,6 +103,7 @@ dpcpu_init(void *dpcpu, int cpuid)
 {
 	struct pcpu *pcpu;
 
+	TSENTER();
 	pcpu = pcpu_find(cpuid);
 	pcpu->pc_dynamic = (uintptr_t)dpcpu - DPCPU_START;
 
@@ -115,6 +116,7 @@ dpcpu_init(void *dpcpu, int cpuid)
 	 * Place it in the global pcpu offset array.
 	 */
 	dpcpu_off[cpuid] = pcpu->pc_dynamic;
+	TSEXIT();
 }
 
 static void

sys/kern/subr_prf.c

@@ -58,6 +58,7 @@ __FBSDID("$FreeBSD$");
 #include <sys/proc.h>
 #include <sys/stddef.h>
 #include <sys/sysctl.h>
+#include <sys/tslog.h>
 #include <sys/tty.h>
 #include <sys/syslog.h>
 #include <sys/cons.h>
@@ -1037,6 +1038,7 @@ msgbufinit(void *ptr, int size)
 	static struct msgbuf *oldp = NULL;
 	bool print_boot_tag;
 
+	TSENTER();
 	size -= sizeof(*msgbufp);
 	cp = (char *)ptr;
 	print_boot_tag = !msgbufmapped;
@@ -1052,6 +1054,7 @@ msgbufinit(void *ptr, int size)
 	if (print_boot_tag && *current_boot_tag != '\0')
 		printf("%s\n", current_boot_tag);
 	oldp = msgbufp;
+	TSEXIT();
 }
 
 /* Sysctls for accessing/clearing the msgbuf */

sys/x86/pci/pci_early_quirks.c

@@ -33,6 +33,7 @@ __FBSDID("$FreeBSD$");
 #include <sys/bus.h>
 #include <sys/kernel.h>
 #include <sys/sysctl.h>
+#include <sys/tslog.h>
 
 #include <vm/vm.h>
 /* XXX: enable this once the KPI is available */
@@ -317,5 +318,7 @@ void
 pci_early_quirks(void)
 {
 
+	TSENTER();
 	intel_graphics_stolen();
+	TSEXIT();
 }

sys/x86/x86/identcpu.c

@@ -1424,6 +1424,7 @@ identify_hypervisor(void)
 	u_int regs[4];
 	char *p;
 
+	TSENTER();
 	/*
 	 * If CPUID2_HV is set, we are running in a hypervisor environment.
 	 */
@@ -1432,8 +1433,10 @@ identify_hypervisor(void)
 		identify_hypervisor_cpuid_base();
 
 		/* If we have a definitive vendor, we can return now. */
-		if (*hv_vendor != '\0')
+		if (*hv_vendor != '\0') {
+			TSEXIT();
 			return;
+		}
 	}
 
 	/*
@@ -1446,11 +1449,13 @@ identify_hypervisor(void)
 			if (regs[1] == VMW_HVMAGIC) {
 				vm_guest = VM_GUEST_VMWARE;
 				freeenv(p);
+				TSEXIT();
 				return;
 			}
 		}
 		freeenv(p);
 	}
+	TSEXIT();
 }
 
 bool

sys/x86/xen/pv.c

@@ -49,6 +49,7 @@ __FBSDID("$FreeBSD$");
 #include <sys/mutex.h>
 #include <sys/smp.h>
 #include <sys/efi.h>
+#include <sys/tslog.h>
 
 #include <vm/vm.h>
 #include <vm/vm_extern.h>
@@ -417,6 +418,7 @@ xen_pvh_parse_preload_data(uint64_t modulep)
 	char *envp;
 	char acpi_rsdp[19];
 
+	TSENTER();
 	if (start_info->modlist_paddr != 0) {
 		struct hvm_modlist_entry *mod;
 		const char *cmdline;
@@ -507,6 +509,7 @@ xen_pvh_parse_preload_data(uint64_t modulep)
 #ifdef DDB
 	xen_pvh_parse_symtab();
 #endif
+	TSEXIT();
 	return (kmdp);
 }