loader: Use tslog to instrument some functions

In my initial testing, these are the functions which showed up as
being worth instrumenting.  More may be added later.

common/console.c: cons_probe
common/gfx_fb.c: read_list, insert_font, autoload_font
common/interp.c: interact
common/interp_lua.c: interp_init, interp_run
efi/libefi/efipart.c: efipart_readwrite
i386/libi386/biosdisk.c: bd_init, bd_open, bd_edd_io, bd_chs_io, bd_io
libsa/open.c: open
libsa/read.c: read
libsa/twiddle.c: twiddle

Note that profiling interp_run may be of questionable utility as it
may depend on user behaviour (e.g. pressing keys).

Reviewed by:	kevans (earlier version)

9 files changed, 70 insertions, 4 deletions

diff --git a/stand/common/console.c b/stand/common/console.c
index 5b2ddfb10f69..7886f9386c14 100644
--- a/stand/common/console.c
+++ b/stand/common/console.c
@@ -53,6 +53,8 @@ cons_probe(void)
 	int	active;
 	char	*prefconsole;
 
+	TSENTER();
+
 	/* We want a callback to install the new value when this var changes. */
 	env_setenv("twiddle_divisor", EV_VOLATILE, "1", twiddle_set,
 	    env_nounset);
@@ -98,6 +100,8 @@ cons_probe(void)
 		    env_nounset);
 		free(prefconsole);
 	}
+
+	TSEXIT();
 }
 
 int
diff --git a/stand/common/gfx_fb.c b/stand/common/gfx_fb.c
index 92af49913748..522c70327425 100644
--- a/stand/common/gfx_fb.c
+++ b/stand/common/gfx_fb.c
@@ -2430,6 +2430,8 @@ read_list(char *fonts)
 	char buf[PATH_MAX];
 	int fd, len;
 
+	TSENTER();
+
 	dir = strdup(fonts);
 	if (dir == NULL)
 		return (NULL);
@@ -2477,6 +2479,7 @@ read_list(char *fonts)
 		SLIST_INSERT_HEAD(nl, np, n_entry);
 	}
 	close(fd);
+	TSEXIT();
 	return (nl);
 }
 
@@ -2494,6 +2497,8 @@ insert_font(char *name, FONT_FLAGS flags)
 	int fd;
 	char *font_name;
 
+	TSENTER();
+
 	font_name = NULL;
 	if (flags == FONT_BUILTIN) {
 		/*
@@ -2540,6 +2545,7 @@ insert_font(char *name, FONT_FLAGS flags)
 			free(entry->font_name);
 			entry->font_name = font_name;
 			entry->font_flags = FONT_RELOAD;
+			TSEXIT();
 			return (true);
 		}
 	}
@@ -2563,6 +2569,7 @@ insert_font(char *name, FONT_FLAGS flags)
 
 	if (STAILQ_EMPTY(&fonts)) {
 		STAILQ_INSERT_HEAD(&fonts, fp, font_next);
+		TSEXIT();
 		return (true);
 	}
 
@@ -2581,6 +2588,7 @@ insert_font(char *name, FONT_FLAGS flags)
 				STAILQ_INSERT_AFTER(&fonts, previous, fp,
 				    font_next);
 			}
+			TSEXIT();
 			return (true);
 		}
 		next = STAILQ_NEXT(entry, font_next);
@@ -2588,10 +2596,12 @@ insert_font(char *name, FONT_FLAGS flags)
 		    size > next->font_data->vfbd_width *
 		    next->font_data->vfbd_height) {
 			STAILQ_INSERT_AFTER(&fonts, entry, fp, font_next);
+			TSEXIT();
 			return (true);
 		}
 		previous = entry;
 	}
+	TSEXIT();
 	return (true);
 }
 
@@ -2650,6 +2660,8 @@ autoload_font(bool bios)
 	struct name_list *nl;
 	struct name_entry *np;
 
+	TSENTER();
+
 	nl = read_list("/boot/fonts/INDEX.fonts");
 	if (nl == NULL)
 		return;
@@ -2671,6 +2683,8 @@ autoload_font(bool bios)
 	}
 
 	(void) cons_update_mode(gfx_state.tg_fb_type != FB_TEXT);
+
+	TSEXIT();
 }
 
 COMMAND_SET(load_font, "loadfont", "load console font from file", command_font);
diff --git a/stand/common/interp.c b/stand/common/interp.c
index a0a6bd486614..ab68694d61b7 100644
--- a/stand/common/interp.c
+++ b/stand/common/interp.c
@@ -48,6 +48,8 @@ interact(void)
 	static char		input[256];		/* big enough? */
 	const char * volatile	interp_identifier;
 
+	TSENTER();
+
 	/*
 	 * Because interp_identifier is volatile, it cannot be optimized out by
 	 * the compiler as it's considered an externally observable event.  This
diff --git a/stand/common/interp_lua.c b/stand/common/interp_lua.c
index 94001918e151..8a420660683e 100644
--- a/stand/common/interp_lua.c
+++ b/stand/common/interp_lua.c
@@ -107,6 +107,8 @@ interp_init(void)
 	const char *filename;
 	const luaL_Reg *lib;
 
+	TSENTER();
+
 	setenv("script.lang", "lua", 1);
 	LDBG("creating context");
 
@@ -131,6 +133,8 @@ interp_init(void)
 		lua_pop(luap, 1);
 		setenv("autoboot_delay", "NO", 1);
 	}
+
+	TSEXIT();
 }
 
 int
@@ -142,6 +146,7 @@ interp_run(const char *line)
 	struct interp_lua_softc	*softc = &lua_softc;
 	int status, ret;
 
+	TSENTER();
 	luap = softc->luap;
 	LDBG("executing line...");
 	if ((status = luaL_dostring(luap, line)) != 0) {
@@ -186,6 +191,7 @@ interp_run(const char *line)
 		}
 	}
 
+	TSEXIT();
 	return (status == 0 ? CMD_OK : CMD_ERROR);
 }
 
diff --git a/stand/efi/libefi/efipart.c b/stand/efi/libefi/efipart.c
index 424df7d2e423..aede28ef40c3 100644
--- a/stand/efi/libefi/efipart.c
+++ b/stand/efi/libefi/efipart.c
@@ -1006,6 +1006,8 @@ efipart_readwrite(EFI_BLOCK_IO *blkio, int rw, daddr_t blk, daddr_t nblks,
 {
 	EFI_STATUS status;
 
+	TSENTER();
+
 	if (blkio == NULL)
 		return (ENXIO);
 	if (blk < 0 || blk > blkio->Media->LastBlock)
@@ -1032,6 +1034,7 @@ efipart_readwrite(EFI_BLOCK_IO *blkio, int rw, daddr_t blk, daddr_t nblks,
 		printf("%s: rw=%d, blk=%ju size=%ju status=%lu\n", __func__, rw,
 		    blk, nblks, EFI_ERROR_CODE(status));
 	}
+	TSEXIT();
 	return (efi_status_to_errno(status));
 }
 
diff --git a/stand/i386/libi386/biosdisk.c b/stand/i386/libi386/biosdisk.c
index 00d2de5de418..2c52617f255d 100644
--- a/stand/i386/libi386/biosdisk.c
+++ b/stand/i386/libi386/biosdisk.c
@@ -339,6 +339,8 @@ bd_init(void)
 	int base, unit;
 	bdinfo_t *bd;
 
+	TSENTER();
+
 	base = 0x80;
 	for (unit = 0; unit < *(unsigned char *)PTOV(BIOS_NUMDRIVES); unit++) {
 		/*
@@ -358,6 +360,7 @@ bd_init(void)
 		STAILQ_INSERT_TAIL(&hdinfo, bd, bd_link);
 	}
 	bcache_add_dev(unit);
+	TSEXIT();
 	return (0);
 }
 
@@ -840,6 +843,8 @@ bd_open(struct open_file *f, ...)
 	va_list ap;
 	int rc;
 
+	TSENTER();
+
 	va_start(ap, f);
 	dev = va_arg(ap, struct disk_devdesc *);
 	va_end(ap);
@@ -873,6 +878,7 @@ bd_open(struct open_file *f, ...)
 			}
 		}
 	}
+	TSEXIT();
 	return (rc);
 }
 
@@ -1135,6 +1141,8 @@ bd_edd_io(bdinfo_t *bd, daddr_t dblk, int blks, caddr_t dest,
 {
 	static struct edd_packet packet;
 
+	TSENTER();
+
 	packet.len = sizeof(struct edd_packet);
 	packet.count = blks;
 	packet.off = VTOPOFF(dest);
@@ -1152,6 +1160,8 @@ bd_edd_io(bdinfo_t *bd, daddr_t dblk, int blks, caddr_t dest,
 	v86int();
 	if (V86_CY(v86.efl))
 		return (v86.eax >> 8);
+
+	TSEXIT();
 	return (0);
 }
 
@@ -1161,6 +1171,8 @@ bd_chs_io(bdinfo_t *bd, daddr_t dblk, int blks, caddr_t dest,
 {
 	uint32_t x, bpc, cyl, hd, sec;
 
+	TSENTER();
+
 	bpc = bd->bd_sec * bd->bd_hds;	/* blocks per cylinder */
 	x = dblk;
 	cyl = x / bpc;			/* block # / blocks per cylinder */
@@ -1189,6 +1201,7 @@ bd_chs_io(bdinfo_t *bd, daddr_t dblk, int blks, caddr_t dest,
 	v86int();
 	if (V86_CY(v86.efl))
 		return (v86.eax >> 8);
+	TSEXIT();
 	return (0);
 }
 
@@ -1206,6 +1219,8 @@ bd_io(struct disk_devdesc *dev, bdinfo_t *bd, daddr_t dblk, int blks,
 {
 	int result, retry;
 
+	TSENTER();
+
 	/* Just in case some idiot actually tries to read/write -1 blocks... */
 	if (blks < 0)
 		return (-1);
@@ -1264,6 +1279,8 @@ bd_io(struct disk_devdesc *dev, bdinfo_t *bd, daddr_t dblk, int blks,
 		}
 	}
 
+	TSEXIT();
+
 	return (result);
 }
 
diff --git a/stand/libsa/open.c b/stand/libsa/open.c
index d1f1fcf9bb4d..9590508b0015 100644
--- a/stand/libsa/open.c
+++ b/stand/libsa/open.c
@@ -96,6 +96,8 @@ open(const char *fname, int mode)
 	int fd, i, error, besterror;
 	const char *file;
 
+	TSENTER();
+
 	if ((fd = o_gethandle()) == -1) {
 		errno = EMFILE;
 		return (-1);
@@ -126,6 +128,7 @@ open(const char *fname, int mode)
 	if (file == NULL || *file == '\0') {
 		f->f_flags |= F_RAW;
 		f->f_rabuf = NULL;
+		TSEXIT();
 		return (fd);
 	}
 
@@ -149,10 +152,12 @@ open(const char *fname, int mode)
 err:
 	f->f_flags = 0;
 	errno = error;
+	TSEXIT();
 	return (-1);
 
 ok:
 	f->f_ops = fs;
 	o_rainit(f);
+	TSEXIT();
 	return (fd);
 }
diff --git a/stand/libsa/read.c b/stand/libsa/read.c
index 021425371ee7..7ad75c387a5d 100644
--- a/stand/libsa/read.c
+++ b/stand/libsa/read.c
@@ -72,6 +72,8 @@ read(int fd, void *dest, size_t bcount)
 	struct open_file *f = &files[fd];
 	size_t resid;
 
+	TSENTER();
+
 	if ((unsigned)fd >= SOPEN_MAX || !(f->f_flags & F_READ)) {
 		errno = EBADF;
 		return (-1);
@@ -83,6 +85,7 @@ read(int fd, void *dest, size_t bcount)
 		if (errno)
 			return (-1);
 		f->f_offset += resid;
+		TSEXIT();
 		return (resid);
 	}
 
@@ -102,8 +105,10 @@ read(int fd, void *dest, size_t bcount)
 			f->f_raoffset += ccount;
 			f->f_ralen -= ccount;
 			resid -= ccount;
-			if (resid == 0)
+			if (resid == 0) {
+				TSEXIT();
 				return (bcount);
+			}
 			dest = (char *)dest + ccount;
 		}
 
@@ -116,6 +121,7 @@ read(int fd, void *dest, size_t bcount)
 			errno = (f->f_ops->fo_read)(f, dest, resid, &cresid);
 			if (errno != 0)
 				return (-1);
+			TSEXIT();
 			return (bcount - cresid);
 		}
 
@@ -127,7 +133,9 @@ read(int fd, void *dest, size_t bcount)
 		f->f_raoffset = 0;
 		f->f_ralen = SOPEN_RASIZE - cresid;
 		/* no more data, return what we had */
-		if (f->f_ralen == 0)
+		if (f->f_ralen == 0) {
+			TSEXIT();
 			return (bcount - resid);
+		}
 	}
 }
diff --git a/stand/libsa/twiddle.c b/stand/libsa/twiddle.c
index 31828542f7f3..7565295fa1a3 100644
--- a/stand/libsa/twiddle.c
+++ b/stand/libsa/twiddle.c
@@ -49,16 +49,23 @@ twiddle(u_int callerdiv)
 {
 	static u_int callercnt, globalcnt, pos;
 
+	TSENTER();
+
 	callercnt++;
-	if (callerdiv > 1 && (callercnt % callerdiv) != 0)
+	if (callerdiv > 1 && (callercnt % callerdiv) != 0) {
+		TSEXIT();
 		return;
+	}
 
 	globalcnt++;
-	if (globaldiv > 1 && (globalcnt % globaldiv) != 0)
+	if (globaldiv > 1 && (globalcnt % globaldiv) != 0) {
+		TSEXIT();
 		return;
+	}
 
 	putchar("|/-\\"[pos++ & 3]);
 	putchar('\b');
+	TSEXIT();
 }
 
 void