On Wed, Apr 13, 2022 at 02:16:51PM +0200, Sebastien Marie wrote:
> Here a new diff which will record a bit more information.
>
> It keep track of the last 10 v_usecount changes with:
> - pid and ps_comm
> - usecount value (before and after)
> - stacktrace
[-- MARK -- Thu Apr 14 17:30:00 2022]
uvn_io: start: 0x2928ca30, type VREG, use 0, write 0, hold 0, flags (VXLOCK)
tag VT_UFS, ino 550996, on dev 0, 10 flags 0x100, effnlink 1, nlink 1
mode 0100660, owner 21, group 21, size 93596
==> vnode_history_print 0x2928ca30, next=1
[0] make[97726] usecount 1>0
#0 alisize+0x30
#1 0xe9b99df4
#2 vput+0x58
#3 dofstatat+0xb0
#4 sys_stat+0x30
#5 trap+0x950
#6 trapagain+0x4
[3] nm[10151] usecount 2>1
#0 uvm_mapent_mkfree+0x18c
#1 0xd522fffc
#2 vrele+0x5c
#3 uvn_detach+0x154
#4 uvm_unmap_detach+0x1a4
#5 sys_munmap+0x124
#6 trap+0x950
#7 trapagain+0x4
[4] nm[10151] usecount 1>0
#0 pool_do_put+0x50
#1 mtx_enter_try+0x5c
#2 vput+0x58
#3 vn_closefile+0xc4
#4 fdrop+0xb4
#5 closef+0xe0
#6 fdrelease+0xf8
#7 sys_close+0x80
#8 trap+0x950
#9 trapagain+0x4
[6] ar[49145] usecount 1>2
#0 pool_get+0x128
[8] ar[49145] usecount 1>0
#0 uvm_mapent_mkfree+0x18c
#1 0x9821fffc
#2 vrele+0x5c
#3 uvn_detach+0x154
#4 uvm_unmap_detach+0x1a4
#5 sys_munmap+0x124
#6 trap+0x950
#7 trapagain+0x4
[-- MARK -- Thu Apr 14 17:35:00 2022]
...
[-- MARK -- Thu Apr 14 18:05:00 2022]
uvn_io: start: 0x23e6b910, type VREG, use 0, write 0, hold 0, flags
(VBIOONFREELIST)
tag VT_UFS, ino 703119, on dev 0, 10 flags 0x100, effnlink 1, nlink 1
mode 0100660, owner 21, group 21, size 13647873
==> vnode_history_print 0x23e6b910, next=5
[3] c++[68540] usecount 2>1
#0 0x625703e0
[4] reaper[31684] usecount 1>0
#0 splx+0x30
#1 0xfffffffc
#2 vrele+0x5c
#3 uvn_detach+0x154
#4 uvm_unmap_detach+0x1a4
#5 uvm_map_teardown+0x184
#6 uvmspace_free+0x60
#7 uvm_exit+0x30
#8 reaper+0x138
#9 fork_trampoline+0x14
vn_lock: v_usecount == 0: 0x23e6b910, type VREG, use 0, write 0, hold 0, flags
(VBIOONFREELIST)
tag VT_UFS, ino 703119, on dev 0, 10 flags 0x100, effnlink 1, nlink 1
mode 0100660, owner 21, group 21, size 13647873
==> vnode_history_print 0x23e6b910, next=5
[3] c++[68540] usecount 2>1
#0 0x625703e0
[4] reaper[31684] usecount 1>0
#0 splx+0x30
#1 0xfffffffc
#2 vrele+0x5c
#3 uvn_detach+0x154
#4 uvm_unmap_detach+0x1a4
#5 uvm_map_teardown+0x184
#6 uvmspace_free+0x60
#7 uvm_exit+0x30
#8 reaper+0x138
#9 fork_trampoline+0x14
panic: vn_lock: v_usecount == 0
Stopped at db_enter+0x24: lwz r11,12(r1)
TID PID UID PRFLAGS PFLAGS CPU COMMAND
433418 19000 21 0x2 0 0 c++
*232867 36343 0 0x14000 0x200 1K pagedaemon
db_enter() at db_enter+0x20
panic(9434f4) at panic+0x158
vn_lock(49535400,202000) at vn_lock+0x1c4
uvn_io(5db64f85,a994c4,a979f4,ffffffff,e4010000) at uvn_io+0x254
uvn_put(fec3fe2c,e7ebbdd4,23ca9af0,40e0880) at uvn_put+0x64
uvm_pager_put(0,0,e7ebbd70,32c0c0,2000000,80000000,0) at uvm_pager_put+0x15c
uvmpd_scan_inactive(0) at uvmpd_scan_inactive+0x224
uvmpd_scan() at uvmpd_scan+0x158
uvm_pageout(5d4841c9) at uvm_pageout+0x398
fork_trampoline() at fork_trampoline+0x14
end trace frame: 0x0, count: 5
https://www.openbsd.org/ddb.html describes the minimum info required in bug
reports. Insufficient info makes it difficult to find and fix bugs.
ddb{1}> show panic
*cpu1: vn_lock: v_usecount == 0
ddb{1}> trace
db_enter() at db_enter+0x20
panic(9434f4) at panic+0x158
vn_lock(49535400,202000) at vn_lock+0x1c4
uvn_io(5db64f85,a994c4,a979f4,ffffffff,e4010000) at uvn_io+0x254
uvn_put(fec3fe2c,e7ebbdd4,23ca9af0,40e0880) at uvn_put+0x64
uvm_pager_put(0,0,e7ebbd70,32c0c0,2000000,80000000,0) at uvm_pager_put+0x15c
uvmpd_scan_inactive(0) at uvmpd_scan_inactive+0x224
uvmpd_scan() at uvmpd_scan+0x158
uvm_pageout(5d4841c9) at uvm_pageout+0x398
fork_trampoline() at fork_trampoline+0x14
end trace frame: 0x0, count: -10
ddb{1}> show register
r0 0x8552f8 panic+0x15c
r1 0xe7ebbb60
r2 0
r3 0xafcc00 cpu_info+0x4c0
r4 0xb00000 uvm_small_amap_pool+0x130
r5 0x1
r6 0
r7 0xe7bb9000
r8 0
r9 0x91ae69 digits
r10 0x14
r11 0xb9c58763
r12 0x972ab42e
r13 0
r14 0xaf51b8 bcstats
r15 0xa979d0 uvmexp
r16 0
r17 0
r18 0
r19 0x202000 rtable_match+0x4c
r20 0x1000 tlbdsmsize+0xf18
r21 0x1000 tlbdsmsize+0xf18
r22 0xa80294 netlock
r23 0xe4010000
r24 0x23ca9b08
r25 0x23ca9b0c
r26 0x925186 digits+0xa31d
r27 0
r28 0
r29 0xafcec0 cpu_info+0x780
r30 0x9434f4 cy_pio_rec+0x10c93
r31 0xa97afc uvmexp+0x12c
lr 0x465b64 db_enter+0x24
cr 0x48228204
xer 0x20000000
ctr 0x84331c openpic_splx
iar 0x465b64 db_enter+0x24
msr 0x9032 tlbdsmsize+0x8f4a
dar 0
dsisr 0
db_enter+0x24: lwz r11,12(r1)
ddb{1}> ps
PID TID PPID UID S FLAGS WAIT COMMAND
19000 433418 88497 21 7 0x2 c++
88497 403151 58565 21 3 0x10008a sigsusp sh
41513 242275 9837 21 2 0x2 c++
9837 71908 58565 21 3 0x10008a sigsusp sh
58565 163952 54207 21 3 0x10008a sigsusp make
54207 76575 55963 21 3 0x10008a sigsusp sh
55963 491542 28020 21 3 0x10008a sigsusp make
28020 11887215 21 3 0x10008a sigsusp make
17215 246222 89415 21 3 0x10008a sigsusp sh
89415 114664 17720 21 3 0x10008a sigsusp make
17720 164665 66695 0 3 0x10008a sigsusp sh
66695 16970 75998 0 3 0x10008a sigsusp make
75998 377562 93606 0 3 0x10008a sigsusp make
93606 189705 64097 0 3 0x10008a sigsusp sh
64097 134632 17259 0 3 0x82 piperd perl
17259 145120 30986 0 3 0x10008a sigsusp ksh
30986 428793 43374 0 3 0x9a kqread sshd
62653 378789 1 0 3 0x100083 ttyin getty
72583 62696 1 0 3 0x100098 kqread cron
1933 419760 1 99 3 0x1100090 kqread sndiod
73776 124138 1 110 3 0x100090 kqread sndiod
7481 214185 45433 95 3 0x1100092 kqread smtpd
6611 409063 45433 103 3 0x1100092 kqread smtpd
16731 262914 45433 95 3 0x1100092 kqread smtpd
40301 71250 45433 95 3 0x100092 kqread smtpd
96109 124474 45433 95 3 0x1100092 kqread smtpd
13936 404650 45433 95 3 0x1100092 kqread smtpd
45433 263236 1 0 3 0x100080 kqread smtpd
343 120441 1 0 3 0x100080 kqread snmpd
87257 308298 1 91 3 0x1000092 kqread snmpd
43374 12041 1 0 3 0x88 kqread sshd
36767 275688 0 0 3 0x14280 nfsidl nfsio
23523 322381 0 0 3 0x14280 nfsidl nfsio
18830 59893 0 0 3 0x14280 nfsidl nfsio
69933 327304 0 0 3 0x14280 nfsidl nfsio
76335 497295 1 0 3 0x100080 kqread ntpd
49727 34189 86240 83 3 0x100092 kqread ntpd
86240 183312 1 83 3 0x1100092 kqread ntpd
80059 107446 93928 74 3 0x1100092 bpf pflogd
93928 203794 1 0 3 0x80 netio pflogd
6842 97383 70269 73 3 0x1100090 kqread syslogd
70269 299053 1 0 3 0x100082 netio syslogd
96628 496905 1 0 3 0x100080 kqread resolvd
24421 272632 88548 77 3 0x100092 kqread dhcpleased
593 201390 88548 77 3 0x100092 kqread dhcpleased
88548 261115 1 0 3 0x80 kqread dhcpleased
6816 477914 60015 115 3 0x100092 kqread slaacd
60023 386633 60015 115 3 0x100092 kqread slaacd
60015 89490 1 0 3 0x100080 kqread slaacd
94936 82285 0 0 3 0x14200 bored smr
24751 194620 0 0 3 0x40014200 idle1
76151 100547 0 0 2 0x14200 zerothread
9389 345055 0 0 3 0x14200 aiodoned aiodoned
72624 434131 0 0 3 0x14200 syncer update
60402 516935 0 0 3 0x14200 cleaner cleaner
31684 508907 0 0 3 0x14200 reaper reaper
*36343 232867 0 0 7 0x14200 pagedaemon
96816 67592 0 0 3 0x14200 usbtsk usbtask
77492 19911 0 0 3 0x14200 usbatsk usbatsk
36069 22766 0 0 3 0x14200 bored sensors
36770 121581 0 0 2 0x14200 softnet
44639 205909 0 0 3 0x14200 bored systqmp
56468 113797 0 0 3 0x14200 bored systq
91597 251663 0 0 3 0x40014200 bored softclock
48713 469657 0 0 3 0x40014200 idle0
1 516722 0 0 3 0x82 wait init
0 0 -1 0 3 0x10200 scheduler swapper
ddb{1}> x/s version
version: OpenBSD 7.1-current (GENERIC.MP) #0: Wed Apr 13 15:47:33 CEST
2022\012
r...@ot26.obsd-lab.genua.de:/usr/src/sys/arch/macppc/compile/GENERIC.MP\012
ddb{1}> show uvm
Current UVM status:
pagesize=4096 (0x1000), pagemask=0xfff, pageshift=12
500889 VM pages: 174484 active, 178200 inactive, 1 wired, 39224 free (0 zero)
min 10% (25) anon, 10% (25) vnode, 5% (12) vtext
freemin=16696, free-target=22261, inactive-target=125065, wired-max=166963
faults=969270667, traps=0, intrs=1106855, ctxswitch=15212500 fpuswitch=3248421
softint=8160299, syscalls=1385935235, kmapent=8
fault counts:
noram=0, noanon=0, noamap=0, pgwait=0, pgrele=0
ok relocks(total)=633576(636470), anget(retries)=781401497(0),
amapcopy=60231123
neighbor anon/obj pg=68714269/141374437, gets(lock/unlock)=49238431/637452
cases: anon=779642530, anoncow=1758967, obj=42501171, prcopy=6733384,
przero=138634615
daemon and swap counts:
woke=5, revs=1, scans=22738, obscans=22518, anscans=0
busy=0, freed=22517, reactivate=220, deactivate=0
pageouts=1, pending=0, nswget=0
nswapdev=1
swpages=589823, swpginuse=0, swpgonly=0 paging=0
kernel pointers:
objs(kern)=0xb03480
ddb{1}> show vnode /f 0x23e6b910
0x23e6b910 tag UFS(1) type VREG(1) mount 0xe040f800 typedata 0x0
data 0x23d51dc0 usecount 0 writecount 0 holdcnt 0 numoutput 0
flag 0x0 lflag 0x0 bioflag 0x4
clean bufs:
dirty bufs:
==> vnode_history_print 0x23e6b910, next=5
[3] c++[68540] usecount 2>1
#0 0x625703e0
[4] reaper[31684] usecount 1>0
#0 splx+0x30
#1 0xfffffffc
#2 vrele+0x5c
#3 uvn_detach+0x154
#4 uvm_unmap_detach+0x1a4
#5 uvm_map_teardown+0x184
#6 uvmspace_free+0x60
#7 uvm_exit+0x30
#8 reaper+0x138
#9 fork_trampoline+0x14
ddb{1}> show mount 0xe040f800
flags 201818<NOSUID,NODEV,WXALLOWED,LOCAL,SWAPPABLE>
vnodecovered 0x311750a0 syncer 0x31175250 data 0xe024fe00
vfsconf: ops 0xa53e84 name "ffs" num 1 ref 9 flags 0x201000
statvfs cache: bsize 800 iosize 4000
blocks 3094879 free 3092871 avail 2938128
files 805502 ffiles 803496 favail 803496
f_fsidx {0xa, 0x4069424e} owner 0 ctime 0x6256d525
syncwrites 392685 asyncwrites = 188844
syncreads 3825549 asyncreads = 0
fstype "ffs" mnton "/usr/obj" mntfrom "/dev/wd0k" mntspec "6102496318219727.k"
locked vnodes:
Unfortunately the address in the trace is not correct this time.
vn_lock(49535400,202000) at vn_lock+0x1c4
0x49535400 is not a vnode.
