Commit 89a9852f authored by Colin Percival's avatar Colin Percival
Browse files

MFC loader+userland TSLOG support

stand/common: Add file_addbuf()
libsa: Add support for timestamp logging (tslog)
stand/common: Add support for timestamp logging (tslog)
i386/loader: Call tslog_init
efi/loader: Call tslog_init (+ bugfix)
stand/common command_boot: Pass tslog to kernel
kern_tslog: Include tslog data from loader
loader: Use tslog to instrument some functions
Add userland boot profiling to TSLOG (+ bugfix)

Sponsored by:	https://www.patreon.com/cperciva

(cherry picked from commit 60a978be)
(cherry picked from commit e193d3ba)
(cherry picked from commit c8dfc327)
(cherry picked from commit c4b65e95)
(cherry picked from commit f49381cc)
(cherry picked from commit 537a44bf)
(cherry picked from commit fe51b5a7)
(cherry picked from commit 313724ba)
(cherry picked from commit 46dd801a)
(cherry picked from commit 52e125c2)
(cherry picked from commit 19e4f2f2)
parent bd7e18a3
......@@ -113,6 +113,9 @@ command_boot(int argc, char *argv[])
#endif
#endif
/* Pass the tslog buffer to the kernel as a preloaded module. */
tslog_publish();
/* Call the exec handler from the loader matching the kernel */
file_formats[fp->f_loader]->l_exec(fp);
return(CMD_ERROR);
......
......@@ -263,6 +263,9 @@ void file_addmetadata(struct preloaded_file *, int, size_t, void *);
int file_addmodule(struct preloaded_file *, char *, int,
struct kernel_module **);
void file_removemetadata(struct preloaded_file *fp);
int file_addbuf(const char *name, const char *type, size_t len, void *buf);
int tslog_init(void);
int tslog_publish(void);
vm_offset_t build_font_module(vm_offset_t);
......
......@@ -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
......
......@@ -2432,6 +2432,8 @@ read_list(char *fonts)
char buf[PATH_MAX];
int fd, len;
TSENTER();
dir = strdup(fonts);
if (dir == NULL)
return (NULL);
......@@ -2479,6 +2481,7 @@ read_list(char *fonts)
SLIST_INSERT_HEAD(nl, np, n_entry);
}
close(fd);
TSEXIT();
return (nl);
}
......@@ -2496,6 +2499,8 @@ insert_font(char *name, FONT_FLAGS flags)
int fd;
char *font_name;
TSENTER();
font_name = NULL;
if (flags == FONT_BUILTIN) {
/*
......@@ -2542,6 +2547,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);
}
}
......@@ -2565,6 +2571,7 @@ insert_font(char *name, FONT_FLAGS flags)
if (STAILQ_EMPTY(&fonts)) {
STAILQ_INSERT_HEAD(&fonts, fp, font_next);
TSEXIT();
return (true);
}
......@@ -2583,6 +2590,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);
......@@ -2590,10 +2598,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);
}
......@@ -2652,6 +2662,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;
......@@ -2673,6 +2685,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);
......
......@@ -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
......
......@@ -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);
}
......
......@@ -1042,6 +1042,57 @@ file_removemetadata(struct preloaded_file *fp)
fp->f_metadata = NULL;
}
/*
* Add a buffer to the list of preloaded "files".
*/
int
file_addbuf(const char *name, const char *type, size_t len, void *buf)
{
struct preloaded_file *fp;
vm_offset_t dest;
/* We can't load first */
if ((file_findfile(NULL, NULL)) == NULL) {
command_errmsg = "can't load file before kernel";
return (-1);
}
/* Figure out where to load the data. */
dest = loadaddr;
if (archsw.arch_loadaddr != NULL)
dest = archsw.arch_loadaddr(LOAD_RAW, (void *)name, dest);
/* Create & populate control structure */
fp = file_alloc();
if (fp == NULL) {
snprintf(command_errbuf, sizeof (command_errbuf),
"no memory to load %s", name);
return (-1);
}
fp->f_name = strdup(name);
fp->f_type = strdup(type);
fp->f_args = NULL;
fp->f_metadata = NULL;
fp->f_loader = -1;
fp->f_addr = dest;
fp->f_size = len;
if ((fp->f_name == NULL) || (fp->f_type == NULL)) {
snprintf(command_errbuf, sizeof (command_errbuf),
"no memory to load %s", name);
free(fp->f_name);
free(fp->f_type);
return (-1);
}
/* Copy the data in. */
archsw.arch_copyin(buf, fp->f_addr, len);
loadaddr = fp->f_addr + len;
/* Add to the list of loaded files */
file_insert_tail(fp);
return(0);
}
struct file_metadata *
metadata_next(struct file_metadata *md, int type)
{
......
/*-
* Copyright (c) 2021 Colin Percival
* All rights reserved.
*
* Redistribution and use in source and binary forms, with or without
* modification, are permitted provided that the following conditions
* are met:
* 1. Redistributions of source code must retain the above copyright
* notice, this list of conditions and the following disclaimer.
* 2. Redistributions in binary form must reproduce the above copyright
* notice, this list of conditions and the following disclaimer in the
* documentation and/or other materials provided with the distribution.
*
* THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
* ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
* IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
* ARE DISCLAIMED. IN NO EVENT SHALL THE AUTHOR OR CONTRIBUTORS BE LIABLE
* FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
* DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
* OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
* HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
* LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
* OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
* SUCH DAMAGE.
*/
#include <sys/cdefs.h>
__FBSDID("$FreeBSD$");
#include <sys/types.h>
#include <stand.h>
#include "bootstrap.h"
/* Buffer for holding tslog data in string format. */
#ifndef LOADER_TSLOGSIZE
#define LOADER_TSLOGSIZE (2 * 1024 * 1024)
#endif
int
tslog_init(void)
{
void * tslog_buf;
/* Allocate buffer and pass to libsa tslog code. */
if ((tslog_buf = malloc(LOADER_TSLOGSIZE)) == NULL)
return (-1);
tslog_setbuf(tslog_buf, LOADER_TSLOGSIZE);
/* Record this as when we entered the loader. */
TSRAW("ENTER", "loader", NULL);
return (0);
}
/*
* Pass our tslog buffer as a preloaded "module" to the kernel. This should
* be called as late as possible prior to the kernel being executed, since
* any timestamps logged after this is called will not be visible to the
* kernel.
*/
int
tslog_publish(void)
{
void * tslog_buf;
size_t tslog_bufpos;
/* Record a log entry for ending logging. */
TSRAW("EXIT", "loader", NULL);
/* Get the buffer and its current length. */
tslog_getbuf(&tslog_buf, &tslog_bufpos);
/* If we never allocated a buffer, return an error. */
if (tslog_buf == NULL)
return (-1);
/* Store the buffer where the kernel can read it. */
return (file_addbuf("TSLOG", "TSLOG data", tslog_bufpos, tslog_buf));
}
......@@ -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));
}
......
......@@ -27,6 +27,7 @@
#include <sys/cdefs.h>
__FBSDID("$FreeBSD$");
#include <bootstrap.h>
#include <efi.h>
#include <eficonsctl.h>
#include <efilib.h>
......@@ -101,6 +102,9 @@ efi_main(EFI_HANDLE image_handle, EFI_SYSTEM_TABLE *system_table)
setheap((void *)(uintptr_t)heap, (void *)(uintptr_t)(heap + heapsize));
/* Start tslog now that we have a heap.*/
tslog_init();
/* Use efi_exit() from here on... */
status = OpenProtocolByHandle(IH, &image_protocol, (void**)&img);
......
......@@ -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);
}
......
......@@ -130,6 +130,12 @@ main(void)
}
setheap(heap_bottom, heap_top);
/*
* Now that malloc is usable, allocate a buffer for tslog and start
* logging timestamps during the boot process.
*/
tslog_init();
/*
* detect ACPI for future reference. This may set console to comconsole
* if we do have ACPI SPCR table.
......
......@@ -16,7 +16,7 @@ LIB?= sa
SRCS+= gzguts.h zutil.h __main.c abort.c assert.c bcd.c environment.c \
getopt.c gets.c globals.c \
hexdump.c pager.c panic.c printf.c strdup.c strerror.c \
random.c sbrk.c twiddle.c zalloc.c zalloc_malloc.c
random.c sbrk.c tslog.c twiddle.c zalloc.c zalloc_malloc.c
# private (pruned) versions of libc string functions
SRCS+= strcasecmp.c
......
......@@ -145,6 +145,8 @@ open(const char *fname, int mode)
int fd, i, error, besterror;
const char *file;
TSENTER();
if ((fd = o_gethandle(&f)) == -1) {
errno = EMFILE;
return (-1);
......@@ -174,6 +176,7 @@ open(const char *fname, int mode)
if (file == NULL || *file == '\0') {
f->f_flags |= F_RAW;
f->f_rabuf = NULL;
TSEXIT();
return (fd);
}
......@@ -197,10 +200,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);
}
......@@ -72,6 +72,7 @@ read(int fd, void *dest, size_t bcount)
struct open_file *f;
size_t resid;
TSENTER();
f = fd2open_file(fd);
if (f == NULL || !(f->f_flags & F_READ)) {
errno = EBADF;
......@@ -84,6 +85,7 @@ read(int fd, void *dest, size_t bcount)
if (errno)
return (-1);
f->f_offset += resid;
TSEXIT();
return (resid);
}
......@@ -103,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;
}
......@@ -117,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);
}
......@@ -128,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);
}
}
}
......@@ -477,4 +477,13 @@ caddr_t ptov(uintptr_t);
/* hexdump.c */
void hexdump(caddr_t region, size_t len);
/* tslog.c */
#define TSRAW(a, b, c) tslog(a, b, c)
#define TSENTER() TSRAW("ENTER", __func__, NULL)
#define TSEXIT() TSRAW("EXIT", __func__, NULL)
#define TSLINE() TSRAW("EVENT", __FILE__, __XSTRING(__LINE__))
void tslog(const char *, const char *, const char *);
void tslog_setbuf(void * buf, size_t len);
void tslog_getbuf(void ** buf, size_t * len);
#endif /* STAND_H */
/*-
* Copyright (c) 2021 Colin Percival
* All rights reserved.
*
* Redistribution and use in source and binary forms, with or without
* modification, are permitted provided that the following conditions
* are met:
* 1. Redistributions of source code must retain the above copyright
* notice, this list of conditions and the following disclaimer.
* 2. Redistributions in binary form must reproduce the above copyright
* notice, this list of conditions and the following disclaimer in the
* documentation and/or other materials provided with the distribution.
*
* THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
* ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
* IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
* ARE DISCLAIMED. IN NO EVENT SHALL THE AUTHOR OR CONTRIBUTORS BE LIABLE
* FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
* DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
* OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
* HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
* LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
* OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
* SUCH DAMAGE.
*/
#include <sys/cdefs.h>
__FBSDID("$FreeBSD$");
#include <sys/types.h>
#include <machine/cpufunc.h>
#include <stand.h>
/* Buffer for holding tslog data in string format. */
static char * tslog_buf = NULL;
static size_t tslog_buflen = 0;
static size_t tslog_bufpos = 0;
void
tslog_setbuf(void * buf, size_t len)
{
tslog_buf = (char *)buf;
tslog_buflen = len;
tslog_bufpos = 0;
}
void
tslog_getbuf(void ** buf, size_t * len)
{
*buf = (void *)tslog_buf;
*len = tslog_bufpos;
}
void
tslog(const char * type, const char * f, const char * s)
{
#if defined(__amd64__) || defined(__i386__)
uint64_t tsc = rdtsc();
#else
uint64_t tsc = 0;
#endif
int len;
/* If we have no buffer, do nothing. */
if (tslog_buf == NULL)
return;
/* Append to existing buffer, if we have enough space. */
len = snprintf(&tslog_buf[tslog_bufpos],
tslog_buflen - tslog_bufpos, "0x0 %llu %s %s%s%s\n",
(unsigned long long)tsc, type, f, s ? " " : "", s ? s : "");
if ((len > 0) && (tslog_bufpos + len <= tslog_buflen))
tslog_bufpos += len;
}
......@@ -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)