1 /*-
2  * SPDX-License-Identifier: BSD-2-Clause
4  * Copyright (c) 2008-2022 NetApp, Inc.
18  * IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR ANY DIRECT, INDIRECT,
21  * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
56  * Boot-time & shutdown-time event.
62 	uint32_t cpuid;			/* CPU on which the event ran */
73 	uint32_t wrap;			/* Wrap-around, instead of dropping */
74 	uint32_t drops_early;		/* Trace entries dropped before init */
79 /* Boot-time tracing */
82 /* Run-time tracing */
85 /* Shutdown-time tracing */
94 /* Turn on dotrace() debug logging to console. */
122     "Capture a boot-time trace event");
126     "Capture a run-time trace event");
130     "Capture a shutdown-time trace event");
131 SYSCTL_PROC(_kern_boottrace, OID_AUTO, reset,
134     "Reset run-time tracing table");
142     "Boot-time and shutdown-time tracing enabled");
163     "Boot-time tracing table size");
168  * Non-zero delta_threshold selectively prints entries based on delta
175  *  11 1228262715          0 init                     shutdown pre sync begin
176  *   3 1228265622       2907 init                     shutdown pre sync complete
177  *   3 1228265623          0 init                     shutdown turned swap off
178  *  18 1228266466        843 init                     shutdown unmounted all filesystems
186  * For example, above: Pre-Sync is taking 2907ms, and something between swap and unmount
195 		sbuf_printf(sbp, fmt, (bte)->cpuid, msecs, delta,	\
196 		    (bte)->tdname, (bte)->name, (bte)->pid,		\
197 		    (bte)->cputime / 1000000,				\
198 		    ((bte)->cputime % 1000000) / 10000,			\
199 		    (bte)->inblock, (bte)->oublock);			\
201 		printf(fmt, (bte)->cpuid, msecs, delta,			\
202 		    (bte)->tdname, (bte)->name, (bte)->pid,		\
203 		    (bte)->cputime / 1000000,				\
204 		    ((bte)->cputime % 1000000) / 10000,			\
205 		    (bte)->inblock, (bte)->oublock);			\
227 	const char *fmt     = "%3u %10llu %10llu %-24s %-40s %5d %4d.%02d %5u %5u\n";  in boottrace_display()
228 	const char *hdr_fmt = "\n\n%3s %10s %10s %-24s %-40s %5s %6s %5s %5s\n";  in boottrace_display()
247 	i = curr = btp->curr;  in boottrace_display()
250 		evtp = &btp->table[i];  in boottrace_display()
251 		if (evtp->tsc == 0)  in boottrace_display()
254 		msecs = cputick2usec(evtp->tick) / 1000;  in boottrace_display()
256 		    msecs - last_msecs : 0;  in boottrace_display()
285 		i = (i + 1) % btp->size;  in boottrace_display()
289 	    (last_msecs - first_msecs) : 0;  in boottrace_display()
329 		tdname = (curproc->p_flag & P_SYSTEM) ?  in dotrace()
330 		    curthread->td_name : curproc->p_comm;  in dotrace()
334 	    PCPU_GET(cpuid), curthread->td_proc->p_pid,  in dotrace()
336 	if (btp->table == NULL) {  in dotrace()
337 		btp->drops_early++;  in dotrace()
344 		idx = btp->curr;  in dotrace()
345 		nxt = (idx + 1) % btp->size;  in dotrace()
346 		if (nxt == 0 && btp->wrap == 0) {  in dotrace()
347 			btp->drops_full++;  in dotrace()
351 	} while (!atomic_cmpset_int(&btp->curr, idx, nxt));  in dotrace()
353 	btp->table[idx].cpuid = PCPU_GET(cpuid);  in dotrace()
354 	btp->table[idx].tsc = get_cyclecount(),  in dotrace()
355 	btp->table[idx].tick = cpu_ticks();  in dotrace()
356 	btp->table[idx].pid = curthread->td_proc->p_pid;  in dotrace()
362 	if ((curthread->td_proc == &proc0) || (curthread->td_critnest != 0)) {  in dotrace()
363 		btp->table[idx].cputime = 0;  in dotrace()
364 		btp->table[idx].inblock = 0;  in dotrace()
365 		btp->table[idx].oublock = 0;  in dotrace()
368 		btp->table[idx].cputime =  in dotrace()
372 		btp->table[idx].inblock = (uint32_t)usage.ru_inblock;  in dotrace()
373 		btp->table[idx].oublock = (uint32_t)usage.ru_oublock;  in dotrace()
375 	strlcpy(btp->table[idx].name, eventname, BT_EVENT_NAMELEN);  in dotrace()
376 	strlcpy(btp->table[idx].tdname, tdname, BT_EVENT_TDNAMELEN);  in dotrace()
383  * Log various boot-time events, with the trace message encoded using
384  * printf-like arguments.
410  * Log a run-time event & switch over to run-time tracing mode.
426  * e.g. reboot(8):SIGINT to init(8)
439 		*tdname = curproc->p_comm;  in boottrace_parse_message()
475 	if (!boottrace_enabled || req->newptr != NULL)  in sysctl_log()
495 	/* No output */  in sysctl_boottrace()
496 	if (req->newptr == NULL)  in sysctl_boottrace()
499 	/* Trace to rt if we have reached multi-user. */  in sysctl_boottrace()
504  * Log a run-time event and switch over to run-time tracing mode.
513 	/* No output */  in sysctl_runtrace()
514 	if (req->newptr == NULL)  in sysctl_runtrace()
522  * Log a shutdown-time event and switch over to shutdown tracing mode.
531 	/* No output */  in sysctl_shuttrace()
532 	if (req->newptr == NULL)  in sysctl_shuttrace()
540  * Reset the runtime tracing buffer.
547 	snprintf(tmpbuf, sizeof(tmpbuf), "reset: %s", actor);  in boottrace_reset()
552  * Note that a resize implies a reset, i.e., the index is reset to 0.
576 	if (req->newptr != NULL)  in sysctl_boottrace_reset()
602 	/* Run-time trace table (may wrap-around). */  in boottrace_init()