Use the TSLOG framework to record entry/exit timestamps for DELAY and

_vprintf; these functions are called in many places and can contribute
meaningfully to the total time spent booting.

sys/arm/amlogic/aml8726/aml8726_timer.c

@@ -347,6 +347,7 @@ DELAY(int usec)
 			}
 		return;
 	}
+	TSENTER();
 
 	/*
 	 * Some of the other timers in the source tree do this calculation as:
@@ -391,4 +392,5 @@ DELAY(int usec)
 		previous = now;
 		remaining -= delta;
 	}
+	TSEXIT();
 }

sys/arm/arm/generic_timer.c

@@ -526,6 +526,7 @@ DELAY(int usec)
 {
 	int32_t counts;
 
+	TSENTER();
 	/*
 	 * Check the timers are setup, if not just
 	 * use a for loop for the meantime
@@ -540,6 +541,7 @@ DELAY(int usec)
 				cpufunc_nullop();
 	} else
 		arm_tmr_do_delay(usec, arm_tmr_sc);
+	TSEXIT();
 }
 #endif
 

sys/arm/arm/machdep.c

@@ -347,7 +347,9 @@ void
 DELAY(int usec)
 {
 
+	TSENTER();
 	delay_impl(usec, delay_arg);
+	TSEXIT();
 }
 #endif
 

sys/arm/arm/mpcore_timer.c

@@ -547,6 +547,7 @@ DELAY(int usec)
 	struct arm_tmr_softc *sc;
 	int32_t counts;
 
+	TSENTER();
 	/* Check the timers are setup, if not just use a for loop for the meantime */
 	if (arm_tmr_tc == NULL || arm_tmr_timecount.tc_frequency == 0) {
 		for (; usec > 0; usec--)
@@ -558,5 +559,6 @@ DELAY(int usec)
 		sc = arm_tmr_tc->tc_priv;
 		arm_tmr_delay(usec, sc);
 	}
+	TSEXIT();
 }
 #endif

sys/arm/at91/at91_machdep.c

@@ -672,8 +672,10 @@ void
 DELAY(int n)
 {
 
+	TSENTER();
 	if (soc_info.soc_data)
 		soc_info.soc_data->soc_delay(n);
+	TSEXIT();
 }
 
 void

sys/arm/cavium/cns11xx/timer.c

@@ -122,6 +122,7 @@ DELAY(int usec)
 				;
 		return;
 	}
+	TSENTER();
 
 	val = read_timer_counter_noint();
 	nticks = (((APB_clock / 1000) * usec) / 1000) + 100;
@@ -135,7 +136,7 @@ DELAY(int usec)
 
 		val = val_temp;
 	}
-
+	TSEXIT();
 }
 
 /*

sys/arm/lpc/lpc_timer.c

@@ -292,6 +292,7 @@ DELAY(int usec)
 				;
 		return;
 	}
+	TSENTER();
 
 	first = lpc_get_timecount(&lpc_timecounter);
 	while (val > 0) {
@@ -304,4 +305,5 @@ DELAY(int usec)
 		val -= (last - first);
 		first = last;
 	}
+	TSEXIT();
 }

sys/arm/mv/timer.c

@@ -272,6 +272,7 @@ DELAY(int usec)
 				__asm __volatile("nop" ::: "memory");
 		return;
 	}
+	TSENTER();
 
 	val = mv_get_timer(1);
 	nticks = ((MV_CLOCK_SRC / 1000000 + 1) * usec);
@@ -285,6 +286,7 @@ DELAY(int usec)
 
 		val = val_temp;
 	}
+	TSEXIT();
 }
 
 static uint32_t

sys/arm/ralink/rt1310_timer.c

@@ -326,6 +326,7 @@ DELAY(int usec)
 				;
 		return;
 	}
+	TSENTER();
 
 	first = rt1310_get_timecount(&rt1310_timecounter);
 	while (val > 0) {
@@ -338,4 +339,5 @@ DELAY(int usec)
 		val -= (last - first);
 		first = last;
 	}
+	TSEXIT();
 }

sys/arm/xscale/i8134x/i80321_timer.c

@@ -428,6 +428,7 @@ DELAY(int n)
 {
 	uint32_t cur, last, delta, usecs;
 
+	TSENTER();
 	/*
 	 * This works by polling the timer and counting the
 	 * number of microseconds that go by.
@@ -451,6 +452,7 @@ DELAY(int n)
 			delta %= COUNTS_PER_USEC;
 		}
 	}
+	TSEXIT();
 }
 
 /*

sys/arm/xscale/ixp425/ixp425_timer.c

@@ -213,6 +213,7 @@ DELAY(int n)
 
 	if (n == 0)
 		return;
+	TSENTER();
 
 	/*
 	 * Clamp the timeout at a maximum value (about 32 seconds with
@@ -233,6 +234,7 @@ DELAY(int n)
 		usecs -= (int)(last - first);
 		first = last;
 	}
+	TSEXIT();
 }
 
 /*

sys/arm/xscale/pxa/pxa_timer.c

@@ -214,10 +214,12 @@ DELAY(int usec)
 				;
 		return;
 	}
+	TSENTER();
 
 	val = pxa_timer_get_oscr();
 	val += (PXA_TIMER_FREQUENCY * usec) / 1000000;
 	while (pxa_timer_get_oscr() <= val);
+	TSEXIT();
 }
 
 uint32_t

sys/kern/subr_prf.c

@@ -276,6 +276,7 @@ _vprintf(int level, int flags, const char *fmt, va_list ap)
 	char bufr[PRINTF_BUFR_SIZE];
 #endif
 
+	TSENTER();
 	pca.tty = NULL;
 	pca.pri = level;
 	pca.flags = flags;
@@ -303,6 +304,7 @@ _vprintf(int level, int flags, const char *fmt, va_list ap)
 	}
 #endif
 
+	TSEXIT();
 	return (retval);
 }
 

sys/mips/ingenic/jz4780_timer.c

@@ -283,6 +283,7 @@ DELAY(int usec)
 			}
 		return;
 	}
+	TSENTER();
 
 	/*
 	 * Some of the other timers in the source tree do this calculation as:
@@ -327,6 +328,7 @@ DELAY(int usec)
 		previous = now;
 		remaining -= delta;
 	}
+	TSEXIT();
 }
 
 void

sys/mips/mips/tick.c

@@ -197,6 +197,7 @@ DELAY(int n)
 {
 	uint32_t cur, last, delta, usecs;
 
+	TSENTER();
 	/*
 	 * This works by polling the timer and counting the number of
 	 * microseconds that go by.
@@ -220,6 +221,7 @@ DELAY(int n)
 			delta %= cycles_per_usec;
 		}
 	}
+	TSEXIT();
 }
 
 static int

sys/mips/nlm/tick.c

@@ -198,6 +198,7 @@ DELAY(int n)
 {
 	uint32_t cur, last, delta, usecs;
 
+	TSENTER();
 	/*
 	 * This works by polling the timer and counting the number of
 	 * microseconds that go by.
@@ -221,6 +222,7 @@ DELAY(int n)
 			delta %= cycles_per_usec;
 		}
 	}
+	TSEXIT();
 }
 
 static int

sys/mips/rmi/tick.c

@@ -195,6 +195,7 @@ DELAY(int n)
 {
 	uint32_t cur, last, delta, usecs;
 
+	TSENTER();
 	/*
 	 * This works by polling the timer and counting the number of
 	 * microseconds that go by.
@@ -218,6 +219,7 @@ DELAY(int n)
 			delta %= cycles_per_usec;
 		}
 	}
+	TSEXIT();
 }
 
 static int

sys/powerpc/powerpc/clock.c

@@ -305,9 +305,11 @@ DELAY(int n)
 {
 	u_quad_t	tb, ttb;
 
+	TSENTER();
 	tb = mftb();
 	ttb = tb + howmany(n * 1000, ns_per_tick);
 	while (tb < ttb)
 		tb = mftb();
+	TSEXIT();
 }
 

sys/riscv/riscv/timer.c

@@ -261,6 +261,7 @@ DELAY(int usec)
 				cpufunc_nullop();
 		return;
 	}
+	TSENTER();
 
 	/* Get the number of times to count */
 	counts_per_usec = ((riscv_timer_timecount.tc_frequency / 1000000) + 1);
@@ -283,4 +284,5 @@ DELAY(int usec)
 		counts -= (int64_t)(last - first);
 		first = last;
 	}
+	TSEXIT();
 }

sys/sparc64/sparc64/clock.c

@@ -45,6 +45,7 @@ DELAY(int usec)
 
 	if (usec < 0)
 		return;
+	TSENTER();
 
 	/*
 	 * We avoid being migrated to another CPU with a possibly
@@ -57,5 +58,6 @@ DELAY(int usec)
 		cpu_spinwait();
 
 	sched_unpin();
+	TSEXIT();
 }
 

sys/x86/x86/delay.c

@@ -101,8 +101,12 @@ void
 DELAY(int n)
 {
 
-	if (delay_tc(n))
+	TSENTER();
+	if (delay_tc(n)) {
+		TSEXIT();
 		return;
+	}
 
 	init_ops.early_delay(n);
+	TSEXIT();
 }