diff options
| author | Devin Teske <dteske@FreeBSD.org> | 2026-07-28 23:32:57 +0000 |
|---|---|---|
| committer | Devin Teske <dteske@FreeBSD.org> | 2026-07-28 23:32:57 +0000 |
| commit | 434283fda99e89af20c3fe95fde427624ae96d04 (patch) | |
| tree | d9f71fd0c3339ee607bc60257ae2d2abeca95b80 | |
| parent | 14f5fd2395e3f1c3fadeee8b95756c142f7dcb0b (diff) | |
dwatch: add nine diagnostic modules; grow errno, io, proc, sched
Grow the module collection to answer, each with a single command, the
first questions asked when diagnosing a sick system: why is my
application stalling, where is the kernel fighting over locks, what
file could it not find, why is this process getting EPERM, what killed
my process, will that fatal signal actually leave a core behind, what
was my process stuck on, where is my kernel memory going, who is
creating or entering jails, is the network slow because TCP is
resending, how long did my thread wait to run, and is the disk itself
slow. Every module keeps to the house style: invocation-name
overloading through hard links, predicate-only D with inline lookup
tables (no if-statements), and stable providers only (syscall, proc,
sched, io, dtmalloc, and the lockstat, vfs, priv, and mib SDT
providers), so the modules remain drop-in compatible with older
releases (the one documented exception is noted below). No kernel
changes: new and extended profiles under cddl/usr.sbin/dwatch/libexec
plus one libdtrace inline table (priv.d).
slow (slow-fsync, slow-open, slow-read, slow-syscall, slow-write, or
any slow-NAME by new link) records syscall entry timestamps in
thread-local storage and prints, at return, any call whose latency
meets a threshold (DWATCH_SLOW_MS, default 100), naming the syscall,
the elapsed time to the microsecond, and any errno returned. The bare
profile watches a curated set of filesystem-related calls expected to
be fast; slow-syscall watches everything; unrecognized invocation
names fall through to syscall::NAME:return with the matching entry
probe derived mechanically from the return probe list.
lock (lock-adaptive, lock-block, lock-lockmgr, lock-rw, lock-spin,
lock-sx, lock-thread) rides the dtrace_lockstat(4) block and spin
probes, printing the held-off thread (free from the standard event
tag), the holdoff duration, the lock class, the lo_name of the lock
through a single cast of arg0 to struct lock_object (the first member
of every kernel lock), and reader/writer intent on the probes that
report it. Holdoffs shorter than DWATCH_LOCK_MS (default 1; 0 shows
everything) are suppressed.
namei (namei-enoent, namei-entry, namei-failure) records the pathname
at vfs:namei:lookup:entry and reports it with the result at return.
Unlike the vop_lookup profile, which reconstructs paths from the name
cache one component at a time, this sees the whole path exactly as the
process requested it. namei-enoent hunts file-not-found storms -- the
single most common use of truss(1) -- without stopping the victim.
priv (priv-err, priv-ok) watches priv_check(9) verdicts, naming the
exact privilege denied -- something no syscall tracer can see, because
by the time EPERM surfaces the priv(9) value is gone. The number is
decoded by priv_string[], a new libdtrace inline table in the errno.d
and signal.d tradition, mechanically generated from sys/priv.h (247
entries) and installed to /usr/lib/dtrace where dtrace(1) auto-loads
it; on older releases it is a drop-in file like the module itself.
coredump (coredump-top) watches for delivery of signals whose default
action produces a core, per the SIGPROP_CORE entries of the sigproptbl
in kern_sig.c, and renders a verdict the same way and in the same
order the kernel will decide it: ignored or caught per the target's
struct sigacts, then the coredump() gauntlet of kern.coredump,
kern.sugid_coredump vs P_SUGID, procctl(2) PROC_TRACE_CTL, and
RLIMIT_CORE -- the sysctl knobs read live through kernel globals.
Where a coredump-worthy signal will produce no core, the verdict says
precisely which policy ate it. coredump-top maintains a cumulative
catalog of coredump-worthy signals by process and signal, refreshed
every 3 seconds in the style of systop; combine the event profile with
`-O cmd' to capture state as each event occurs.
hang (hang-top) pairs sched:::sleep with sched:::wakeup through a
tid-keyed timestamp array and prints, as each thread wakes, any sleep
that meets a threshold (DWATCH_HANG_MS, default 1000), naming the
sleeper in the details and the waker in the standard event tag. This
is the blocking the slow module structurally cannot see: a syscall
that never returns never reports its latency, while hang reports the
moment the wait ends, with the full duration. hang-top maintains a
cumulative catalog of long sleeps by process (count and maximum) in
the style of coredump-top.
jail (jail-attach, jail-get, jail-remove, jail-set) watches the jail
management plane -- jail(2), jail_set(2), jail_get(2), jail_attach(2),
and jail_remove(2) -- naming the operation, the jail id (taken from
the entry argument for attach/remove, from the return value for the
others), and any errno. Complements the dwatch `-j jail' filter,
which scopes any profile to processes inside one jail; this watches
who manipulates jails, from any jail or none.
dtmalloc (dtmalloc-top, or any dtmalloc-NAME by new link) rides the
dtmalloc provider (one malloc and one free probe per malloc(9) type).
The event profile prints allocations and frees meeting a size
threshold (DWATCH_MALLOC_MIN, default 65536) -- who is allocating huge
kernel buffers. dtmalloc-top maintains a running catalog of net bytes
and outstanding allocation balance by type, sorted by net bytes so
leak suspects rise: a type that climbs without bound while the system
is in steady state is the suspect. The catalog reflects activity
since the watch began, and is honest about caches holding what they
allocate.
mib (tcp-retransmit, or any mib-NAME by new link) rides the
per-counter mib SDT probes of the network stack. The tcp-retransmit
profile curates the counters that signal send-path congestion or loss
-- data packet retransmissions, unnecessary retransmissions,
retransmit timer expirations, and connections dropped by retransmit
exhaustion -- decoded through an inline description table, answering
"is this network slow because TCP is resending?" as events with
process context rather than netstat(1) deltas. NB: the mib probes
exist only in kernels built with options KDTRACE_MIB_SDT (default in
-CURRENT via std.debug); the module documents this and dtrace(1)
refuses the script elsewhere, making the dependency self-announcing.
Four existing modules gain personalities. proc grows
proc-signal-fatal, filtering signal-send to signals whose default
disposition terminates the receiver, most-notably including
kernel-generated SIGSEGV/SIGBUS/SIGILL/SIGFPE that no kill(2) watcher
will ever see. errno now reads its invocation name: errno-NAME shows
only syscalls returning that errno, where NAME is a symbolic name from
errno.d or a number; links are installed for errno-EACCES,
errno-ECAPMODE, errno-ENOENT, errno-ENOTCAPABLE, and errno-EPERM (the
latter pairs covering capsicum(4) capability-mode violations), and any
other errno needs only a new link. sched grows sched-latency,
recording a timestamp at sched:::enqueue keyed by tid and printing at
sched:::on-cpu any run-queue wait meeting a threshold (DWATCH_SCHED_MS,
default 10) -- the literal measurement of scheduler delay on a system
with idle CPU that still feels sluggish. io grows io-slow, pairing
io:::start with io:::done through a bio-keyed timestamp array and
printing any request that meets a threshold (DWATCH_IO_MS, default
100), naming the device, command, size, and elapsed time; watched
against zvols and a pool's leaf vdevs this brackets where in a ZFS
stack the time is going, without touching unstable providers.
Document all of the above plus the DWATCH_HANG_MS, DWATCH_IO_MS,
DWATCH_LOCK_MS, DWATCH_MALLOC_MIN, DWATCH_SCHED_MS, and DWATCH_SLOW_MS
knobs in dwatch(1).
All 46 new invocation names were exercised through `dwatch -d' with a
profile-path sandbox emulating the installed hard links: every one
sources cleanly and emits the intended D -- probe selection per alias,
entry/return and sleep/wakeup pairing through thread-local and global
associative arrays, threshold and mask predicates picking up their
knobs, aggregation clauses and printa column layout in the -top
profiles, multi-line predicate rendering, and `-t' correctly
displacing each module's default test were verified by inspection of
the generated scripts. Invocations untouched by this pass generate D
identical to their previous output. Modules pass sh -n, fit 80
columns, and dwatch.1 passes mandoc -Tlint with no new warnings. A
validation harness performing a `dwatch -e' compile per profile
against the live kernel globs every staged profile for runs wherever
the dtrace device is present.
Reviewed by: markj
Differential Revision: https://reviews.freebsd.org/D58093
| -rw-r--r-- | cddl/lib/libdtrace/Makefile | 6 | ||||
| -rwxr-xr-x | cddl/lib/libdtrace/mkpriv | 119 | ||||
| -rw-r--r-- | cddl/usr.sbin/dwatch/dwatch.1 | 105 | ||||
| -rw-r--r-- | cddl/usr.sbin/dwatch/libexec/Makefile | 42 | ||||
| -rw-r--r-- | cddl/usr.sbin/dwatch/libexec/coredump | 210 | ||||
| -rw-r--r-- | cddl/usr.sbin/dwatch/libexec/dtmalloc | 146 | ||||
| -rw-r--r-- | cddl/usr.sbin/dwatch/libexec/errno | 15 | ||||
| -rw-r--r-- | cddl/usr.sbin/dwatch/libexec/hang | 174 | ||||
| -rw-r--r-- | cddl/usr.sbin/dwatch/libexec/io | 72 | ||||
| -rw-r--r-- | cddl/usr.sbin/dwatch/libexec/jail | 92 | ||||
| -rw-r--r-- | cddl/usr.sbin/dwatch/libexec/lock | 136 | ||||
| -rw-r--r-- | cddl/usr.sbin/dwatch/libexec/mib | 78 | ||||
| -rw-r--r-- | cddl/usr.sbin/dwatch/libexec/namei | 84 | ||||
| -rw-r--r-- | cddl/usr.sbin/dwatch/libexec/priv | 59 | ||||
| -rw-r--r-- | cddl/usr.sbin/dwatch/libexec/proc | 23 | ||||
| -rw-r--r-- | cddl/usr.sbin/dwatch/libexec/sched | 65 | ||||
| -rw-r--r-- | cddl/usr.sbin/dwatch/libexec/slow | 131 |
17 files changed, 1544 insertions, 13 deletions
diff --git a/cddl/lib/libdtrace/Makefile b/cddl/lib/libdtrace/Makefile index fbc6d5fbbec2..08836a91b164 100644 --- a/cddl/lib/libdtrace/Makefile +++ b/cddl/lib/libdtrace/Makefile @@ -55,6 +55,7 @@ DSRCS= cam.d \ errno.d \ io.d \ ip.d \ + priv.d \ psinfo.d \ sctp.d \ siftr.d \ @@ -150,7 +151,7 @@ LDFLAGS+= -fsanitize=address -fsanitize=undefined LIBADD= ctf elf proc pthread rtld_db xo -CLEANFILES= dt_errtags.c dt_names.c +CLEANFILES= dt_errtags.c dt_names.c priv.d .include <bsd.lib.mk> @@ -159,3 +160,6 @@ dt_errtags.c: ${OPENSOLARIS_USR_DISTDIR}/lib/libdtrace/common/dt_errtags.h dt_names.c: ${OPENSOLARIS_SYS_DISTDIR}/uts/common/sys/dtrace.h sh ${OPENSOLARIS_USR_DISTDIR}/lib/libdtrace/common/mknames.sh < ${.ALLSRC} > ${.TARGET} + +priv.d: mkpriv ${SRCTOP}/sys/sys/priv.h + sh ${.CURDIR}/mkpriv -o ${.TARGET} ${SRCTOP}/sys/sys/priv.h diff --git a/cddl/lib/libdtrace/mkpriv b/cddl/lib/libdtrace/mkpriv new file mode 100755 index 000000000000..d213161f8356 --- /dev/null +++ b/cddl/lib/libdtrace/mkpriv @@ -0,0 +1,119 @@ +#!/bin/sh +# -*- tab-width: 4 -*- ;; Emacs +# vi: set filetype=sh tabstop=8 shiftwidth=8 noexpandtab :: Vi/ViM +############################################################ LICENSE +# +# Copyright (c) 2026 Devin Teske <dteske@FreeBSD.org> +# +# SPDX-License-Identifier: BSD-2-Clause +# +############################################################ IDENT(1) +# +# $Title: Generate priv.d from <sys/priv.h> for libdtrace(3) $ +# $Copyright: 2026 Devin Teske. All rights reserved. $ +# +############################################################ GLOBALS + +VERSION='$Version: 1.0 $' + +pgm="${0##*/}" # Program basename + +# +# Global exit status +# +SUCCESS=0 +FAILURE=1 + +# +# Command-line options +# +OUTPUT_FILE= # -o file + +# +# Miscellaneous +# +PRIV_H= + +############################################################ FUNCTIONS + +usage() +{ + local fmt="$1" + local optfmt="\t%-5s %s\n" + + exec >&2 + if [ "$fmt" ]; then + shift 1 # fmt + printf "%s: $fmt\n" "$pgm" "$@" + fi + printf "Usage: %s [-hv] [-o file] priv.h\n" "$pgm" + printf "Options:\n" + printf "$optfmt" "-h" "Print this usage statment and exit." + printf "$optfmt" "-o file" "Write to output file instead of stdout." + printf "$optfmt" "-v" "Print version information and exit." + exit $FAILURE +} + +############################################################ MAIN + +# +# Process command-line options +# +while getopts ho:v flag; do + case "$flag" in + o) OUTPUT_FILE="$OPTARG" ;; + v) VERSION="${VERSION#*: }" + echo "${VERSION% $}" + exit $SUCCESS ;; + *) usage # NOTREACHED + esac +done +shift $(( $OPTIND - 1 )) + +# +# Check command-line arguments +# +[ $# -gt 0 ] || usage "Too few arguments" # NOTREACHED +[ $# -eq 1 ] || usage "Too many arguments" # NOTREACHED +[ "$1" ] || usage "Missing priv.h argument" # NOTREACHED +[ -e "$1" ] || usage "%s: No such file or directory" "$1" # NOTREACHED + +# +# Generate priv.d contents from priv.h input +# +PRIV_H="$1" +exec 9<<PRIV_D_EOF +/*- + * Copyright (c) 2026 Devin Teske <dteske@FreeBSD.org> + * + * SPDX-License-Identifier: BSD-2-Clause + */ + +/* + * Map priv(9) privilege values to their symbolic names. + * NB: Mechanically generated from <sys/priv.h> -- keep in-sync. + * NB: Generated by /usr/src/cddl/lib/libdtrace/$pgm + */ + +#pragma D binding "1.13" priv_string +inline string priv_string[int priv] = +$( awk ' + /^#define[[:space:]]+PRIV_[A-Z0-9_]+[[:space:]]+[0-9]+/ { + for (i = 0; ++i <= NF; ) if ($i ~ /define/) break + name = $++i + value = $++i + printf "\tpriv == %s ?\t\t\"%s\" :\n", value, name + }' "$PRIV_H" +) + strjoin("PRIV_UNKNOWN#", lltostr(priv)); +PRIV_D_EOF + +# +# Output contents +# +[ ! "$OUTPUT_FILE" ] || exec > "$OUTPUT_FILE" +cat <&9 + +################################################################################ +# END +################################################################################ diff --git a/cddl/usr.sbin/dwatch/dwatch.1 b/cddl/usr.sbin/dwatch/dwatch.1 index 81efb2c2c437..8c201d970620 100644 --- a/cddl/usr.sbin/dwatch/dwatch.1 +++ b/cddl/usr.sbin/dwatch/dwatch.1 @@ -1,4 +1,4 @@ -.\" Copyright (c) 2014-2018 Devin Teske +.\" Copyright (c) 2014-2026 Devin Teske .\" All rights reserved. .\" .\" Redistribution and use in source and binary forms, with or without @@ -22,7 +22,7 @@ .\" ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE .\" POSSIBILITY OF SUCH DAMAGE. .\" -.Dd April 18, 2025 +.Dd July 4, 2026 .Dt DWATCH 1 .Os .Sh NAME @@ -382,17 +382,69 @@ Print mode and path from .Xr chmod 2 , .Xr lchmod 2 , .Xr fchmodat 2 +.It coredump +Print coredump-worthy signal deliveries with a verdict of whether a +core will actually be written +.It coredump-top +Maintain a running catalog of coredump-worthy signals by process and +signal +.It dtmalloc +Print kernel +.Xr malloc 9 +and +.Xr free 9 +activity by malloc type, +meeting a size threshold +.It dtmalloc-top +Maintain a running catalog of net bytes and allocation balance by +malloc type +.Pq leak suspects rise .It errno Print non-zero errno results from system calls +.It errno- Ns Ar NAME +Print system calls returning the given errno, +by symbolic name or number +.Pq e.g., errno-ENOENT, errno-ENOTCAPABLE, errno-13 +.It hang +Print threads that were asleep longer than a threshold, +as they wake, +naming the sleeper and the waker +.It hang-top +Maintain a running catalog of long sleeps by process .It io Print disk I/O details provided by .Xr dtrace_io 4 +.It io-slow +Print disk I/O requests exceeding a latency threshold .It ip Print IPv4 and IPv6 details provided by .Xr dtrace_ip 4 +.It jail +Print jail management activity from +.Xr jail 2 , +.Xr jail_set 2 , +.Xr jail_get 2 , +.Xr jail_attach 2 , +.Xr jail_remove 2 .It kill Print signal and pid from .Xr kill 2 +.It lock +Print kernel lock contention details provided by +.Xr dtrace_lockstat 4 +.It lock-spin +Print kernel lock spinning details provided by +.Xr dtrace_lockstat 4 +.It mib +Print network stack statistics counters as they increment +.Pq requires a kernel built with options KDTRACE_MIB_SDT +.It namei +Print pathname resolution details provided by the +.Fn vfs:namei:lookup +probes +.It namei-failure +Print failed pathname resolutions +.Pq also namei-enoent for ENOENT only .It nanosleep Print requested time from .Xr nanosleep 2 @@ -400,12 +452,19 @@ Print requested time from Print path from .Xr open 2 , .Xr openat 2 +.It priv +Print privilege requests denied by +.Xr priv_check 9 +.Pq also priv-ok for those granted .It proc Print process execution details provided by .Xr dtrace_proc 4 .It proc-signal Print process signal details provided by .Xr dtrace_proc 4 +.It proc-signal-fatal +Print only signals whose default disposition is to terminate the +receiving process .It rw Print buffer contents from .Xr read 2 , @@ -413,12 +472,24 @@ Print buffer contents from .It sched Print CPU scheduling details provided by .Xr dtrace_sched 4 +.It sched-latency +Print threads that waited longer than a threshold between becoming +runnable and running +.It slow +Print filesystem-related syscalls exceeding a latency threshold +.It slow-syscall +Print any syscall exceeding a latency threshold .It tcp Print TCP address/port details provided by .Xr dtrace_tcp 4 .It tcp-io Print TCP I/O details provided by .Xr dtrace_tcp 4 +.It tcp-retransmit +Print TCP retransmissions, +retransmit timeouts, +and connections dropped by retransmit exhaustion +.Pq requires a kernel built with options KDTRACE_MIB_SDT .It udp Print UDP I/O details provided by .Xr dtrace_udp 4 @@ -454,6 +525,26 @@ Print symlink paths being created by These environment variables affect the execution of .Nm : .Bl -tag -width "DWATCH_PROFILES_PATH" +.It Ev DWATCH_HANG_MS +Minimum sleep duration, +in milliseconds, +displayed by the hang profiles +.Pq default 1000; 0 to show everything . +.It Ev DWATCH_IO_MS +Minimum disk I/O request latency, +in milliseconds, +displayed by the io-slow profile +.Pq default 100; 0 to show everything . +.It Ev DWATCH_LOCK_MS +Minimum lock holdoff duration, +in milliseconds, +displayed by the lock profiles +.Pq default 1; 0 to show everything . +.It Ev DWATCH_MALLOC_MIN +Minimum allocation size, +in bytes, +displayed by the dtmalloc profiles +.Pq default 65536; 0 to show everything . .It Ev DWATCH_PROFILES_PATH If .Ev DWATCH_PROFILES_PATH @@ -464,6 +555,16 @@ variable instead of the default .Ql Li /usr/libexec/dwatch:/usr/local/libexec/dwatch . If set to NULL, profiles are not loaded. +.It Ev DWATCH_SCHED_MS +Minimum run-queue wait, +in milliseconds, +displayed by the sched-latency profile +.Pq default 10; 0 to show everything . +.It Ev DWATCH_SLOW_MS +Minimum syscall latency, +in milliseconds, +displayed by the slow profiles +.Pq default 100 . .El .Sh EXIT STATUS .Ex -std diff --git a/cddl/usr.sbin/dwatch/libexec/Makefile b/cddl/usr.sbin/dwatch/libexec/Makefile index 72ea5be686fb..d32c54c34c83 100644 --- a/cddl/usr.sbin/dwatch/libexec/Makefile +++ b/cddl/usr.sbin/dwatch/libexec/Makefile @@ -1,16 +1,25 @@ PACKAGE= dwatch FILESDIR= ${LIBEXECDIR}/dwatch FILES= chmod \ + coredump \ + dtmalloc \ errno \ + hang \ io \ ip \ + jail \ kill \ + lock \ + mib \ + namei \ nanosleep \ open \ + priv \ proc \ rw \ sched \ sendrecv \ + slow \ systop \ tcp \ udp \ @@ -23,11 +32,37 @@ FILES= chmod \ LINKMODE= ${SHAREMODE} LINKS= ${LIBEXECDIR}/dwatch/chmod ${LIBEXECDIR}/dwatch/fchmodat LINKS+= ${LIBEXECDIR}/dwatch/chmod ${LIBEXECDIR}/dwatch/lchmod +LINKS+= ${LIBEXECDIR}/dwatch/coredump ${LIBEXECDIR}/dwatch/coredump-top +LINKS+= ${LIBEXECDIR}/dwatch/dtmalloc ${LIBEXECDIR}/dwatch/dtmalloc-top +LINKS+= ${LIBEXECDIR}/dwatch/errno ${LIBEXECDIR}/dwatch/errno-EACCES +LINKS+= ${LIBEXECDIR}/dwatch/errno ${LIBEXECDIR}/dwatch/errno-ECAPMODE +LINKS+= ${LIBEXECDIR}/dwatch/errno ${LIBEXECDIR}/dwatch/errno-ENOENT +LINKS+= ${LIBEXECDIR}/dwatch/errno ${LIBEXECDIR}/dwatch/errno-ENOTCAPABLE +LINKS+= ${LIBEXECDIR}/dwatch/errno ${LIBEXECDIR}/dwatch/errno-EPERM +LINKS+= ${LIBEXECDIR}/dwatch/hang ${LIBEXECDIR}/dwatch/hang-top LINKS+= ${LIBEXECDIR}/dwatch/io ${LIBEXECDIR}/dwatch/io-done +LINKS+= ${LIBEXECDIR}/dwatch/io ${LIBEXECDIR}/dwatch/io-slow LINKS+= ${LIBEXECDIR}/dwatch/io ${LIBEXECDIR}/dwatch/io-start LINKS+= ${LIBEXECDIR}/dwatch/ip ${LIBEXECDIR}/dwatch/ip-receive LINKS+= ${LIBEXECDIR}/dwatch/ip ${LIBEXECDIR}/dwatch/ip-send +LINKS+= ${LIBEXECDIR}/dwatch/jail ${LIBEXECDIR}/dwatch/jail-attach +LINKS+= ${LIBEXECDIR}/dwatch/jail ${LIBEXECDIR}/dwatch/jail-get +LINKS+= ${LIBEXECDIR}/dwatch/jail ${LIBEXECDIR}/dwatch/jail-remove +LINKS+= ${LIBEXECDIR}/dwatch/jail ${LIBEXECDIR}/dwatch/jail-set +LINKS+= ${LIBEXECDIR}/dwatch/lock ${LIBEXECDIR}/dwatch/lock-adaptive +LINKS+= ${LIBEXECDIR}/dwatch/lock ${LIBEXECDIR}/dwatch/lock-block +LINKS+= ${LIBEXECDIR}/dwatch/lock ${LIBEXECDIR}/dwatch/lock-lockmgr +LINKS+= ${LIBEXECDIR}/dwatch/lock ${LIBEXECDIR}/dwatch/lock-rw +LINKS+= ${LIBEXECDIR}/dwatch/lock ${LIBEXECDIR}/dwatch/lock-spin +LINKS+= ${LIBEXECDIR}/dwatch/lock ${LIBEXECDIR}/dwatch/lock-sx +LINKS+= ${LIBEXECDIR}/dwatch/lock ${LIBEXECDIR}/dwatch/lock-thread +LINKS+= ${LIBEXECDIR}/dwatch/mib ${LIBEXECDIR}/dwatch/tcp-retransmit +LINKS+= ${LIBEXECDIR}/dwatch/namei ${LIBEXECDIR}/dwatch/namei-enoent +LINKS+= ${LIBEXECDIR}/dwatch/namei ${LIBEXECDIR}/dwatch/namei-entry +LINKS+= ${LIBEXECDIR}/dwatch/namei ${LIBEXECDIR}/dwatch/namei-failure LINKS+= ${LIBEXECDIR}/dwatch/open ${LIBEXECDIR}/dwatch/openat +LINKS+= ${LIBEXECDIR}/dwatch/priv ${LIBEXECDIR}/dwatch/priv-err +LINKS+= ${LIBEXECDIR}/dwatch/priv ${LIBEXECDIR}/dwatch/priv-ok LINKS+= ${LIBEXECDIR}/dwatch/proc ${LIBEXECDIR}/dwatch/proc-create LINKS+= ${LIBEXECDIR}/dwatch/proc ${LIBEXECDIR}/dwatch/proc-exec LINKS+= ${LIBEXECDIR}/dwatch/proc ${LIBEXECDIR}/dwatch/proc-exec-failure @@ -36,6 +71,7 @@ LINKS+= ${LIBEXECDIR}/dwatch/proc ${LIBEXECDIR}/dwatch/proc-exit LINKS+= ${LIBEXECDIR}/dwatch/proc ${LIBEXECDIR}/dwatch/proc-signal LINKS+= ${LIBEXECDIR}/dwatch/proc ${LIBEXECDIR}/dwatch/proc-signal-clear LINKS+= ${LIBEXECDIR}/dwatch/proc ${LIBEXECDIR}/dwatch/proc-signal-discard +LINKS+= ${LIBEXECDIR}/dwatch/proc ${LIBEXECDIR}/dwatch/proc-signal-fatal LINKS+= ${LIBEXECDIR}/dwatch/proc ${LIBEXECDIR}/dwatch/proc-signal-send LINKS+= ${LIBEXECDIR}/dwatch/proc ${LIBEXECDIR}/dwatch/proc-status LINKS+= ${LIBEXECDIR}/dwatch/rw ${LIBEXECDIR}/dwatch/read @@ -45,6 +81,7 @@ LINKS+= ${LIBEXECDIR}/dwatch/sched ${LIBEXECDIR}/dwatch/sched-cpu LINKS+= ${LIBEXECDIR}/dwatch/sched ${LIBEXECDIR}/dwatch/sched-dequeue LINKS+= ${LIBEXECDIR}/dwatch/sched ${LIBEXECDIR}/dwatch/sched-enqueue LINKS+= ${LIBEXECDIR}/dwatch/sched ${LIBEXECDIR}/dwatch/sched-exec +LINKS+= ${LIBEXECDIR}/dwatch/sched ${LIBEXECDIR}/dwatch/sched-latency LINKS+= ${LIBEXECDIR}/dwatch/sched ${LIBEXECDIR}/dwatch/sched-lend-pri LINKS+= ${LIBEXECDIR}/dwatch/sched ${LIBEXECDIR}/dwatch/sched-load-change LINKS+= ${LIBEXECDIR}/dwatch/sched ${LIBEXECDIR}/dwatch/sched-off-cpu @@ -63,6 +100,11 @@ LINKS+= ${LIBEXECDIR}/dwatch/sendrecv ${LIBEXECDIR}/dwatch/recvmsg LINKS+= ${LIBEXECDIR}/dwatch/sendrecv ${LIBEXECDIR}/dwatch/send LINKS+= ${LIBEXECDIR}/dwatch/sendrecv ${LIBEXECDIR}/dwatch/sendmsg LINKS+= ${LIBEXECDIR}/dwatch/sendrecv ${LIBEXECDIR}/dwatch/sendto +LINKS+= ${LIBEXECDIR}/dwatch/slow ${LIBEXECDIR}/dwatch/slow-fsync +LINKS+= ${LIBEXECDIR}/dwatch/slow ${LIBEXECDIR}/dwatch/slow-open +LINKS+= ${LIBEXECDIR}/dwatch/slow ${LIBEXECDIR}/dwatch/slow-read +LINKS+= ${LIBEXECDIR}/dwatch/slow ${LIBEXECDIR}/dwatch/slow-syscall +LINKS+= ${LIBEXECDIR}/dwatch/slow ${LIBEXECDIR}/dwatch/slow-write LINKS+= ${LIBEXECDIR}/dwatch/tcp ${LIBEXECDIR}/dwatch/tcp-accept LINKS+= ${LIBEXECDIR}/dwatch/tcp ${LIBEXECDIR}/dwatch/tcp-accept-established LINKS+= ${LIBEXECDIR}/dwatch/tcp ${LIBEXECDIR}/dwatch/tcp-accept-refused diff --git a/cddl/usr.sbin/dwatch/libexec/coredump b/cddl/usr.sbin/dwatch/libexec/coredump new file mode 100644 index 000000000000..0b68564691de --- /dev/null +++ b/cddl/usr.sbin/dwatch/libexec/coredump @@ -0,0 +1,210 @@ +# -*- tab-width: 4 -*- ;; Emacs +# vi: set filetype=sh tabstop=8 shiftwidth=8 noexpandtab :: Vi/ViM +############################################################ IDENT(1) +# +# $Title: dwatch(8) module for coredump-worthy signal delivery $ +# $Copyright: 2026 Devin Teske. All rights reserved. $ +# +############################################################ DESCRIPTION +# +# Print signals whose default action produces a coredump, as they are +# sent, together with a verdict of whether a core will actually be +# written, rendered the same way and in the same order the kernel will +# decide it: the target may be ignoring or catching the signal, dumps +# may be disabled (kern.coredump), the target may be flagged sugid +# (kern.sugid_coredump) or may have disabled tracing via procctl(2) +# PROC_TRACE_CTL, or RLIMIT_CORE may be 0. +# Coredump-worthy is defined by the SIGPROP_CORE entries of the +# sigproptbl in kern_sig.c: SIGQUIT, SIGILL, SIGTRAP, SIGABRT, SIGEMT, +# SIGFPE, SIGBUS, SIGSEGV, and SIGSYS. +# The coredump-top profile maintains a running catalog, updated +# every 3 seconds, of coredump-worthy signals by process and signal. +# Combine with `-O cmd' to capture state as each event occurs. +# +############################################################ PRAGMAS + +case "$PROFILE" in +coredump-top) + DTRACE_PRAGMA=" + option quiet + option aggsortrev + " # END-QUOTE + ;; +esac + +############################################################ PROBE + +case "$PROFILE" in +coredump-top) + : ${PROBE:=profile:::tick-3s} ;; +*) + : ${PROBE:=proc:::signal-send} +esac + +############################################################ GLOBALS + +exec 9<<EOF +/* + * Signals whose default action includes a coredump, per the + * SIGPROP_CORE entries of the sigproptbl in kern_sig.c of FreeBSD + */ +inline int coredump_sig[int sig] = + sig == SIGQUIT ? 1 : + sig == SIGILL ? 1 : + sig == SIGTRAP ? 1 : + sig == SIGABRT ? 1 : /* SIGIOT */ + sig == SIGEMT ? 1 : + sig == SIGFPE ? 1 : + sig == SIGBUS ? 1 : + sig == SIGSEGV ? 1 : + sig == SIGSYS ? 1 : + 0; +EOF +GLOBALS=$( cat <&9 ) + +############################################################ EVENT ACTION + +[ "$CUSTOM_TEST" ] || case "$PROFILE" in +coredump-top) ;; +*) EVENT_TEST="coredump_sig[this->sig]" +esac + +############################################################ ACTIONS + +if [ "$PROFILE" = "coredump-top" ]; then +exec 9<<EOF +$GLOBALS + +BEGIN { printf("Cataloging coredump-worthy signals ...") } /* probe ID $ID */ + +proc:::signal-send /coredump_sig[(int)arg2]/ /* probe ID $(( $ID + 1 )) */ +{ + @cores[stringof(((struct proc *)args[1])->p_comm), + signal_string[(int)arg2]] = count(); +} +EOF +ACTIONS=$( cat <&9 ) +ID=$(( $ID + 2 )) +else +exec 9<<EOF +$GLOBALS + +this int sig; +this pid_t pid; +this string verdict; +this struct proc * target; +this u_int core_catch; +this u_int core_ign; +this u_int core_notrace; +this u_int core_sugid; +this uint64_t core_limit; + +$PROBE /* probe ID $ID */ +{${TRACE:+ + printf("<$ID>"); +} + this->target = (struct proc *)args[1]; + this->pid = (pid_t)this->target->p_pid; + this->sig = (int)arg2; +} + +$PROBE /* probe ID $(( $ID + 1 )) */ +{${TRACE:+ + printf("<$(( $ID + 1 ))>"); +} + /* + * Render a verdict the way the kernel will: disposition first + * (struct sigacts), then the coredump() gauntlet in its order: + * kern.coredump, kern.sugid_coredump vs P_SUGID, procctl(2) + * PROC_TRACE_CTL (P2_NOTRACE), and finally RLIMIT_CORE + */ + this->core_ign = + this->target->p_sigacts->ps_sigignore.__bits[ + (this->sig - 1) >> 5] & + (1 << ((this->sig - 1) & 31)); + this->core_catch = + this->target->p_sigacts->ps_sigcatch.__bits[ + (this->sig - 1) >> 5] & + (1 << ((this->sig - 1) & 31)); + this->core_sugid = + this->target->p_flag & 0x00000100; /* P_SUGID */ + this->core_notrace = + this->target->p_flag2 & 0x00000002; /* P2_NOTRACE */ + this->core_limit = this->target->p_limit-> + pl_rlimit[4].rlim_cur; /* RLIMIT_CORE */ + + this->verdict = + this->core_ign ? "ignored" : + this->core_catch ? "caught" : + \`do_coredump == 0 ? "denied by kern.coredump" : + this->core_sugid && \`sugid_coredump == 0 ? + "denied by kern.sugid_coredump" : + this->core_notrace ? "denied by procctl trace ctl" : + this->core_limit == 0 ? "denied by RLIMIT_CORE" : + "will dump core"; + + $( pproc -P _core "(struct proc *)args[1]" ) +} +EOF +ACTIONS=$( cat <&9 ) +ID=$(( $ID + 2 )) +fi + +############################################################ EVENT TAG + +# For the running catalog, override the default `UID.GID CMD[PID]: ' tag +# with ANSI cursor-homing and screen-clearing codes plus column headers. + +if [ "$PROFILE" = "coredump-top" ]; then +size=$( stty size 2> /dev/null ) +rows="${size%% *}" +cols="${size#* }" + +exec 9<<EOF + printf("\033[H"); /* Position the cursor at top-left */ + printf("\033[J"); /* Clear display from cursor to end */ + + /* Header line containing probe (left) and date (right) */ + printf("%-*s%s%Y%s\n", + $(( ${cols:-80} - 20 )), "$PROBE", + console ? "\033[32m" : "", + walltimestamp, + console ? "\033[39m" : ""); + + /* Column headers */ + printf("%s%8s %-20s %s%s\n", + console ? "\033[1m" : "", + "COUNT", + "EXECNAME", + "SIGNAL", + console ? "\033[22m" : ""); +EOF +EVENT_TAG=$( cat <&9 ) +fi + +############################################################ EVENT DETAILS + +if [ "$PROFILE" = "coredump-top" ]; then +exec 9<<EOF + /* NB: Cumulative; not truncated between updates */ + printa("%@8u %-20s %s\n", @cores); +EOF +EVENT_DETAILS=$( cat <&9 ) +elif [ ! "$CUSTOM_DETAILS" ]; then +exec 9<<EOF + /* + * Print coredump-worthy signal details + */ + printf("%s[%d] pid %d (%s) -- %s", + signal_string[this->sig], + this->sig, + this->pid, + this->verdict, + this->args_core); +EOF +EVENT_DETAILS=$( cat <&9 ) +fi + +################################################################################ +# END +################################################################################ diff --git a/cddl/usr.sbin/dwatch/libexec/dtmalloc b/cddl/usr.sbin/dwatch/libexec/dtmalloc new file mode 100644 index 000000000000..ad1a044020fa --- /dev/null +++ b/cddl/usr.sbin/dwatch/libexec/dtmalloc @@ -0,0 +1,146 @@ +# -*- tab-width: 4 -*- ;; Emacs +# vi: set filetype=sh tabstop=8 shiftwidth=8 noexpandtab :: Vi/ViM +############################################################ IDENT(1) +# +# $Title: dwatch(8) module for malloc(9) type activity $ +# $Copyright: 2026 Devin Teske. All rights reserved. $ +# +############################################################ DESCRIPTION +# +# Print kernel malloc(9) and free(9) activity by malloc type, via the +# dtmalloc provider (one malloc and one free probe per type; see +# vmstat -m for the types). The default profile prints allocations and +# frees meeting a size threshold (default 65536 bytes; tunable via +# DWATCH_MALLOC_MIN in the environment, 0 to show everything), +# answering "who is allocating huge kernel buffers?" Use +# dtmalloc-NAME to watch a single type (e.g., dtmalloc-devbuf). +# The dtmalloc-top profile maintains a running catalog, updated every +# 3 seconds, of net bytes and outstanding allocation balance by type: +# a type whose net bytes climb without bound while the system is in +# steady state is a leak suspect. NB: the catalog reflects activity +# since the watch began, not preexisting allocations, and caches +# legitimately hold what they allocate. +# +############################################################ PRAGMAS + +case "$PROFILE" in +dtmalloc-top) + DTRACE_PRAGMA=" + option quiet + option aggsortrev + " # END-QUOTE + ;; +esac + +############################################################ PROBE + +case "$PROFILE" in +dtmalloc) + : ${PROBE:=dtmalloc:::malloc, dtmalloc:::free} ;; +dtmalloc-top) + : ${PROBE:=profile:::tick-3s} ;; +*) + : ${PROBE:=$( echo \ + dtmalloc::${PROFILE#dtmalloc-}:malloc, \ + dtmalloc::${PROFILE#dtmalloc-}:free )} ;; +esac + +############################################################ EVENT ACTION + +: ${DWATCH_MALLOC_MIN:=65536} + +case "$DWATCH_MALLOC_MIN" in +""|*[!0-9]*) die "DWATCH_MALLOC_MIN must be a number" ;; # NOTREACHED +esac + +[ "$CUSTOM_TEST" ] || case "$PROFILE" in +dtmalloc-top) ;; +*) EVENT_TEST="(uint64_t)arg3 >= $DWATCH_MALLOC_MIN" +esac + +############################################################ ACTIONS + +if [ "$PROFILE" = "dtmalloc-top" ]; then +exec 9<<EOF +this int64_t dtmalloc_delta; + +BEGIN { printf("Cataloging malloc(9) activity ...") } /* probe ID $ID */ + +dtmalloc:::malloc /* probe ID $(( $ID + 1 )) */ +{ + this->dtmalloc_delta = (int64_t)arg3; +} + +dtmalloc:::free /* probe ID $(( $ID + 2 )) */ +{ + this->dtmalloc_delta = -(int64_t)arg3; +} + +dtmalloc:::malloc, dtmalloc:::free /* probe ID $(( $ID + 3 )) */ +{ + @dtmalloc_bytes[probefunc] = sum(this->dtmalloc_delta); + @dtmalloc_allocs[probefunc] = + sum(this->dtmalloc_delta > 0 ? 1 : -1); +} +EOF +ACTIONS=$( cat <&9 ) +ID=$(( $ID + 4 )) +fi + +############################################################ EVENT TAG + +# For the running catalog, override the default `UID.GID CMD[PID]: ' tag +# with ANSI cursor-homing and screen-clearing codes plus column headers. + +if [ "$PROFILE" = "dtmalloc-top" ]; then +size=$( stty size 2> /dev/null ) +rows="${size%% *}" +cols="${size#* }" + +exec 9<<EOF + printf("\033[H"); /* Position the cursor at top-left */ + printf("\033[J"); /* Clear display from cursor to end */ + + /* Header line containing probe (left) and date (right) */ + printf("%-*s%s%Y%s\n", + $(( ${cols:-80} - 20 )), "$PROBE", + console ? "\033[32m" : "", + walltimestamp, + console ? "\033[39m" : ""); + + /* Column headers */ + printf("%s%14s %10s %s%s\n", + console ? "\033[1m" : "", + "NET(B)", + "BALANCE", + "TYPE", + console ? "\033[22m" : ""); +EOF +EVENT_TAG=$( cat <&9 ) +fi + +############################################################ EVENT DETAILS + +if [ "$PROFILE" = "dtmalloc-top" ]; then +exec 9<<EOF + /* NB: Cumulative; not truncated between updates */ + printa("%@14d %@10d %s\n", @dtmalloc_bytes, @dtmalloc_allocs); +EOF +EVENT_DETAILS=$( cat <&9 ) +elif [ ! "$CUSTOM_DETAILS" ]; then +exec 9<<EOF + /* + * Print malloc(9) activity details + */ + printf("%s(9) type %s %d byte%s", + probename, + probefunc, + (long)arg3, + (long)arg3 == 1 ? "" : "s"); +EOF +EVENT_DETAILS=$( cat <&9 ) +fi + +################################################################################ +# END +################################################################################ diff --git a/cddl/usr.sbin/dwatch/libexec/errno b/cddl/usr.sbin/dwatch/libexec/errno index d899906a1313..e87cbde7ce50 100644 --- a/cddl/usr.sbin/dwatch/libexec/errno +++ b/cddl/usr.sbin/dwatch/libexec/errno @@ -3,7 +3,7 @@ ############################################################ IDENT(1) # # $Title: dwatch(8) module for syscall errno logging $ -# $Copyright: 2014-2018 Devin Teske. All rights reserved. $ +# $Copyright: 2014-2026 Devin Teske. All rights reserved. $ # ############################################################ DESCRIPTION # @@ -11,13 +11,24 @@ # To override the default test condition, use (for example) `-t errno==2' to # test for specific value or simply `-t 1' to unconditionally show all values. # +# When invoked as errno-NAME, only syscalls returning that errno are shown, +# where NAME is either a symbolic name from errno.d of libdtrace(1) or a +# number; e.g., errno-ENOENT for failed pathname lookups, errno-EACCES or +# errno-EPERM for permission problems, and errno-ENOTCAPABLE or +# errno-ECAPMODE for capsicum(4) capability-mode violations. Links are +# installed for the aforementioned; others need only a new link to this +# module (e.g., `ln -s errno errno-EDEADLK'). +# ############################################################ PROBE : ${PROBE:=syscall:::return} ############################################################ EVENT ACTION -[ "$CUSTOM_TEST" ] || EVENT_TEST="errno > 0" +[ "$CUSTOM_TEST" ] || case "$PROFILE" in +errno) EVENT_TEST="errno > 0" ;; + *) EVENT_TEST="errno == ${PROFILE#errno-}" +esac ############################################################ EVENT DETAILS diff --git a/cddl/usr.sbin/dwatch/libexec/hang b/cddl/usr.sbin/dwatch/libexec/hang new file mode 100644 index 000000000000..22f15544b47b --- /dev/null +++ b/cddl/usr.sbin/dwatch/libexec/hang @@ -0,0 +1,174 @@ +# -*- tab-width: 4 -*- ;; Emacs +# vi: set filetype=sh tabstop=8 shiftwidth=8 noexpandtab :: Vi/ViM +############################################################ IDENT(1) +# +# $Title: dwatch(8) module for long sleeps and hung threads $ +# $Copyright: 2026 Devin Teske. All rights reserved. $ +# +############################################################ DESCRIPTION +# +# Print threads that were asleep for a long time, as they wake, naming +# the sleeper, how long it slept, and (in the standard event tag) the +# process that woke it. Sleeps shorter than a threshold are suppressed +# (default 1000 ms; tunable via DWATCH_HANG_MS in the environment, 0 to +# show everything). Answers "what was my process stuck on?" -- the +# blocking that the slow profile cannot see, because a syscall that +# never returns never reports its latency. NB: the report fires at +# wakeup with the full duration; a thread still asleep has not yet +# been reported. +# The hang-top profile maintains a running catalog, updated every +# 3 seconds, of long sleeps by process. Combine with `-O cmd' to +# capture state as each event occurs. +# +############################################################ PRAGMAS + +case "$PROFILE" in +hang-top) + DTRACE_PRAGMA=" + option quiet + option aggsortrev + " # END-QUOTE + ;; +esac + +############################################################ PROBE + +case "$PROFILE" in +hang-top) + : ${PROBE:=profile:::tick-3s} ;; +*) + : ${PROBE:=sched:::wakeup} +esac + +############################################################ EVENT ACTION + +: ${DWATCH_HANG_MS:=1000} + +case "$DWATCH_HANG_MS" in +""|*[!0-9]*) die "DWATCH_HANG_MS must be a number" ;; # NOTREACHED +esac + +[ "$CUSTOM_TEST" ] || case "$PROFILE" in +hang-top) ;; +*) EVENT_TEST="this->hang_ns >= (int64_t)$DWATCH_HANG_MS * 1000000" +esac + +############################################################ ACTIONS + +if [ "$PROFILE" = "hang-top" ]; then +exec 9<<EOF +this int64_t hang_ns; +int64_t hang_ts[int]; + +BEGIN { printf("Cataloging long sleeps ...") } /* probe ID $ID */ + +sched:::sleep /* probe ID $(( $ID + 1 )) */ +{ + hang_ts[curthread->td_tid] = timestamp; +} + +sched:::wakeup /* probe ID $(( $ID + 2 )) */ +{ + /* NB: -1 if we did not see the sleep (enabled mid-sleep) */ + this->hang_ns = + hang_ts[((struct thread *)args[0])->td_tid] ? timestamp - + hang_ts[((struct thread *)args[0])->td_tid] : -1; + hang_ts[((struct thread *)args[0])->td_tid] = 0; +} + +sched:::wakeup /this->hang_ns >= + (int64_t)$DWATCH_HANG_MS * 1000000/ /* probe ID $(( $ID + 3 )) */ +{ + @hang_cnt[stringof(((struct proc *)args[1])->p_comm)] = count(); + @hang_max[stringof(((struct proc *)args[1])->p_comm)] = + max(this->hang_ns / 1000000); +} +EOF +ACTIONS=$( cat <&9 ) +ID=$(( $ID + 4 )) +else +exec 9<<EOF +this int64_t hang_ns; +int64_t hang_ts[int]; + +sched:::sleep /* probe ID $ID */ +{${TRACE:+ + printf("<$ID>"); +} + hang_ts[curthread->td_tid] = timestamp; +} + +$PROBE /* probe ID $(( $ID + 1 )) */ +{${TRACE:+ + printf("<$(( $ID + 1 ))>"); +} + /* NB: -1 if we did not see the sleep (enabled mid-sleep) */ + this->hang_ns = + hang_ts[((struct thread *)args[0])->td_tid] ? timestamp - + hang_ts[((struct thread *)args[0])->td_tid] : -1; + hang_ts[((struct thread *)args[0])->td_tid] = 0; + + $( pproc -P _hang "(struct proc *)args[1]" ) +} +EOF +ACTIONS=$( cat <&9 ) +ID=$(( $ID + 2 )) +fi + +############################################################ EVENT TAG + +# For the running catalog, override the default `UID.GID CMD[PID]: ' tag +# with ANSI cursor-homing and screen-clearing codes plus column headers. + +if [ "$PROFILE" = "hang-top" ]; then +size=$( stty size 2> /dev/null ) +rows="${size%% *}" +cols="${size#* }" + +exec 9<<EOF + printf("\033[H"); /* Position the cursor at top-left */ + printf("\033[J"); /* Clear display from cursor to end */ + + /* Header line containing probe (left) and date (right) */ + printf("%-*s%s%Y%s\n", + $(( ${cols:-80} - 20 )), "$PROBE", + console ? "\033[32m" : "", + walltimestamp, + console ? "\033[39m" : ""); + + /* Column headers */ + printf("%s%8s %10s %s%s\n", + console ? "\033[1m" : "", + "COUNT", + "MAX(ms)", + "EXECNAME", + console ? "\033[22m" : ""); +EOF +EVENT_TAG=$( cat <&9 ) +fi + +############################################################ EVENT DETAILS + +if [ "$PROFILE" = "hang-top" ]; then +exec 9<<EOF + /* NB: Cumulative; not truncated between updates */ + printa("%@8u %@10d %s\n", @hang_cnt, @hang_max); +EOF +EVENT_DETAILS=$( cat <&9 ) +elif [ ! "$CUSTOM_DETAILS" ]; then +exec 9<<EOF + /* + * Print long sleep details (tag shows the waker) + */ + printf("pid %d slept %d.%03d ms -- %s", + this->pid_hang, + this->hang_ns / 1000000, + (this->hang_ns % 1000000) / 1000, + this->args_hang); +EOF +EVENT_DETAILS=$( cat <&9 ) +fi + +################################################################################ +# END +################################################################################ diff --git a/cddl/usr.sbin/dwatch/libexec/io b/cddl/usr.sbin/dwatch/libexec/io index 6aafb624c820..f8d84d7d1fc2 100644 --- a/cddl/usr.sbin/dwatch/libexec/io +++ b/cddl/usr.sbin/dwatch/libexec/io @@ -3,22 +3,42 @@ ############################################################ IDENT(1) # # $Title: dwatch(8) module for dtrace_io(4) $ -# $Copyright: 2014-2018 Devin Teske. All rights reserved. $ +# $Copyright: 2014-2026 Devin Teske. All rights reserved. $ # ############################################################ DESCRIPTION # -# Display activity related to disk I/O +# Display activity related to disk I/O. The io-slow profile instead +# measures per-request latency -- the time between io:::start and +# io:::done for the same struct bio -- printing any request that meets +# a threshold (default 100 ms; tunable via DWATCH_IO_MS in the +# environment, 0 to show everything). Answers "is the application slow +# because the disk is slow?" and, watched per-device, hunts I/O +# starvation; on ZFS, watched against zvols and the pool's leaf vdevs, +# it brackets where in the stack the time is going. # ############################################################ PROBE case "$PROFILE" in io) : ${PROBE:=io:::start, io:::done} ;; +io-slow) : ${PROBE:=io:::done} ;; *) : ${PROBE:=io:::${PROFILE#io-}} esac ############################################################ EVENT ACTION -[ "$CUSTOM_TEST" ] || EVENT_TEST='this->devinfo.dev_name != ""' +if [ "$PROFILE" = "io-slow" ]; then + : ${DWATCH_IO_MS:=100} + + case "$DWATCH_IO_MS" in + ""|*[!0-9]*) die "DWATCH_IO_MS must be a number" ;; # NOTREACHED + esac + + [ "$CUSTOM_TEST" ] || + EVENT_TEST="this->devinfo.dev_name != \"\" && + this->io_ns >= (int64_t)$DWATCH_IO_MS * 1000000" +else + [ "$CUSTOM_TEST" ] || EVENT_TEST='this->devinfo.dev_name != ""' +fi ############################################################ ACTIONS @@ -82,9 +102,53 @@ EOF ACTIONS=$( cat <&9 ) ID=$(( $ID + 1 )) +if [ "$PROFILE" = "io-slow" ]; then +exec 9<<EOF +$ACTIONS + +this int64_t io_ns; +int64_t io_ts[uintptr_t]; + +io:::start /(struct bio *)args[0] != NULL/ /* probe ID $ID */ +{${TRACE:+ + printf("<$ID>"); +} + io_ts[(uintptr_t)args[0]] = timestamp; +} + +$PROBE /(struct bio *)args[0] != NULL/ /* probe ID $(( $ID + 1 )) */ +{${TRACE:+ + printf("<$(( $ID + 1 ))>"); +} + /* NB: -1 if we did not see the start (enabled mid-request) */ + this->io_ns = io_ts[(uintptr_t)args[0]] ? + timestamp - io_ts[(uintptr_t)args[0]] : -1; + io_ts[(uintptr_t)args[0]] = 0; +} +EOF +ACTIONS=$( cat <&9 ) +ID=$(( $ID + 2 )) +fi + ############################################################ EVENT DETAILS -if [ ! "$CUSTOM_DETAILS" ]; then +if [ "$PROFILE" = "io-slow" ] && [ ! "$CUSTOM_DETAILS" ]; then +exec 9<<EOF + /* + * Print disk I/O latency details + */ + printf("%s %s %s %s %d byte%s %d.%03d ms", + this->device_type, + this->device_entry, + this->bio_cmd, + this->bio_flags, + this->bio_length, + this->bio_length == 1 ? "" : "s", + this->io_ns / 1000000, + (this->io_ns % 1000000) / 1000); +EOF +EVENT_DETAILS=$( cat <&9 ) +elif [ ! "$CUSTOM_DETAILS" ]; then exec 9<<EOF /* * Print disk I/O details diff --git a/cddl/usr.sbin/dwatch/libexec/jail b/cddl/usr.sbin/dwatch/libexec/jail new file mode 100644 index 000000000000..0696367782e0 --- /dev/null +++ b/cddl/usr.sbin/dwatch/libexec/jail @@ -0,0 +1,92 @@ +# -*- tab-width: 4 -*- ;; Emacs +# vi: set filetype=sh tabstop=8 shiftwidth=8 noexpandtab :: Vi/ViM +############################################################ IDENT(1) +# +# $Title: dwatch(8) module for jail(2) management syscalls $ +# $Copyright: 2026 Devin Teske. All rights reserved. $ +# +############################################################ DESCRIPTION +# +# Print jail management activity -- jail(2), jail_set(2), jail_get(2), +# jail_attach(2), and jail_remove(2) -- naming the syscall, the jail id +# operated on, and any errno returned. Answers "who is creating, +# entering, or destroying jails?" Complements the dwatch `-j jail' +# filter, which scopes any profile to processes inside one jail; this +# profile watches the management plane itself, from any jail or none. +# Use jail-attach, jail-get, jail-remove, or jail-set to watch a +# single operation by name. +# +############################################################ PROBE + +case "$PROFILE" in +jail) + : ${PROBE:=$( echo \ + syscall::jail:return, \ + syscall::jail_set:return, \ + syscall::jail_get:return, \ + syscall::jail_attach:return, \ + syscall::jail_remove:return )} ;; +*) + : ${PROBE:=syscall::jail_${PROFILE#jail-}:return} +esac + +# +# Derive the matching entry probes from the return probes being watched +# +ENTRY_PROBE=$( echo "$PROBE" | awk 'gsub(/:return/, ":entry") || 1' ) + +############################################################ ACTIONS + +exec 9<<EOF +self int jail_arg; +this int jail_jid; + +$ENTRY_PROBE /* probe ID $ID */ +{${TRACE:+ + printf("<$ID>");} + self->jail_arg = -1; +} + +syscall::jail_attach:entry, +syscall::jail_remove:entry /* probe ID $(( $ID + 1 )) */ +{${TRACE:+ + printf("<$(( $ID + 1 ))>");} + /* arg0 is the jail id being attached-to or removed */ + self->jail_arg = (int)arg0; +} + +$PROBE /* probe ID $(( $ID + 2 )) */ +{${TRACE:+ + printf("<$(( $ID + 2 ))>"); +} + /* + * jail(2), jail_set(2), and jail_get(2) return the jail id; + * jail_attach(2) and jail_remove(2) were given it at entry + */ + this->jail_jid = self->jail_arg >= 0 ? + self->jail_arg : (int)arg0; + self->jail_arg = 0; +} +EOF +ACTIONS=$( cat <&9 ) +ID=$(( $ID + 3 )) + +############################################################ EVENT DETAILS + +if [ ! "$CUSTOM_DETAILS" ]; then +exec 9<<EOF + /* + * Print jail management details + */ + printf("%s(2) jid %d%s%s", + probefunc, + this->jail_jid, + errno > 0 ? " -- " : "", + errno > 0 ? strerror[errno] : ""); +EOF +EVENT_DETAILS=$( cat <&9 ) +fi + +################################################################################ +# END +################################################################################ diff --git a/cddl/usr.sbin/dwatch/libexec/lock b/cddl/usr.sbin/dwatch/libexec/lock new file mode 100644 index 000000000000..f27c96718a0c --- /dev/null +++ b/cddl/usr.sbin/dwatch/libexec/lock @@ -0,0 +1,136 @@ +# -*- tab-width: 4 -*- ;; Emacs +# vi: set filetype=sh tabstop=8 shiftwidth=8 noexpandtab :: Vi/ViM +############################################################ IDENT(1) +# +# $Title: dwatch(8) module for dtrace_lockstat(4) contention $ +# $Copyright: 2026 Devin Teske. All rights reserved. $ +# +############################################################ DESCRIPTION +# +# Print kernel lock contention events reported by dtrace_lockstat(4), +# naming the lock, the thread held-off by it, and for how long. Answers +# "the system is slow -- where is it fighting over locks?" The default +# profile watches block events (thread went off-CPU waiting); lock-spin +# watches spin events instead. Contention shorter than a threshold is +# suppressed (default 1 ms; tunable via DWATCH_LOCK_MS in the environment, +# 0 to show everything). +# +############################################################ PROBE + +case "$PROFILE" in +lock|lock-block) + : ${PROBE:=$( echo \ + lockstat:::adaptive-block, \ + lockstat:::lockmgr-block, \ + lockstat:::rw-block, \ + lockstat:::sx-block )} ;; +lock-spin) + : ${PROBE:=$( echo \ + lockstat:::adaptive-spin, \ + lockstat:::rw-spin, \ + lockstat:::spin-spin, \ + lockstat:::sx-spin, \ + lockstat:::thread-spin )} ;; +lock-adaptive) + : ${PROBE:=lockstat:::adaptive-block, lockstat:::adaptive-spin} ;; +lock-lockmgr) + : ${PROBE:=lockstat:::lockmgr-block} ;; +lock-rw) + : ${PROBE:=lockstat:::rw-block, lockstat:::rw-spin} ;; +lock-sx) + : ${PROBE:=lockstat:::sx-block, lockstat:::sx-spin} ;; +lock-thread) + : ${PROBE:=lockstat:::thread-spin} ;; +*) + : ${PROBE:=lockstat:::${PROFILE#lock-}} +esac + +############################################################ EVENT ACTION + +: ${DWATCH_LOCK_MS:=1} + +case "$DWATCH_LOCK_MS" in +""|*[!0-9]*) die "DWATCH_LOCK_MS must be a number" ;; # NOTREACHED +esac + +[ "$CUSTOM_TEST" ] || + EVENT_TEST="(int64_t)arg1 >= (int64_t)$DWATCH_LOCK_MS * 1000000" + +############################################################ ACTIONS + +exec 9<<EOF +this string lock_class; +this string lock_how; +this string lock_name; +this string lock_verb; + +/* + * Lock classes from sys/lock.h as-witnessed by dtrace_lockstat(4) + */ +inline string lockstat_class[string name] = + name == "adaptive-block" ? "mtx" : + name == "adaptive-spin" ? "mtx" : + name == "lockmgr-block" ? "lockmgr" : + name == "rw-block" ? "rw" : + name == "rw-spin" ? "rw" : + name == "spin-spin" ? "spin mtx" : + name == "sx-block" ? "sx" : + name == "sx-spin" ? "sx" : + name == "thread-spin" ? "thread" : + name; + +inline string lockstat_verb[string name] = + name == "adaptive-block" ? "blocked" : + name == "lockmgr-block" ? "blocked" : + name == "rw-block" ? "blocked" : + name == "sx-block" ? "blocked" : + "spun"; + +$PROBE /* probe ID $ID */ +{${TRACE:+ + printf("<$ID>"); +} + /* + * struct lock_object * (first member of every kernel lock) + */ + this->lock_name = + stringof(((struct lock_object *)arg0)->lo_name); + this->lock_class = lockstat_class[probename]; + this->lock_verb = lockstat_verb[probename]; + this->lock_how = ""; +} + +lockstat:::lockmgr-block, +lockstat:::rw-block, +lockstat:::sx-block /* probe ID $(( $ID + 1 )) */ +{${TRACE:+ + printf("<$(( $ID + 1 ))>"); +} + /* arg2 is 0 when acquiring as writer, 1 as reader */ + this->lock_how = arg2 == 0 ? " as writer" : " as reader"; +} +EOF +ACTIONS=$( cat <&9 ) +ID=$(( $ID + 2 )) + +############################################################ EVENT DETAILS + +if [ ! "$CUSTOM_DETAILS" ]; then +exec 9<<EOF + /* + * Print lock contention details + */ + printf("%s %d.%03d ms on %s \"%s\"%s", + this->lock_verb, + (int64_t)arg1 / 1000000, + ((int64_t)arg1 % 1000000) / 1000, + this->lock_class, + this->lock_name, + this->lock_how); +EOF +EVENT_DETAILS=$( cat <&9 ) +fi + +################################################################################ +# END +################################################################################ diff --git a/cddl/usr.sbin/dwatch/libexec/mib b/cddl/usr.sbin/dwatch/libexec/mib new file mode 100644 index 000000000000..21ef4dd6d39c --- /dev/null +++ b/cddl/usr.sbin/dwatch/libexec/mib @@ -0,0 +1,78 @@ +# -*- tab-width: 4 -*- ;; Emacs +# vi: set filetype=sh tabstop=8 shiftwidth=8 noexpandtab :: Vi/ViM +############################################################ IDENT(1) +# +# $Title: dwatch(8) module for network stack counter probes $ +# $Copyright: 2026 Devin Teske. All rights reserved. $ +# +############################################################ DESCRIPTION +# +# Print network stack statistics counters as they increment, via the +# mib SDT probes (one probe per counter of the IP, ICMP, UDP, and TCP +# MIBs). The tcp-retransmit profile watches the counters that signal +# congestion or loss on the send path -- data packet retransmissions, +# retransmit timer expirations, and connections dropped by retransmit +# exhaustion -- answering "is this network slow because TCP is +# resending?" as events with process context, not just netstat(1) +# deltas. Use mib-NAME to watch a single counter by name (e.g., +# mib-tcps_sndrexmitpack). NB: the probes exist only in kernels built +# with options KDTRACE_MIB_SDT (enabled by default in -CURRENT via +# std.debug); elsewhere dtrace(1) will refuse the script. Counters +# bumped outside syscall context (e.g., timers) are tagged with the +# interrupted thread, commonly [clock] or [intr]. +# +############################################################ PROBE + +case "$PROFILE" in +mib) + : ${PROBE:=mib:::} ;; +tcp-retransmit) + : ${PROBE:=$( echo \ + mib:tcp:count:tcps_sndrexmitpack, \ + mib:tcp:count:tcps_sndrexmitbad, \ + mib:tcp:count:tcps_rexmttimeo, \ + mib:tcp:count:tcps_timeoutdrop )} ;; +*) + : ${PROBE:=mib:::${PROFILE#mib-}} +esac + +############################################################ ACTIONS + +exec 9<<EOF +this string mib_desc; + +/* + * Counters that signal send-path congestion or loss, described + */ +inline string mib_tcp_desc[string name] = + name == "tcps_sndrexmitpack" ? "data packet retransmitted" : + name == "tcps_sndrexmitbad" ? "unnecessary retransmission" : + name == "tcps_rexmttimeo" ? "retransmit timeout" : + name == "tcps_timeoutdrop" ? + "connection dropped by retransmit timeout" : + name; + +$PROBE /* probe ID $ID */ +{${TRACE:+ + printf("<$ID>");} + this->mib_desc = mib_tcp_desc[probename]; +} +EOF +ACTIONS=$( cat <&9 ) +ID=$(( $ID + 1 )) + +############################################################ EVENT DETAILS + +if [ ! "$CUSTOM_DETAILS" ]; then +exec 9<<EOF + /* + * Print counter increment details + */ + printf("%s (+%d)", this->mib_desc, (int)arg0); +EOF +EVENT_DETAILS=$( cat <&9 ) +fi + +################################################################################ +# END +################################################################################ diff --git a/cddl/usr.sbin/dwatch/libexec/namei b/cddl/usr.sbin/dwatch/libexec/namei new file mode 100644 index 000000000000..2b5d6be9f6ae --- /dev/null +++ b/cddl/usr.sbin/dwatch/libexec/namei @@ -0,0 +1,84 @@ +# -*- tab-width: 4 -*- ;; Emacs +# vi: set filetype=sh tabstop=8 shiftwidth=8 noexpandtab :: Vi/ViM +############################################################ IDENT(1) +# +# $Title: dwatch(8) module for namei(9) pathname resolution $ +# $Copyright: 2026 Devin Teske. All rights reserved. $ +# +############################################################ DESCRIPTION +# +# Print pathnames given to namei(9) for resolution, exactly as the process +# requested them, together with the lookup result. Unlike the vop_lookup +# profile, which reconstructs paths from the name cache one component at a +# time, this rides the vfs:namei:lookup probes and so sees the whole path +# in one piece. Use namei-failure to show only failed lookups or +# namei-enoent to hunt file-not-found storms (the single most common +# use of truss(1), without stopping the victim). +# +############################################################ PROBE + +case "$PROFILE" in +namei|namei-enoent|namei-failure) + : ${PROBE:=vfs:namei:lookup:return} ;; +namei-entry) + : ${PROBE:=vfs:namei:lookup:entry} ;; +*) + : ${PROBE:=vfs:namei:lookup:${PROFILE#namei-}} +esac + +############################################################ EVENT ACTION + +[ "$CUSTOM_TEST" ] || case "$PROFILE" in +namei-enoent) EVENT_TEST="this->namei_error == ENOENT" ;; +namei-failure) EVENT_TEST="this->namei_error != 0" ;; +esac + +############################################################ ACTIONS + +exec 9<<EOF +self string namei_path; +this int namei_error; +this string namei_pathstr; + +vfs:namei:lookup:entry /* probe ID $ID */ +{${TRACE:+ + printf("<$ID>"); +} + /* + * char * (kernel copy of the path being resolved) + */ + this->namei_pathstr = self->namei_path = stringof(arg1); + this->namei_error = 0; +} + +vfs:namei:lookup:return /* probe ID $(( $ID + 1 )) */ +{${TRACE:+ + printf("<$(( $ID + 1 ))>"); +} + /* NB: path was recorded at entry by the clause above */ + this->namei_pathstr = self->namei_path; + this->namei_error = (int)arg0; + self->namei_path = 0; +} +EOF +ACTIONS=$( cat <&9 ) +ID=$(( $ID + 2 )) + +############################################################ EVENT DETAILS + +if [ ! "$CUSTOM_DETAILS" ]; then +exec 9<<EOF + /* + * Print pathname resolution details + */ + printf("%s%s", this->namei_pathstr, + this->namei_error == 0 ? "" : strjoin(": ", + strjoin(strerror[this->namei_error], + strjoin(" (", strjoin(lltostr(this->namei_error), ")"))))); +EOF +EVENT_DETAILS=$( cat <&9 ) +fi + +################################################################################ +# END +################################################################################ diff --git a/cddl/usr.sbin/dwatch/libexec/priv b/cddl/usr.sbin/dwatch/libexec/priv new file mode 100644 index 000000000000..7899c3daf2f6 --- /dev/null +++ b/cddl/usr.sbin/dwatch/libexec/priv @@ -0,0 +1,59 @@ +# -*- tab-width: 4 -*- ;; Emacs +# vi: set filetype=sh tabstop=8 shiftwidth=8 noexpandtab :: Vi/ViM +############################################################ IDENT(1) +# +# $Title: dwatch(8) module for priv_check(9) privilege requests $ +# $Copyright: 2026 Devin Teske. All rights reserved. $ +# +############################################################ DESCRIPTION +# +# Print privilege requests denied by priv_check(9), decoded to their +# symbolic priv(9) names by the priv_string table in priv.d of +# libdtrace(1). Answers "why is this process getting EPERM?" -- kernel +# privilege denials (jails, unprivileged users, MAC policies) name the +# exact privilege refused, something no amount of truss(1) will reveal. +# Use priv-ok to instead watch privileges being granted. +# +# NB: Requires priv.d, a drop-in file for older releases like this module. +# +############################################################ PROBE + +case "$PROFILE" in +priv) + : ${PROBE:=priv:kernel:priv_check:priv-err} ;; +*) + : ${PROBE:=priv:kernel:priv_check:${PROFILE#priv-}} +esac + +############################################################ ACTIONS + +exec 9<<EOF +this int priv; + +$PROBE /* probe ID $ID */ +{${TRACE:+ + printf("<$ID>");} + this->priv = (int)arg0; +} +EOF +ACTIONS=$( cat <&9 ) +ID=$(( $ID + 1 )) + +############################################################ EVENT DETAILS + +if [ ! "$CUSTOM_DETAILS" ]; then +exec 9<<EOF + /* + * Print privilege request details + */ + printf("%s %s (%d)", + probename == "priv-err" ? "denied" : "granted", + priv_string[this->priv], + this->priv); +EOF +EVENT_DETAILS=$( cat <&9 ) +fi + +################################################################################ +# END +################################################################################ diff --git a/cddl/usr.sbin/dwatch/libexec/proc b/cddl/usr.sbin/dwatch/libexec/proc index 02d4d9d1fb8d..0d8974cf4379 100644 --- a/cddl/usr.sbin/dwatch/libexec/proc +++ b/cddl/usr.sbin/dwatch/libexec/proc @@ -3,7 +3,7 @@ ############################################################ IDENT(1) # # $Title: dwatch(8) module for dtrace_proc(4) activity $ -# $Copyright: 2014-2018 Devin Teske. All rights reserved. $ +# $Copyright: 2014-2026 Devin Teske. All rights reserved. $ # ############################################################ DESCRIPTION # @@ -29,6 +29,9 @@ proc-signal) proc:::signal-discard, \ proc:::signal-send )} ;; +proc-signal-fatal) + : ${PROBE:=proc:::signal-send} + ;; proc-status) : ${PROBE:=$( echo \ proc:::create, \ @@ -41,6 +44,24 @@ proc-status) : ${PROBE:=proc:::${PROFILE#proc-}} esac +############################################################ EVENT ACTION + +# Answer "what killed my process?" by showing only those signals whose +# default disposition is to terminate the process (with or without core), +# most-notably including kernel-generated SIGSEGV/SIGBUS/SIGILL/SIGFPE +# that no kill(2) watcher will ever see. + +[ "$CUSTOM_TEST" ] || case "$PROFILE" in +proc-signal-fatal) + EVENT_TEST="this->sig == SIGABRT || this->sig == SIGBUS || + this->sig == SIGEMT || this->sig == SIGFPE || + this->sig == SIGILL || this->sig == SIGKILL || + this->sig == SIGQUIT || this->sig == SIGSEGV || + this->sig == SIGSYS || this->sig == SIGTRAP || + this->sig == SIGXCPU || this->sig == SIGXFSZ" + ;; +esac + ############################################################ ACTIONS exec 9<<EOF diff --git a/cddl/usr.sbin/dwatch/libexec/sched b/cddl/usr.sbin/dwatch/libexec/sched index 2058f199f40a..2ad241b9c0e7 100644 --- a/cddl/usr.sbin/dwatch/libexec/sched +++ b/cddl/usr.sbin/dwatch/libexec/sched @@ -3,11 +3,17 @@ ############################################################ IDENT(1) # # $Title: dwatch(8) module for dtrace_sched(4) $ -# $Copyright: 2014-2018 Devin Teske. All rights reserved. $ +# $Copyright: 2014-2026 Devin Teske. All rights reserved. $ # ############################################################ DESCRIPTION # -# Display CPU scheduling activity +# Display CPU scheduling activity. The sched-latency profile instead +# measures run-queue latency -- the time between a thread being made +# runnable (enqueued) and actually running (on-cpu) -- printing any +# wait that meets a threshold (default 10 ms; tunable via +# DWATCH_SCHED_MS in the environment, 0 to show everything). Answers +# "the system has idle CPU but feels sluggish -- who is waiting to +# run, and for how long?" # ############################################################ PROBE @@ -18,6 +24,8 @@ sched-cpu) : ${PROBE:=sched:::off-cpu, sched:::on-cpu, sched:::remain-cpu} ;; sched-exec) : ${PROBE:=sched:::sleep, sched:::wakeup} ;; +sched-latency) + : ${PROBE:=sched:::on-cpu} ;; sched-pri) : ${PROBE:=sched:::change-pri, sched:::lend-pri} ;; sched-queue) @@ -26,8 +34,48 @@ sched-queue) : ${PROBE:=sched:::${PROFILE#sched-}} esac +############################################################ EVENT ACTION + +case "$PROFILE" in +sched-latency) + : ${DWATCH_SCHED_MS:=10} + + case "$DWATCH_SCHED_MS" in + ""|*[!0-9]*) die "DWATCH_SCHED_MS must be a number" ;; # NOTREACHED + esac + + [ "$CUSTOM_TEST" ] || + EVENT_TEST="this->sched_ns >= (int64_t)$DWATCH_SCHED_MS * 1000000" + ;; +esac + ############################################################ ACTIONS +if [ "$PROFILE" = "sched-latency" ]; then +exec 9<<EOF +this int64_t sched_ns; +int64_t sched_ts[int]; + +sched:::enqueue /* probe ID $ID */ +{${TRACE:+ + printf("<$ID>"); +} + sched_ts[((struct thread *)args[0])->td_tid] = timestamp; +} + +$PROBE /* probe ID $(( $ID + 1 )) */ +{${TRACE:+ + printf("<$(( $ID + 1 ))>"); +} + /* NB: -1 if we did not see the enqueue (enabled mid-wait) */ + this->sched_ns = sched_ts[curthread->td_tid] ? + timestamp - sched_ts[curthread->td_tid] : -1; + sched_ts[curthread->td_tid] = 0; +} +EOF +ACTIONS=$( cat <&9 ) +ID=$(( $ID + 2 )) +else exec 9<<EOF this pid_t pid; this string args; @@ -90,10 +138,21 @@ $PROBE /* probe ID $(( $ID + 5 )) */ EOF ACTIONS=$( cat <&9 ) ID=$(( $ID + 6 )) +fi ############################################################ EVENT DETAILS -if [ ! "$CUSTOM_DETAILS" ]; then +if [ "$PROFILE" = "sched-latency" ] && [ ! "$CUSTOM_DETAILS" ]; then +exec 9<<EOF + /* + * Print run-queue latency details + */ + printf("waited %d.%03d ms to run", + this->sched_ns / 1000000, + (this->sched_ns % 1000000) / 1000); +EOF +EVENT_DETAILS=$( cat <&9 ) +elif [ ! "$CUSTOM_DETAILS" ]; then exec 9<<EOF /* * Print scheduling details diff --git a/cddl/usr.sbin/dwatch/libexec/slow b/cddl/usr.sbin/dwatch/libexec/slow new file mode 100644 index 000000000000..b6b441008d01 --- /dev/null +++ b/cddl/usr.sbin/dwatch/libexec/slow @@ -0,0 +1,131 @@ +# -*- tab-width: 4 -*- ;; Emacs +# vi: set filetype=sh tabstop=8 shiftwidth=8 noexpandtab :: Vi/ViM +############################################################ IDENT(1) +# +# $Title: dwatch(8) module for slow syscall detection $ +# $Copyright: 2026 Devin Teske. All rights reserved. $ +# +############################################################ DESCRIPTION +# +# Print syscalls whose entry-to-return latency meets or exceeds a threshold +# (default 100 ms; tunable via DWATCH_SLOW_MS in the environment). Answers +# "why is my application stalling?" by naming the slow operation, the time +# it took, and any errno it returned. The default profile watches a curated +# set of filesystem-related syscalls that are expected to be fast. Use +# slow-syscall to watch every syscall (NB: intentionally-blocking syscalls +# such as select(2), poll(2), kevent(2), and wait4(2) will dominate), or +# slow-NAME (e.g., slow-connect) to watch a single syscall by name. +# +############################################################ PROBE + +case "$PROFILE" in +slow) + : ${PROBE:=$( echo \ + syscall::open:return, \ + syscall::openat:return, \ + syscall::close:return, \ + syscall::read:return, \ + syscall::readv:return, \ + syscall::pread:return, \ + syscall::preadv:return, \ + syscall::write:return, \ + syscall::writev:return, \ + syscall::pwrite:return, \ + syscall::pwritev:return, \ + syscall::copy_file_range:return, \ + syscall::getdirentries:return, \ + syscall::readlink:return, \ + syscall::readlinkat:return, \ + syscall::fsync:return, \ + syscall::fdatasync:return, \ + syscall::rename:return, \ + syscall::renameat:return, \ + syscall::renameat2:return, \ + syscall::unlink:return, \ + syscall::unlinkat:return )} ;; +slow-open) + : ${PROBE:=syscall::open:return, syscall::openat:return} ;; +slow-read) + : ${PROBE:=$( echo \ + syscall::read:return, \ + syscall::readv:return, \ + syscall::pread:return, \ + syscall::preadv:return, \ + syscall::getdirentries:return, \ + syscall::readlink:return, \ + syscall::readlinkat:return )} ;; +slow-write) + : ${PROBE:=$( echo \ + syscall::write:return, \ + syscall::writev:return, \ + syscall::pwrite:return, \ + syscall::pwritev:return, \ + syscall::copy_file_range:return )} ;; +slow-fsync) + : ${PROBE:=syscall::fsync:return, syscall::fdatasync:return} ;; +slow-syscall) + : ${PROBE:=syscall:::return} ;; +*) + : ${PROBE:=syscall::${PROFILE#slow-}:return} +esac + +# +# Derive the matching entry probes from the return probes being watched +# +ENTRY_PROBE=$( echo "$PROBE" | awk 'gsub(/:return/, ":entry") || 1' ) + +############################################################ EVENT ACTION + +: ${DWATCH_SLOW_MS:=100} + +case "$DWATCH_SLOW_MS" in +""|*[!0-9]*) die "DWATCH_SLOW_MS must be a number" ;; # NOTREACHED +esac + +[ "$CUSTOM_TEST" ] || + EVENT_TEST="this->slow_ns >= (int64_t)$DWATCH_SLOW_MS * 1000000" + +############################################################ ACTIONS + +exec 9<<EOF +self int64_t slow_ts; +this int64_t slow_ns; + +$ENTRY_PROBE /* probe ID $ID */ +{${TRACE:+ + printf("<$ID>");} + self->slow_ts = timestamp; +} + +$PROBE /* probe ID $(( $ID + 1 )) */ +{${TRACE:+ + printf("<$(( $ID + 1 ))>"); +} + /* NB: -1 if we did not see the entry (enabled mid-syscall) */ + this->slow_ns = self->slow_ts ? timestamp - self->slow_ts : -1; + self->slow_ts = 0; +} +EOF +ACTIONS=$( cat <&9 ) +ID=$(( $ID + 2 )) + +############################################################ EVENT DETAILS + +if [ ! "$CUSTOM_DETAILS" ]; then +exec 9<<EOF + /* + * Print syscall latency details + */ + printf("%s(2) %d.%03d ms%s%s", + probefunc, + this->slow_ns / 1000000, + (this->slow_ns % 1000000) / 1000, + errno > 0 ? " -- " : "", + errno > 0 ? strerror[errno] : ""); +EOF +EVENT_DETAILS=$( cat <&9 ) +fi + +################################################################################ +# END +################################################################################ |
