DF-3982 / run.log
=================================================================
DF-3982 mechanism verification - DragonFly 6.5-DEVELOPMENT guest
callout_stop() from the sbp_recv1 state (crit section / interrupt
path) BLOCKS in 'costp' while the target callout is INPROG, and the
wedged softclock thread cascades to unrelated tsleep timeouts.
=================================================================
RUN 1 (15s busy-wait callback, stop arrived after INPROG had cleared -
negative-control datapoint: stop of a non-INPROG callout returns
in 9 ms):
sbpprep[B]: armed 1-tick mgm_ocb_timeout replica
sbpprep[B]: mgm_timeout replica callback STARTED (INPROG set, cpu=2)
sbpprep[B]: mgm_timeout replica callback DONE (INPROG cleared after 15160238 usec)
sbpprep[B]: callout_stop() ENTERED inside crit section (sbp.c:1600 state) at 1789636881.479961
sbpprep[B]: callout_stop() RETURNED after 9 ms (callback body is 5000 ms) at 1789636881.489438
[the busy-wait body froze userland scheduling on the callback CPU, so the
stopper landed late - replaced by the no-timeout-sleep design of RUN 2]
RUN 2 (callback blocks in 'bcb' until released - the sbp_mgm_timeout shape
whose body completes only when the bus answers):
# arm, then background a fully-detached stopb (survives the ssh session):
$ sysctl kern.sbpprep_armb=1
kern.sbpprep_armb: 0 -> 0
$ (sysctl -n kern.sbpprep_stopb=1 >/dev/null 2>&1 </dev/null &); echo DETACHED
DETACHED
# 3 s later, LIVE CAPTURE:
$ ps -o pid,stat,wchan,comm -ax | grep sysctl | grep -v grep
1237 D5 costp sysctl <-- callout_stop() caller asleep INSIDE crit (D-state)
$ ps -axH -o pid,tdpri,stat,wchan,comm | grep softclock
-1 12 B1 - softclock 1
-1 12 B2 bcb softclock 2 <-- mgm-timeout replica callback INPROG, blocked in body
-1 12 B3 - softclock 3
-1 12 B4 - softclock 4
-1 12 B5 - softclock 5
-1 12 B0 - softclock 0
# release attempt from a third thread (wakeb) with a 3 s tsleep before the
# wakeup - CASCADE: that tsleep's own timeout callout lands on the wedged
# cpu2 wheel and never fires:
$ sysctl -n kern.sbpprep_wakeb=1
sbpprep[B]: callout_stop() ENTERED inside crit section (sbp.c:1600 state) at 1789637158.530768
sbpprep[B]: wakeb: releasing callback in 3s (stopper has been in 'costp' all this time)
$ ps -o pid,stat,wchan,comm -ax | grep sysctl | grep -v grep
1237 D5 costp sysctl <-- stopper, still blocked (crit held)
1256 D2 wkdelay sysctl <-- third thread: tsleep timeout starved by wedged softclock
INTERPRETATION (mechanism PROVEN on the shipped kernel):
1. kern_timeout.c callout_stop() (= _callout_cancel_or_stop(sync=1),
kern_timeout.c:1091) sleeps in 'costp' (kern_timeout.c:923 ssleep) for
the ENTIRE duration of an INPROG callback - even when the caller holds
a critical section. sbp.c:1600/2590/2705 run in exactly that state
(fwohci hard-IRQ: fwohcivar.h:37 FWOHCI_TASKQUEUE=0 -> fwohci_intr
-> fwohci_intr_body -> fwohci_arcv crit_enter fwohci.c:2688 -> fw_rcv
-> fw_xfer_done firewire.c:991 -> sbp_recv crit_enter sbp.c:1823).
In the real driver the blocked context is the fwohci interrupt thread:
the FireWire IRQ stalls for as long as sbp_mgm_timeout takes (its body
does kprintf + sbp_reset_start -> fw_asyreq, allocation-dependent).
2. Cascade: the softclock thread wedged INPROG in the callback starves
every tsleep-with-timeout whose callout shares that CPU (observed live:
wkdelay) - i.e. an unbounded set of unrelated kernel sleeps.
Guest was wedged by design at the end of RUN 2 -> vm.sh reset with-src.