Page MenuHomeFreeBSD

dwatch: add nine diagnostic modules; grow errno, io, proc, sched
Needs ReviewPublic

Authored by dteske on Tue, Jul 7, 10:27 PM.
Tags
None
Referenced Files
F162649355: D58093.id.diff
Wed, Jul 15, 10:11 AM
F162612267: D58093.id181492.diff
Wed, Jul 15, 1:32 AM
F162593792: D58093.id181635.diff
Tue, Jul 14, 9:25 PM
F162569165: D58093.id181635.diff
Tue, Jul 14, 3:40 PM
F162569035: D58093.id.diff
Tue, Jul 14, 3:39 PM
F162568472: D58093.id181635.diff
Tue, Jul 14, 3:33 PM
Unknown Object (File)
Tue, Jul 14, 11:35 AM
Unknown Object (File)
Tue, Jul 14, 11:26 AM
Subscribers

Details

Reviewers
gnn
markj
Group Reviewers
DTrace
manpages
Summary

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.

Test Plan

Build in-tree from a clean checkout:

cd /usr/src
make -C cddl/lib/libdtrace all
make -C cddl/usr.sbin/dwatch all

No kernel rebuild required — this is all under cddl/.

Static checks I ran locally:

sh -n on each new/changed libexec module
mandoc -Tlint cddl/usr.sbin/dwatch/dwatch.1  (no new warnings)

For each new profile I ran dwatch -d and looked at the generated D
script — probe selection, entry/return pairing, threshold predicates,
-top aggregations, and -t overriding the default test all look right.
Unchanged profiles (sched, io, io-start, etc.) still produce the same
D as before.

Compile against the running kernel (needs root + dtrace):

kldload dtraceall   # if not already loaded

DWATCH=/usr/src/cddl/usr.sbin/dwatch/dwatch
LIB=/usr/src/cddl/lib/libdtrace

# priv* needs -L until priv.d is installed:
$DWATCH -eqX priv -L $LIB
$DWATCH -eqX priv-err -L $LIB

# spot-check the rest:
for p in slow lock namei coredump coredump-top hang hang-top \
         jail sched-latency io-slow dtmalloc dtmalloc-top \
         tcp-retransmit proc-signal-fatal errno-ENOENT; do
  $DWATCH -eqX $p || echo FAIL: $p
done

# (-e compile-checks, -q quiet, -X selects the profile by name)

tcp-retransmit / mib profiles only work on kernels with
KDTRACE_MIB_SDT (on by default in -CURRENT debug kernels via
std.debug). Without it dtrace will reject the script — expected,
documented in the man page.

Quick runtime smoke if you have a test box (Ctrl-C to stop each):

slow-open          ls /
namei-enoent       ls /no/such/file
hang               sleep 2   (in another window while hang runs)
sched-latency      run something CPU-heavy
io-slow            dd if=/dev/zero of=/tmp/dwatch-test bs=1m count=50
jail               jail -c name=dwatchtest persist ip4.addr=127.0.0.2
                   then jail -r dwatchtest
dtmalloc-top       let it sit a few ticks, watch the catalog refresh
coredump           ulimit -c 0; send SIGSEGV to a throwaway helper

I did not get a live dtrace -e pass on the machine where I wrote this
(the dtrace device wasn't available there). Harbormaster build passed;
compile + a quick smoke on a box with dtrace loaded is the main thing
I'd like a reviewer to confirm.

Diff Detail

Repository
rG FreeBSD src repository
Lint
Lint Skipped
Unit
Tests Skipped
Build Status
Buildable 74787
Build 71670: arc lint + arc unit

Event Timeline

Amended the squashed commit message to fold in the second batch (hang, jail, dtmalloc, mib, sched-latency, io-slow) and to note taint scope: no kernel changes, libexec profiles plus priv.d only. Tip commit is now 176b3b389fde (tree unchanged from c029c0fb59f4).

cddl/lib/libdtrace/priv.d
9 ↗(On Diff #181492)

How is it mechanically generated? Can you include the script, or better, generate this script as part of the build, akin to lib/libsysdecode/mktables?

(I know we have similar hard-coded lists for errno, signals, etc., but we don't add new ones very often and we should really be generating those lists too.)

dteske edited the summary of this revision. (Show Details)

Add mkpriv update Makefile to produce priv.d

markj added inline comments.
cddl/lib/libdtrace/mkpriv
91

I'd extend the comment to include a path to this script, just so it's a bit easier to find.

This revision is now accepted and ready to land.Mon, Jul 13, 1:57 PM
This revision now requires review to proceed.Mon, Jul 13, 9:45 PM