uvm_fault, rebooting while nfs stalled

Martin Pieuchot

2017-06-02 06:39:04 UTC

Post by Stuart Henderson
I rebooted a couple of machines in the "wrong" order, NFS server
first, followed by clients.
On one of the clients I then mistyped a command and it tried to
search for it in an NFS directory in the path, so it was stalled
pending the NFS server coming back.
Then in another window I issued a reboot and hit this.

It's a known race. I managed to trigger it while working on the
NET_LOCK(). Problem is that fixing it leads to another panic because
NFS nodes aren't locked.

Post by Stuart Henderson
Self-built i386 MP kernel from head of the tree as of about
10 hours ago. (Not that it's likely to be anything recent,
it's not something I'd do very often).
login: [-- MARK -- Thu Jun 1 06:00:00 2017]
[-- MARK -- Thu Jun 1 07:00:00 2017 .. Thu Jun 1 15:00:00 2017 -- MARK --]
syncing disks... uvm_fault(0xd0bcffc0, 0xefff1000, 0, 1) -> e
kernel: page fault trap, code=0
Stopped at solock+0xc: movl 0x4(%eax),%eax
ps
PID TID PPID UID S FLAGS WAIT COMMAND
12003 212609 1 0 2 0x3 reboot
*28175 224927 1 0 7 0x102037 doas
10627 504005 0 0 3 0x14280 nfsidl nfsio
24110 388618 0 0 3 0x14280 nfsidl nfsio
57979 18934 0 0 3 0x14280 nfsidl nfsio
47178 289785 0 0 3 0x14280 nfsidl nfsio
38998 74857 0 0 3 0x14280 nfsidl nfsio
4068 387681 0 0 3 0x14280 nfsidl nfsio
18772 220491 0 0 3 0x14280 nfsidl nfsio
17506 446748 0 0 3 0x14280 nfsidl nfsio
68328 451968 0 0 2 0x14200 zerothread
17973 87009 0 0 3 0x14200 aiodoned aiodoned
90679 434708 0 0 3 0x14200 syncer update
50941 190454 0 0 3 0x14200 cleaner cleaner
84887 320266 0 0 3 0x14200 reaper reaper
40106 400998 0 0 3 0x14200 pgdaemon pagedaemon
64018 107467 0 0 3 0x14200 bored crynlk
14749 448513 0 0 3 0x14200 bored crypto
55284 395100 0 0 3 0x14200 pftm pfpurge
97314 97574 0 0 3 0x14200 usbtsk usbtask
40659 442434 0 0 3 0x14200 usbatsk usbatsk
73875 175284 0 0 3 0x14200 bored sensors
51157 352523 0 0 3 0x40014200 acpi0 acpi0
42890 369596 0 0 7 0x40014200 idle3
31561 183664 0 0 7 0x40014200 idle2
36877 114398 0 0 7 0x40014200 idle1
20858 196756 0 0 3 0x14200 bored softnet
74600 291067 0 0 3 0x14200 bored systqmp
62533 360102 0 0 3 0x14200 bored systq
42790 105222 0 0 3 0x40014200 bored softclock
50699 456949 0 0 3 0x40014200 idle0
75000 223342 0 0 3 0x14200 bored sbar
40611 471609 0 0 3 0x14200 kmalloc kmthread
1 296897 0 0 3 0x82 wait init
0 0 -1 0 3 0x10200 scheduler swapper
ddb{0}> tr
solock(d684ec7c,1,0,d08ac619,1000) at solock+0xc
soreceive(d684ec7c,0,d4c768a8,d4c76918,0) at soreceive+0xc3
nfs_receive(fae0a008,d4c76938,d4c76918,fae0a008,fae0a008) at nfs_receive+0xb9
nfs_reply(fae0a008,daa14b00,daa01600,fae0a008,d6a09010) at nfs_reply+0x4e
nfs_request(d65be994,3,d4c76ab0,4,d0b14e54) at nfs_request+0x384
nfs_lookup(d4c76afc,0,d65be994,d4c76e90,d4c76eb8) at nfs_lookup+0x2fe
VOP_LOOKUP(d65be994,d4c76e90,d4c76eb8,d4c76b44,d0697989) at VOP_LOOKUP+0x39
vfs_lookup(d4c76e74,d4c76e74,d4c26000,d4c76e98,d0bd06c0) at vfs_lookup+0x2cc
namei(d4c76e74,0,d4c76c0c,d0208a52,d0bd06c0) at namei+0x310
check_exec(d6a09010,d4c76cb8,1,0,ffffff9c) at check_exec+0x3c
sys_execve(d6a09010,d4c76f54,d4c76f7c,0,d4c76fa8) at sys_execve+0x1aa
syscall() at syscall+0x250
--- syscall (number -2058191488) ---
ddb{0}> sh reg
ds 0x10
es 0x10
fs 0x20 clean_idt
gs 0
edi 0
esi 0xd684ec7c end+0x5bb3c7c
ebp 0xd4c767dc end+0x3fdb7dc
ebx 0xd684eccc end+0x5bb3ccc
edx 0x1
ecx 0
eax 0xefff1133
eip 0xd0364e5c solock+0xc
cs 0x8
eflags 0x10282 mp_startup+0x25b
esp 0xd4c767c4 end+0x3fdb7c4
ss 0x10
solock+0xc: movl 0x4(%eax),%eax
ddb{0}> mach ddbcpu 1
Stopped at db_enter+0x7: leave
ddb{1}> tr
db_enter(d6a6b800,fb315224,12b,f936febc,5bb71) at db_enter+0x7
i386_ipi_handler(0,d6a60020,d6a10000,f9360010,d0350010) at i386_ipi_handler+0x5
f
Xintripi() at Xintripi+0x49
--- interrupt ---
acpicpu_idle(d07eb6ca,d6a6b834,d6a6b800,d07eb5c0,f936ff90) at acpicpu_idle+0x22
2
cpu_idle_cycle(d6a6b800) at cpu_idle_cycle+0xc
ddb{1}> mach ddbcpu 2
Stopped at db_enter+0x7: leave
ddb{2}> tr
db_enter(d6a6d000,fb315224,12b,f9371ebc,5bb71) at db_enter+0x7
i386_ipi_handler(0,d6a60020,d6a10000,f9370010,d0350010) at i386_ipi_handler+0x5
f
Xintripi() at Xintripi+0x49
--- interrupt ---
acpicpu_idle(d07eb6ca,d6a6d034,d6a6d000,d07eb5c0,f9371f90) at acpicpu_idle+0x22
2
cpu_idle_cycle(d6a6d000) at cpu_idle_cycle+0xc
ddb{2}> mach ddbcpu 3
Stopped at db_enter+0x7: leave
ddb{3}> tr
db_enter(d6a6d800,fb315224,12b,f9373ebc,5bb71) at db_enter+0x7
i386_ipi_handler(0,d6a60020,d6a10000,f9370010,d0350010) at i386_ipi_handler+0x5
f
Xintripi() at Xintripi+0x49
--- interrupt ---
acpicpu_idle(d07eb6ca,d6a6d834,d6a6d800,d07eb5c0,f9373f90) at acpicpu_idle+0x22
2
cpu_idle_cycle(d6a6d800) at cpu_idle_cycle+0xc
ddb{3}> sh uvmexp
pagesize=4096 (0x1000), pagemask=0xfff, pageshift=12
760702 VM pages: 391 active, 5272 inactive, 48 wired, 719435 free (83399 zero
)
min 10% (25) anon, 10% (25) vnode, 5% (12) vtext
pages 0 anon, 0 vnode, 0 vtext
freemin=25356, free-target=33808, inactive-target=72378, wired-max=253567
faults=298901797, traps=300653176, intrs=4072834, ctxswitch=22129797 fpuswitc
h=233909
softint=6205583, syscalls=221497670, kmapent=27
noram=0, noanon=0, noamap=0, pgwait=0, pgrele=0
ok relocks(total)=272855(272855), anget(retries)=100505411(0), amapcopy=110
454654
neighbor anon/obj pg=14754221/170190292, gets(lock/unlock)=49246566/272855
cases: anon=84294682, anoncow=16210729, obj=43932813, prcopy=5313753, przer
o=149149793
woke=5, revs=1, scans=76428, obscans=76428, anscans=0
busy=0, freed=76428, reactivate=0, deactivate=0
pageouts=0, pending=0, nswget=0
nswapdev=1, nanon=0, nanonneeded=0 nfreeanon=0
swpages=844100, swpginuse=0, swpgonly=0 paging=0
objs(kern)=0xd0bb6f40
ddb{3}> sh bcst
numbufs 5146 busymapped 1, delwri 0
kvaslots 1216 avail kva slots 1215
bufpages 21673, dmapages 21673, dirtypages 0
pendingreads 0, pendingwrites 0
highflips 0, highflops 0, dmaflips 0