⬢ DragonFlyBSD Kernel Audit
DF-3715 / run.log
← back to finding ↓ download raw
# Session 1 (pre-reset guest instance, fresh boot after vm.sh reset with-src):
#   build:  cc -O2 ... -c callout_replica.c ; ld -r -o callout_replica.ko      (build.log has full output)
#   load:   kldload /root/kmod/callout_replica.ko  -> KLD_OK
#           sysctl kern.emreplica.arm -> 0       (module live)
#
# Test 1 - arm both replica callouts (gc = try-based em_txgc_timer shape,
#          blk = blocking em_timer shape):
root# sysctl kern.emreplica.arm=1
kern.emreplica.arm: 0 -> 0
# dmesg: callout_replica: loaded (hz=100)
#        replica: armed (gc every tick, blk every hz/4)

# Test 2 - em_stop vs try-based gc timer (negative control for the
#          DF-3669/DF-3681 "re-arm survives callout_stop" premise):
root# sysctl kern.emreplica.stop_gc=1
kern.emreplica.stop_gc: 0 -> 0
GC_TEST_RC=0
# dmesg: replica[gc]: stop while INPROG (fired=300 ran=300)
#        replica[gc]: callout_stop returned, pending=0
#        replica[gc]: RESULT pending=0 (0 == re-arm did NOT survive callout_stop;
#                     DF-3681 premise false for try-based handler here)
# -> on this kern_timeout.c, callout_stop() unloads a racing self-re-arm:
#    the em_txgc_timer cannot survive em_stop().

# Test 3 - em_stop vs blocking timer (em_timer shape): AB-BA
root# (sysctl kern.emreplica.stop_blk=1 > /root/blk.log 2>&1) &
# ... 12+ seconds later, from a second session:
root# cat /root/blk.log
kern.emreplica.stop_blk: 0
# dmesg (final lines - note the absent "callout_stop returned (NO deadlock)"):
#   replica[blk]: handler BLOCKED on our serializer (fired=91 ran=90) - entering callout_stop()
#   replica[blk]: IF THIS IS THE LAST replica LINE, AB-BA DEADLOCK IS PROVEN
#
# wedged-thread evidence (second session, ps):
root# ps -o pid,stat,wchan,command -ax | grep stop_blk
  1051 D3     costp    sysctl kern.emreplica.stop_blk=1
#
# ^ D-state (uninterruptible) with wait-channel "costp" == the ssleep label
# inside _callout_cancel_or_stop() sys/kern/kern_timeout.c:923 - the caller
# is permanently stuck inside callout_stop() holding the serializer, while
# the replica handler (softclock thread) is blocked in lwkt_serialize_enter()
# on that very serializer.  The sysctl thread never returns; the softclock
# thread of the armed CPU never processes another callout.  Guest was reset
# afterwards (vm.sh reset with-src).

# ---- RAW CAPTURES (pre-reset instance, session output) ----
# dmesg | grep replica | tail -4:
callout_replica: loaded (hz=100)
replica: armed (gc every tick, blk every hz/4)
replica[gc]: stop while INPROG (fired=300 ran=300)
replica[gc]: callout_stop returned, pending=0
replica[gc]: RESULT pending=0 (0 == re-arm did NOT survive callout_stop; DF-3681 premise false for try-based handler here)
replica[blk]: handler BLOCKED on our serializer (fired=91 ran=90) - entering callout_stop()
replica[blk]: IF THIS IS THE LAST replica LINE, AB-BA DEADLOCK IS PROVEN
# ^ "replica[blk]: callout_stop returned (NO deadlock)" NEVER printed.

# ps -o pid,stat,wchan,command -ax | grep stop_blk (second session, guest wedged):
  1051 D3     costp    sysctl kern.emreplica.stop_blk=1
# ^ D3 = uninterruptible; wchan "costp" = ssleep label in
#   sys/kern/kern_timeout.c:923 inside _callout_cancel_or_stop() -> the
#   caller is permanently stuck INSIDE callout_stop() holding the replica
#   serializer while the em_timer-shaped callback is blocked acquiring it.

# softclock threads at capture time (one of them is the wedged callback):
root  -1  0.0 0.0 0 0 ??  B0..B5   (softclock 0..5 present, 6 cpus)