https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=298534
Bug ID: 298534
Summary: nfsd: ERELOOKUP retry leaks srvstartcnt, so nfsstat -d
"ql" grows forever and "%b" sticks at 100
Product: Base System
Version: 15.1-RELEASE
Hardware: Any
OS: Any
Status: New
Severity: Affects Some People
Priority: ---
Component: kern
Assignee: [email protected]
Reporter: [email protected]
sys/fs/nfsserver/nfs_nfsdsocket.c pairs nfsrvd_statstart() with
nfsrvd_statend() around every operation. The ERELOOKUP retry paths added in
774a368 ("nfsd: fix NFS server for ERELOOKUP", D27875) break that pairing:
both "goto tryagain" jumps happen after statstart() and before statend(), and
the retried attempt calls statstart() again. Each retry therefore increments
srvstartcnt (and srvrpccnt[op]) twice but srvdonecnt once.
NFSv3 path, nfsrvd_dorpc():
nfsrvd_statstart(nfsv3to4op[nd->nd_procnum], &start_time);
... error == 0 && nd->nd_repstat == ERELOOKUP -> goto tryagain; /* no
statend */
nfsrvd_statend(...);
NFSv4 path, nfsrvd_compound():
nfsrvd_statstart(op, &start_time); statsinprog = 1;
... nd->nd_repstat == ERELOOKUP -> goto tryagain; /* no
statend */
if (statsinprog != 0) nfsrvd_statend(...);
Both are unchanged in main as of 2026-09 (only the NFSD_VNET -> VNET macro
rename touched those lines).
Two user-visible consequences, because nfsrvd_statstart() only resets
busyfrom when srvstartcnt == srvdonecnt:
1. The gap srvstartcnt - srvdonecnt, which nfsstat(1) reports as "ql" in
-d mode, becomes a monotonically growing count of retries rather than the
in-flight queue length. On a busy server it never returns to zero.
2. Once the gap is non-zero, busytime accumulates every interval between
consecutive statend() calls, i.e. all wall-clock time while any traffic
flows. nfsstat -d "%b" then reads 100 as long as there is at least one
op per sample, regardless of actual load.
srvops[], srvbytes[] and srvduration[] are only updated in statend(), so
per-op counts, throughput and latency remain correct; srvrpccnt[op] is
over-counted by one per retry.
How to reproduce:
On a FreeBSD 13.0 or later NFS server exporting ZFS (or UFS after r367672)
with clients that create/remove/rename concurrently with lookups in the same
directories, run:
nfsstat -d -w 1
Watch "ql": it steps up by one each time an operation hits ERELOOKUP and
never steps back down once the server is idle. Once ql is non-zero, "%b"
reads ~100 whenever any request is being served.
Observed on 15.1-RELEASE-p1 serving a ZFS pool to ~11 NFSv4 clients (mostly
GetAttr/Lookup/Access, ~15 namespace-changing ops/s), 48 days after boot:
# nfsstat -d -w 1
[===== Read =====] [===== Write ====] [=========== Total ============]
KB/t tps MB/s KB/t tps MB/s KB/t tps MB/s ms ql %b
114.60 2108 235.90 38.02 6 0.22 22.33 10828 236.13 0.22 3784 100
106.38 2005 208.25 2.89 9 0.03 18.24 11692 208.28 0.39 3793 100
102.97 2132 214.38 4.87 4 0.02 16.69 13156 214.40 0.45 3782 100
108.32 1563 165.33 12.02 15 0.18 17.16 9878 165.50 0.33 3782 100
"ql" cannot be a real queue: it never drops below ~3,780, while mean latency
is well under a millisecond. Sampling srvstartcnt - srvdonecnt once a minute
shows it climbing from 0 at boot to ~3,780 over 48 days, 30-80 per day,
tracking the rate of concurrent rename/remove activity. A second, nearly
idle, 15.1-RELEASE-p3 server shows ql 0 and a sane %b. Third-party consumers
of nfsstatsv1 (e.g. net-mgmt/nfs-exporter, which publishes
nfs_nfsd_start_count, nfs_nfsd_done_count and nfs_nfsd_busytime) show the
same drift.
Suggested fix:
Close the accounting before retrying, in both paths. For nfsrvd_dorpc():
if (error == 0 && nd->nd_repstat == ERELOOKUP) {
+ nfsrvd_statend(nfsv3to4op[nd->nd_procnum], /*bytes*/ 0,
+ /*now*/ NULL, /*then*/ &start_time);
/* Roll back to the beginning of the RPC request arguments. */
...
goto tryagain;
}
For nfsrvd_compound():
if (nd->nd_repstat == ERELOOKUP) {
+ if (statsinprog != 0) {
+ nfsrvd_statend(op, /*bytes*/ 0, /*now*/ NULL,
+ /*then*/ &start_time);
+ statsinprog = 0;
+ }
/* Roll back to the beginning of the operation arguments. */
...
goto tryagain;
}
This counts a retried operation as two completed attempts (matching the two
starts), keeps ql meaningful and lets busyfrom reset. An alternative that
keeps srvrpccnt at one per retried op would be to decrement srvstartcnt and
srvrpccnt[op] under nfsrvd_statmtx before the retry instead.
--
You are receiving this mail because:
You are the assignee for the bug.
