Page MenuHomeFreeBSD
Differential D30184 Diff 102170 sys/kern/kern_boottrace.c

Changeset View

Standalone View

View Options

sys/kern/kern_boottrace.c

  • This file was added.
/*-
* SPDX-License-Identifier: BSD-2-Clause-FreeBSD
*
* Copyright (c) 2008-2021 NetApp, Inc.
*
* 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 ``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 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/param.h>
#include <sys/systm.h>
#include <sys/boottrace.h>
#include <sys/kernel.h>
#include <sys/malloc.h>
#include <sys/pcpu.h>
#include <sys/proc.h>
#include <sys/resourcevar.h>
#include <sys/sbuf.h>
#include <sys/syscallsubr.h>
#include <sys/sysctl.h>
#include <sys/time.h>
#include <machine/stdarg.h>
#define dprintf(fmt, ...) \
do { \
if (dotrace_debugging) \
printf(fmt, ##__VA_ARGS__); \
} while (0);
static MALLOC_DEFINE(M_BOOTTRACE, "boottrace", "memory for boot tracing");
#define BT_TABLE_DEFSIZE 3000
#define BT_TABLE_RUNSIZE 2000
#define BT_TABLE_SHTSIZE 1000
#define BT_TABLE_MINSIZE 500
/*
* Boot-time & shutdown-time event.
*/
struct bt_event {
uint64_t tsc; /* Timestamp */
uint64_t tick; /* Kernel tick */
uint64_t cputime; /* Microseconds of process CPU time */
0mpUnsubmitted
Not Done
Inline Actions
uint64_t tsc; /* Timestamp */
- uint64_t tick; /* kernel tick */
+ uint64_t tick; /* Kernel tick */
uint64_t cputime; /* Microseconds of process CPU time */
0mp:
uint32_t cpuid; /* CPU on which the event ran */
uint32_t inblock; /* # of blocks in */
0mpUnsubmitted
Not Done
Inline Actions
uint64_t cputime; /* Microseconds of process CPU time */
- uint32_t cpuid; /* cpu on which the event ran */
+ uint32_t cpuid; /* CPU on which the event ran */
uint32_t inblock; /* # of blocks in */
0mp:
uint32_t oublock; /* # of blocks out */
pid_t pid; /* Current PID */
char name[BT_EVENT_NAMELEN]; /* Event name */
char tdname[BT_EVENT_TDNAMELEN]; /* Thread name */
0mpUnsubmitted
Not Done
Inline Actions
pid_t pid; /* Current PID */
- char name[BT_EVENT_NAMELEN]; /* event name */
+ char name[BT_EVENT_NAMELEN]; /* Event name */
char tdname[BT_EVENT_TDNAMELEN]; /* thread name */
0mp:
};
0mpUnsubmitted
Not Done
Inline Actions
char name[BT_EVENT_NAMELEN]; /* event name */
- char tdname[BT_EVENT_TDNAMELEN]; /* thread name */
+ char tdname[BT_EVENT_TDNAMELEN]; /* Thread name */
};
struct bt_table {
0mp:
struct bt_table {
uint32_t size; /* Trace table size */
uint32_t curr; /* Trace entry to use */
uint32_t wrap; /* Wrap-around, instead of dropping */
uint32_t drops_early; /* Trace entries dropped before init */
uint32_t drops_full; /* Trace entries dropped after full */
struct bt_event *table;
};
/* Boot-time tracing */
static struct bt_table bt;
/* Run-time tracing */
static struct bt_table rt;
/* Shutdown-time tracing */
static struct bt_table st;
/* Set when system boot is complete, and we've switched to runtime tracing. */
static bool bootdone;
0mpUnsubmitted
Not Done
Inline Actions
static struct bt_table st;
- /* Set when system boot is complete, and we've switch to runtime tracing. */
+ /* Set when system boot is complete, and we've switched to runtime tracing. */
static bool bootdone;
0mp:
/* Set when system shutdown has started. */
static bool shutdown;
/* Turn on dotrace() debug logging to console. */
static bool dotrace_debugging;
TUNABLE_BOOL("debug.boottrace.dotrace_debugging", &dotrace_debugging);
/* Trace kernel events */
static bool dotrace_kernel = true;
TUNABLE_BOOL("kern.boottrace.dotrace_kernel", &dotrace_kernel);
/* Trace userspace events */
static bool dotrace_user = true;
TUNABLE_BOOL("kern.boottrace.dotrace_user", &dotrace_user);
static int sysctl_log(SYSCTL_HANDLER_ARGS);
static int sysctl_boottrace(SYSCTL_HANDLER_ARGS);
static int sysctl_runtrace(SYSCTL_HANDLER_ARGS);
static int sysctl_shuttrace(SYSCTL_HANDLER_ARGS);
static int sysctl_boottrace_reset(SYSCTL_HANDLER_ARGS);
SYSCTL_NODE(_kern, OID_AUTO, boottrace, CTLFLAG_RD | CTLFLAG_MPSAFE, 0,
"boottrace statistics");
SYSCTL_PROC(_kern_boottrace, OID_AUTO, log,
CTLTYPE_STRING | CTLFLAG_RD | CTLFLAG_MPSAFE | CTLFLAG_SKIP,
0, 0, sysctl_log, "A",
"Print a log of the boottrace trace data");
SYSCTL_PROC(_kern_boottrace, OID_AUTO, boottrace,
CTLTYPE_STRING | CTLFLAG_WR | CTLFLAG_MPSAFE,
0mpUnsubmitted
Done
Inline Actions

Shouldn't boottimes be boottrace instead according to the sysctl description in the commit message?

0mp: Shouldn't `boottimes` be `boottrace` instead according to the sysctl description in the commit…
0, 0, sysctl_boottrace, "A",
"Capture a boot-time trace event");
SYSCTL_PROC(_kern_boottrace, OID_AUTO, runtrace,
CTLTYPE_STRING | CTLFLAG_WR | CTLFLAG_MPSAFE,
0, 0, sysctl_runtrace, "A",
"Capture a run-time trace event");
SYSCTL_PROC(_kern_boottrace, OID_AUTO, shuttrace,
CTLTYPE_STRING | CTLFLAG_WR | CTLFLAG_MPSAFE,
0, 0, sysctl_shuttrace, "A",
"Capture a shutdown-time trace event");
SYSCTL_PROC(_kern_boottrace, OID_AUTO, reset,
CTLTYPE_INT | CTLFLAG_WR | CTLFLAG_MPSAFE,
0, 0, sysctl_boottrace_reset, "A",
"Reset run-time tracing table");
/*
* Global enable.
*/
bool boottrace_enabled;
SYSCTL_BOOL(_kern_boottrace, OID_AUTO, enabled, CTLFLAG_RDTUN,
&boottrace_enabled, 0,
"Boot-time and shutdown-time tracing enabled");
/*
* Enable dumping of the shutdown trace entries to console.
*/
bool shutdown_trace;
SYSCTL_BOOL(_kern_boottrace, OID_AUTO, shutdown_trace, CTLFLAG_RWTUN,
&shutdown_trace, 0,
"Enable kernel shutdown tracing to the console.");
/*
* Set the delta threshold (ms) below which events are ignored, used in
* determining what to dump to the console.
*/
static int shutdown_trace_threshold;
SYSCTL_INT(_kern_boottrace, OID_AUTO, shutdown_trace_threshold, CTLFLAG_RWTUN,
&shutdown_trace_threshold, 0,
"Tracing threshold (ms) below which tracing is ignored.");
/*
* Dump a trace to buffer or if buffer is NULL to console.
*
* Non-zero delta_threshold selectively prints entries based on delta
* with current and previous entry. Otherwise, delta_threshold of 0
* prints every trace entry and delta.
*
* Output something like this:
*
* CPU msecs delta process event
* 11 1228262715 0 init shutdown pre sync begin
* 3 1228265622 2907 init shutdown pre sync complete
* 3 1228265623 0 init shutdown turned swap off
* 18 1228266466 843 init shutdown unmounted all filesystems
*
* How to interpret:
*
* delta column represents the time in milliseconds between this event and the previous.
* Usually that means you can take the previous event, current event, match them
* up in the code, and whatever lies between is the culprit taking time.
*
* For example, above: Pre-Sync is taking 2907ms, and something between swap and unmount
* filesystems is taking 843 milliseconds.
*
* An event with a delta of 0 are 'landmark' events that simply exist in the output
* for the developer to know where the time measurement begins. The 0 is an arbitrary
* number that can effectively be ignored.
*/
#define BTC_DELTA_PRINT(bte, msecs, delta) do { \
if (sbp) { \
sbuf_printf(sbp, fmt, (bte)->cpuid, msecs, delta, \
(bte)->tdname, (bte)->name, (bte)->pid, \
(bte)->cputime / 1000000, \
((bte)->cputime % 1000000) / 10000, \
(bte)->inblock, (bte)->oublock); \
} else { \
printf(fmt, (bte)->cpuid, msecs, delta, \
(bte)->tdname, (bte)->name, (bte)->pid, \
(bte)->cputime / 1000000, \
((bte)->cputime % 1000000) / 10000, \
(bte)->inblock, (bte)->oublock); \
} \
} while (0)
/*
* Print the trace entries to the message buffer, or to an sbuf, if provided.
*
* Entries with a difference less than dthres will not be printed.
*/
static void
boottrace_display(struct sbuf *sbp, struct bt_table *btp, uint64_t dthres)
{
struct bt_event *evtp;
struct bt_event *last_evtp;
uint64_t msecs;
uint64_t first_msecs;
uint64_t last_msecs;
uint64_t dmsecs;
uint64_t last_dmsecs;
uint64_t total_dmsecs;
uint32_t i;
uint32_t curr;
const char *fmt = "%3u %10llu %10llu %-24s %-40s %5d %4d.%02d %5u %5u\n";
const char *hdr_fmt = "\n\n%3s %10s %10s %-24s %-40s %5s %6s %5s %5s\n";
bool printed;
bool last_printed;
/* Print the header */
if (sbp != NULL)
sbuf_printf(sbp, hdr_fmt,
"CPU", "msecs", "delta", "process",
"event", "PID", "CPUtime", "IBlks", "OBlks");
else
printf(hdr_fmt,
"CPU", "msecs", "delta", "process",
"event", "PID", "CPUtime", "IBlks", "OBlks");
first_msecs = 0;
last_evtp = NULL;
last_msecs = 0;
last_dmsecs = 0;
last_printed = false;
i = curr = btp->curr;
do {
evtp = &btp->table[i];
if (evtp->tsc == 0)
goto next;
msecs = cputick2usec(evtp->tick) / 1000;
dmsecs = (last_msecs != 0 && msecs > last_msecs) ?
msecs - last_msecs : 0;
printed = false;
/*
* If a threshold is defined, start filtering events by the
* delta of msecs.
*/
if (dthres != 0 && (dmsecs > dthres)) {
/*
* Print the previous entry as a landmark, even if it
* falls below the threshold.
*/
if (last_evtp != NULL && !last_printed)
BTC_DELTA_PRINT(last_evtp, last_msecs,
last_dmsecs);
BTC_DELTA_PRINT(evtp, msecs, dmsecs);
printed = true;
} else if (dthres == 0) {
BTC_DELTA_PRINT(evtp, msecs, dmsecs);
printed = true;
}
if (first_msecs == 0 || msecs < first_msecs)
first_msecs = msecs;
last_evtp = evtp;
last_msecs = msecs;
last_dmsecs = dmsecs;
last_printed = printed;
maybe_yield();
next:
i = (i + 1) % btp->size;
} while (i != curr);
total_dmsecs = last_msecs > first_msecs ?
(last_msecs - first_msecs) : 0;
if (sbp)
sbuf_printf(sbp, "Total measured time: %ju msecs\n",
(uintmax_t)total_dmsecs);
else
printf("Total measured time: %ju msecs\n",
(uintmax_t)total_dmsecs);
}
/*
* Dump trace table entries to the console, given a delta threshold.
*/
void
boottrace_dump_console(void)
{
if (!boottrace_enabled)
return;
if (shutdown || rebooting || KERNEL_PANICKED()) {
boottrace_display(NULL, &st, shutdown_trace_threshold);
} else {
boottrace_display(NULL, &bt, 0);
boottrace_display(NULL, &rt, 0);
}
}
/*
* Records a new tracing event to the specified table.
*
* We don't use a lock because we want this to be callable from interrupt
* context.
*/
static int
dotrace(struct bt_table *btp, const char *eventname, const char *tdname)
{
uint32_t idx, nxt;
struct rusage usage;
MPASS(boottrace_enabled);
kevansUnsubmitted
Done
Inline Actions

You might assert boottrace_enabled here, we're a couple callers deep at points

kevans: You might assert `boottrace_enabled` here, we're a couple callers deep at points
if (tdname == NULL)
tdname = (curproc->p_flag & P_SYSTEM) ?
curthread->td_name : curproc->p_comm;
dprintf("dotrace[");
dprintf("cpu=%u, pid=%d, tsc=%ju, tick=%d, td='%s', event='%s'",
PCPU_GET(cpuid), curthread->td_proc->p_pid,
(uintmax_t)get_cyclecount(), ticks, tdname, eventname);
if (btp->table == NULL) {
btp->drops_early++;
dprintf(", return=ENOSPC_1]\n");
return (ENOSPC);
}
/* Claim a slot in the table. */
do {
idx = btp->curr;
nxt = (idx + 1) % btp->size;
if (nxt == 0 && btp->wrap == 0) {
btp->drops_full++;
dprintf(", return=ENOSPC_2]\n");
return (ENOSPC);
}
} while (!atomic_cmpset_int(&btp->curr, idx, nxt));
btp->table[idx].cpuid = PCPU_GET(cpuid);
btp->table[idx].tsc = get_cyclecount(),
btp->table[idx].tick = cpu_ticks();
btp->table[idx].pid = curthread->td_proc->p_pid;
/*
* Get the resource usage for the process. Don't attempt this for the
* kernel proc0 or for critical section activities.
*/
if ((curthread->td_proc == &proc0) || (curthread->td_critnest != 0)) {
btp->table[idx].cputime = 0;
btp->table[idx].inblock = 0;
btp->table[idx].oublock = 0;
} else {
kern_getrusage(curthread, RUSAGE_CHILDREN, &usage);
btp->table[idx].cputime =
(uint64_t)(usage.ru_utime.tv_sec * 1000000 +
usage.ru_utime.tv_usec + usage.ru_stime.tv_sec * 1000000 +
usage.ru_stime.tv_usec);
btp->table[idx].inblock = (uint32_t)usage.ru_inblock;
btp->table[idx].oublock = (uint32_t)usage.ru_oublock;
}
strlcpy(btp->table[idx].name, eventname, BT_EVENT_NAMELEN);
strlcpy(btp->table[idx].tdname, tdname, BT_EVENT_TDNAMELEN);
dprintf(", return=0]\n");
return (0);
}
/*
* Log various boot-time events, with the trace message encoded using
* printf-like arguments.
*/
int
boottrace(const char *tdname, const char *fmt, ...)
{
char eventname[BT_EVENT_NAMELEN];
struct bt_table *btp;
va_list ap;
if (!dotrace_kernel)
return (ENXIO);
va_start(ap, fmt);
vsnprintf(eventname, sizeof(eventname), fmt, ap);
va_end(ap);
btp = &bt;
if (bootdone)
btp = &rt;
if (shutdown || rebooting || KERNEL_PANICKED())
btp = &st;
return (dotrace(btp, eventname, tdname));
}
/*
* Log a run-time event & switch over to run-time tracing mode.
*/
static int
runtrace(const char *eventname, const char *tdname)
{
bootdone = true;
return (dotrace(&rt, eventname, tdname));
}
/*
* Parse a boottrace message from userspace.
*
* The input from may contain a ':' to denote tdname. If not, tdname is
* inferred from the process' name.
*
* e.g. reboot(8):SIGINT to init(8)
kevansUnsubmitted
Not Done
Inline Actions

I don't see where this is used in this or follow-up patches?

kevans: I don't see where this is used in this or follow-up patches?
mhorneAuthorUnsubmitted
Done
Inline Actions

Indeed, it was but is no longer used anywhere.

mhorne: Indeed, it was but is no longer used anywhere.
*/
static void
boottrace_parse_message(char *message, char **eventname, char **tdname)
{
char *delim;
delim = strchr(message, ':');
if (delim != NULL) {
*delim = '\0';
*tdname = message;
*eventname = ++delim;
} else {
*tdname = curproc->p_comm;
*eventname = message;
}
}
static int
_boottrace_sysctl(struct bt_table *btp, struct sysctl_oid *oidp,
struct sysctl_req *req)
{
char message[BT_MSGLEN];
char *eventname, *tdname;
int error;
if (!dotrace_user)
return (ENXIO);
message[0] = '\0';
error = sysctl_handle_string(oidp, message, sizeof(message), req);
if (error)
return (error);
boottrace_parse_message(message, &eventname, &tdname);
error = dotrace(btp, eventname, tdname);
if (error == ENOSPC) {
/* Ignore table full error. */
error = 0;
}
return (error);
}
static int
sysctl_log(SYSCTL_HANDLER_ARGS)
{
struct sbuf *sbuf;
int error;
if (!boottrace_enabled || req->newptr != NULL)
return (0);
sbuf = sbuf_new(NULL, NULL, 0, SBUF_AUTOEXTEND);
boottrace_display(sbuf, &bt, 0);
boottrace_display(sbuf, &rt, 0);
sbuf_finish(sbuf);
error = SYSCTL_OUT(req, sbuf_data(sbuf), sbuf_len(sbuf));
sbuf_delete(sbuf);
return (error);
}
static int
sysctl_boottrace(SYSCTL_HANDLER_ARGS)
{
if (!boottrace_enabled)
return (0);
/* No output */
if (req->newptr == NULL)
return (0);
/* Trace to rt if we have reached multi-user. */
return (_boottrace_sysctl(bootdone ? &rt : &bt, oidp, req));
}
/*
* Log a run-time event and switch over to run-time tracing mode.
*/
static int
sysctl_runtrace(SYSCTL_HANDLER_ARGS)
{
if (!boottrace_enabled)
return (0);
/* No output */
if (req->newptr == NULL)
return (0);
bootdone = true;
return (_boottrace_sysctl(&rt, oidp, req));
}
/*
* Log a shutdown-time event and switch over to shutdown tracing mode.
*/
static int
sysctl_shuttrace(SYSCTL_HANDLER_ARGS)
{
if (!boottrace_enabled)
return (0);
/* No output */
if (req->newptr == NULL)
return (0);
shutdown = true;
return (_boottrace_sysctl(&st, oidp, req));
}
/*
* Reset the runtime tracing buffer.
*/
void
boottrace_reset(const char *actor)
{
char tmpbuf[64];
snprintf(tmpbuf, sizeof(tmpbuf), "reset: %s", actor);
runtrace(tmpbuf, NULL);
}
/*
* Note that a resize implies a reset, i.e., the index is reset to 0.
* We never shrink the array; we can only increase its size.
*/
int
boottrace_resize(u_int newsize)
{
if (newsize <= rt.size) {
return (EINVAL);
}
rt.table = realloc(rt.table, newsize * sizeof(struct bt_event),
M_BOOTTRACE, M_WAITOK | M_ZERO);
if (rt.table == NULL)
return (ENOMEM);
rt.size = newsize;
boottrace_reset("boottrace_resize");
return (0);
}
static int
sysctl_boottrace_reset(SYSCTL_HANDLER_ARGS)
{
if (!boottrace_enabled)
return (0);
if (req->newptr != NULL)
boottrace_reset("sysctl_boottrace_reset");
return (0);
}
static void
boottrace_init(void)
{
if (!boottrace_enabled)
return;
/* Boottime trace table */
bt.size = BT_TABLE_DEFSIZE;
TUNABLE_INT_FETCH("kern.boottrace.table_size", &bt.size);
bt.size = max(bt.size, BT_TABLE_MINSIZE);
bt.table = malloc(bt.size * sizeof(struct bt_event), M_BOOTTRACE,
M_WAITOK | M_ZERO);
/* Stick in an initial entry. */
bt.table[0].cpuid = PCPU_GET(cpuid);
strlcpy(bt.table[0].tdname, "boottime", BT_EVENT_TDNAMELEN);
strlcpy(bt.table[0].name, "initial event", BT_EVENT_NAMELEN);
bt.curr = 1;
/* Run-time trace table (may wrap-around). */
rt.wrap = 1;
rt.size = BT_TABLE_RUNSIZE;
rt.table = malloc(rt.size * sizeof(struct bt_event), M_BOOTTRACE,
M_WAITOK | M_ZERO);
/* Shutdown trace table */
st.size = BT_TABLE_SHTSIZE;
st.table = malloc(st.size * sizeof(struct bt_event), M_BOOTTRACE,
M_WAITOK | M_ZERO);
}
SYSINIT(boottrace, SI_SUB_CPU, SI_ORDER_ANY, boottrace_init, 0);