On Fri, Apr 08, 2022 at 11:37:43AM +0200, Sebastien Marie wrote:
> and I hope to infer possible problematic codepath with stacktrace history.
Here we go
[-- MARK -- Sat Apr 9 14:10:00 2022]
uvn_io: start: 0xe85497a8, type VREG, use 0, write 0, hold 0, flags
(VBIOONFREELIST)
tag VT_UFS, ino 261391, on dev 0, 10 flags 0x100, effnlink 1, nlink 1
mode 0100660, owner 21, group 21, size 13647873
==> vnode_history_print 0xe85497a8, next=6
[0]
#0 ufs_close+0x30
#1 VOP_CLOSE+0x60
#2 vn_closefile+0xc4
#3 fdrop+0xb4
#4 closef+0xe0
#5 fdrelease+0xf8
#6 sys_close+0x80
#7 trap+0x950
#8 trapagain+0x4
[1]
#0 mtx_leave+0x90
#1 vget+0x5c
#2 cache_lookup+0x1ec
#3 ufs_lookup+0x130
#4 VOP_LOOKUP+0x44
#5 vfs_lookup+0x4a8
#6 namei+0x2a8
#7 vn_open+0xc0
#8 doopenat+0x1b4
#9 sys_open+0x34
#10 trap+0x950
#11 trapagain+0x4
[2]
#0 mtx_leave+0x90
#1 vget+0x5c
#2 cache_lookup+0x1ec
#3 ufs_lookup+0x130
#4 VOP_LOOKUP+0x44
#5 vfs_lookup+0x4a8
#6 namei+0x2a8
#7 sys___realpath+0x18c
#8 trap+0x950
#9 trapagain+0x4
[3]
#0 0x97b09068
#1 0xe95d7e0c
#2 sys___realpath+0x1a8
#3 trap+0x950
#4 trapagain+0x4
[4]
#0 ufs_close+0x30
#1 VOP_CLOSE+0x60
#2 vn_closefile+0xc4
#3 fdrop+0xb4
#4 closef+0xe0
#5 fdrelease+0xf8
#6 sys_close+0x80
#7 trap+0x950
#8 trapagain+0x4
[5]
#0 fwargsave+0x34
[6>]
#0 mtx_leave+0x90
#1 vget+0x5c
#2 cache_lookup+0x1ec
#3 ufs_lookup+0x130
#4 VOP_LOOKUP+0x44n+0x4
[8]
#0 0xe85497a4
#1 VOP_GETATTR+0x58
#2 uvn_attach+0x270
#3 uvm_mmapfile+0x134
#4 sys_mmap+0x594
#5 trap+0x950
#6 trapagain+0x4
vn_lock: v_usecount == 0: 0xe85497a8, type VREG, use 0, write 0, hold 0, flags
(VBIOONFREELIST)
tag VT_UFS, ino 261391, on dev 0, 10 flags 0x100, effnlink 1, nlink 1
mode 0100660, owner 21, group 21, size 13647873
==> vnode_history_print 0xe85497a8, next=6
[0]
#0 ufs_close+0x30
#1 VOP_CLOSE+0x60
#2 vn_closefile+0xc4
#3 fdrop+0xb4
#4 closef+0xe0
#5 fdrelease+0xf8
#6 sys_close+0x80
#7 trap+0x950
#8 trapagain+0x4
[1]
#0 mtx_leave+0x90
#1 vget+0x5c
#2 cache_lookup+0x1ec
#3 ufs_lookup+0x130
#4 VOP_LOOKUP+0x44
#5 vfs_lookup+0x4a8
#6 namei+0x2a8
#7 vn_open+0xc0
#8 doopenat+0x1b4
#9 sys_open+0x34
#10 trap+0x950
#11 trapagain+0x4
[2]
#0 mtx_leave+0x90
#1 vget+0x5c
#2 cache_lookup+0x1ec
#3 ufs_lookup+0x130
#4 VOP_LOOKUP+0x44
#5 vfs_lookup+0x4a8
#6 namei+0x2a8
#7 sys___realpath+0x18c
#8 trap+0x950
#9 trapagain+0x4
[3]
#0 0x97b09068
#1 0xe95d7e0c
#2 sys___realpath+0x1a8
#3 trap+0x950
#4 trapagain+0x4
[4]
#0 ufs_close+0x30
#1 VOP_CLOSE+0x60
#2 vn_closefile+0xc4
#3 fdrop+0xb4
#4 closef+0xe0
#5 fdrelease+0xf8
#6 sys_close+0x80
#7 trap+0x950
#8 trapagain+0x4
[5]
#0 fwargsave+0x34
[6>]
#0 mtx_leave+0x90
#1 vget+0x5c
#2 cache_lookup+0x1ec
#3 ufs_lookup+0x130
#4 VOP_LOOKUP+0x44
#5 vfs_lookup+0x4a8
#6 namei+0x2a8
#7 sys___realpath+0x18c
#8 trap+0x950
#9 trapagain+0x4
[7]
#0 0x95648068
#1 0xe95dbe0c
#2 sys___realpath+0x1a8
#3 trap+0x950
#4 trapagain+0x4
[8]
#0 0xe85497a4
#1 VOP_GETATTR+0x58
#2 uvn_attach+0x270
#3 uvm_mmapfile+0x134
#4 sys_mmap+0x594
#5 trap+0x950
#6 trapagain+0x4
panic: vn_lock: v_usecount == 0
Stopped at db_enter+0x24: lwz r11,12(r1)
TID PID UID PRFLAGS PFLAGS CPU COMMAND
64276 21053 21 0x2 0 0 c++
*394240 19327 0 0x14000 0x200 1K pagedaemon
db_enter() at db_enter+0x20
panic(946547) at panic+0x158
vn_lock(e85497a8,340000) at vn_lock+0x1c4
uvn_io(ccd53e69,ad4b44,ae2948,ffffffff,e4010000) at uvn_io+0x254
uvn_put(d669ea18,e7eb9dd4,246ccb60,5e741d0) at uvn_put+0x64
uvm_pager_put(0,0,e7eb9d70,75cdb8,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(ccb2ea39) 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}> x/s version
version: OpenBSD 7.1-current (GENERIC.MP) #0: Fri Apr 8 12:01:35 CEST
2022\012
[email protected]:/usr/src/sys/arch/macppc/compile/GENERIC.MP\012
ddb{1}> trace
db_enter() at db_enter+0x20
panic(946547) at panic+0x158
vn_lock(e85497a8,340000) at vn_lock+0x1c4
uvn_io(ccd53e69,ad4b44,ae2948,ffffffff,e4010000) at uvn_io+0x254
uvn_put(d669ea18,e7eb9dd4,246ccb60,5e741d0) at uvn_put+0x64
uvm_pager_put(0,0,e7eb9d70,75cdb8,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(ccb2ea39) at uvm_pageout+0x398
fork_trampoline() at fork_trampoline+0x14
end trace frame: 0x0, count: -10
ddb{1}> show register
r0 0x74bb18 panic+0x15c
r1 0xe7eb9b60
r2 0
r3 0xac0bd0 cpu_info+0x4c0
r4 0xa90000 compose_tab+0x1a4
r5 0x1
r6 0
r7 0xe7bb9000
r8 0
r9 0x91a606 digits
r10 0x4
r11 0xc2c92133
r12 0xac3e5499
r13 0
r14 0xac1f38 bcstats
r15 0xae2924 uvmexp
r16 0
r17 0
r18 0
r19 0x340000 bpfread+0x88
r20 0x1000 tlbdsmsize+0xf18
r21 0x1000 tlbdsmsize+0xf18
r22 0xa94f14 netlock
r23 0xe4010000
r24 0x246ccb78
r25 0x246ccb7c
r26 0x927d05 digits+0xd6ff
r27 0
r28 0
r29 0xac0e90 cpu_info+0x780
r30 0x946547 cy_pio_rec+0x1262d
r31 0xae2a50 uvmexp+0x12c
lr 0x2783ec db_enter+0x24
cr 0x48228204
xer 0x20000000
ctr 0x243c08 openpic_splx
iar 0x2783ec 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
21053 64276 94918 21 7 0x2 c++
94918 11758 79302 21 3 0x10008a sigsusp sh
65795 453583 9847 21 2 0x2 c++
9847 20703 79302 21 3 0x10008a sigsusp sh
79302 461715 37653 21 3 0x10008a sigsusp make
37653 281082 32861 21 3 0x10008a sigsusp sh
32861 76154 68725 21 3 0x10008a sigsusp make
68725 3967 78904 21 3 0x10008a sigsusp sh
78904 149837 22402 21 3 0x10008a sigsusp make
22402 337263 16459 21 3 0x10008a sigsusp sh
16459 349504 79997 21 3 0x10008a sigsusp make
79997 42608 65071 21 3 0x10008a sigsusp sh
65071 228837 24390 21 3 0x10008a sigsusp make
24390 391178 61914 0 3 0x10008a sigsusp sh
61914 12808 1377 0 3 0x10008a sigsusp make
1377 521956 55685 0 3 0x10008a sigsusp make
55685 429549 99570 0 3 0x10008a sigsusp sh
99570 162319 470 0 3 0x82 piperd perl
470 426350 29917 0 3 0x10008a sigsusp ksh
29917 336048 87412 0 3 0x9a kqread sshd
3843 426280 1 0 3 0x100083 ttyin getty
36827 12678 1 0 3 0x100098 kqread cron
76603 2083 1 99 3 0x1100090 kqread sndiod
45726 104850 1 110 3 0x100090 kqread sndiod
15675 152126 7194 95 3 0x1100092 kqread smtpd
53951 221266 7194 103 3 0x1100092 kqread smtpd
40248 268874 7194 95 3 0x1100092 kqread smtpd
69900 444269 7194 95 3 0x100092 kqread smtpd
540 289196 7194 95 3 0x1100092 kqread smtpd
24306 520210 7194 95 3 0x1100092 kqread smtpd
7194 307818 1 0 3 0x100080 kqread smtpd
78910 500021 1 0 3 0x100080 kqread snmpd
13498 192026 1 91 3 0x1000092 kqread snmpd
87412 308053 1 0 3 0x88 kqread sshd
64977 135364 0 0 3 0x14280 nfsidl nfsio
2417 421268 0 0 3 0x14280 nfsidl nfsio
15080 197384 0 0 3 0x14280 nfsidl nfsio
10402 462176 0 0 3 0x14280 nfsidl nfsio
96741 412622 1 0 3 0x100080 kqread ntpd
59289 167238 18723 83 3 0x100092 kqread ntpd
18723 109476 1 83 3 0x1100092 kqread ntpd
19197 393988 78321 74 3 0x1100092 bpf pflogd
78321 287438 1 0 3 0x80 netio pflogd
8167 233105 59849 73 3 0x1100090 kqread syslogd
59849 128304 1 0 3 0x100082 netio syslogd
12908 159658 1 0 3 0x100080 kqread resolvd
33166 425005 11100 77 3 0x100092 kqread dhcpleased
9103 447651 11100 77 3 0x100092 kqread dhcpleased
11100 66683 1 0 3 0x80 kqread dhcpleased
15646 490047 87779 115 3 0x100092 kqread slaacd
60101 264984 87779 115 3 0x100092 kqread slaacd
87779 195828 1 0 3 0x100080 kqread slaacd
23836 462551 0 0 3 0x14200 bored smr
69250 316197 0 0 3 0x40014200 idle1
97063 400360 0 0 2 0x14200 zerothread
8287 120502 0 0 3 0x14200 aiodoned aiodoned
22292 347913 0 0 3 0x14200 syncer update
52937 396416 0 0 3 0x14200 cleaner cleaner
90095 163949 0 0 3 0x14200 reaper reaper
*19327 394240 0 0 7 0x14200 pagedaemon
38641 267559 0 0 3 0x14200 usbtsk usbtask
29582 376840 0 0 3 0x14200 usbatsk usbatsk
26521 471257 0 0 3 0x14200 bored sensors
34725 365056 0 0 3 0x14200 bored softnet
81247 261142 0 0 3 0x14200 bored systqmp
12751 203865 0 0 3 0x14200 bored systq
90193 213464 0 0 3 0x40014200 bored softclock
73541 56182 0 0 3 0x40014200 idle0
1 189703 0 0 3 0x82 wait init
0 0 -1 0 3 0x10200 scheduler swapper
ddb{1}> show vnode /f 0xe85497a8
0xe85497a8 tag UFS(1) type VREG(1) mount 0xe040f800 typedata 0x0
data 0x23ed53f8 usecount 0 writecount 0 holdcnt 0 numoutput 0
flag 0x0 lflag 0x0 bioflag 0x4
clean bufs:
dirty bufs:
==> vnode_history_print 0xe85497a8, next=6
[0]
#0 ufs_close+0x30
#1 VOP_CLOSE+0x60
#2 vn_closefile+0xc4
#3 fdrop+0xb4
#4 closef+0xe0
#5 fdrelease+0xf8
#6 sys_close+0x80
#7 trap+0x950
#8 trapagain+0x4
[1]
#0 mtx_leave+0x90
#1 vget+0x5c
#2 cache_lookup+0x1ec
#3 ufs_lookup+0x130
#4 VOP_LOOKUP+0x44
#5 vfs_lookup+0x4a8
#6 namei+0x2a8
#7 vn_open+0xc0
#8 doopenat+0x1b4
#9 sys_open+0x34
#10 trap+0x950
#11 trapagain+0x4
[2]
#0 mtx_leave+0x90
#1 vget+0x5c
#2 cache_lookup+0x1ec
#3 ufs_lookup+0x130
#4 VOP_LOOKUP+0x44
#5 vfs_lookup+0x4a8
#6 namei+0x2a8
#7 sys___realpath+0x18c
#8 trap+0x950
#9 trapagain+0x4
[3]
#0 0x97b09068
#1 0xe95d7e0c
#2 sys___realpath+0x1a8
#3 trap+0x950
#4 trapagain+0x4
[4]
#0 ufs_close+0x30
#1 VOP_CLOSE+0x60
#2 vn_closefile+0xc4
#3 fdrop+0xb4
#4 closef+0xe0
#5 fdrelease+0xf8
#6 sys_close+0x80
#7 trap+0x950
#8 trapagain+0x4
[5]
#0 fwargsave+0x34
[6>]
#0 mtx_leave+0x90
#1 vget+0x5c
#2 cache_lookup+0x1ec
#3 ufs_lookup+0x130
#4 VOP_LOOKUP+0x44
#5 vfs_lookup+0x4a8
#6 namei+0x2a8
#7 sys___realpath+0x18c
#8 trap+0x950
#9 trapagain+0x4
[7]
#0 0x95648068
#1 0xe95dbe0c
#2 sys___realpath+0x1a8
#3 trap+0x950
#4 trapagain+0x4
[8]
#0 0xe85497a4
#1 VOP_GETATTR+0x58
#2 uvn_attach+0x270
#3 uvm_mmapfile+0x134
#4 sys_mmap+0x594
#5 trap+0x950
#6 trapagain+0x4
ddb{1}> show mount 0xe040f800
flags 201818<NOSUID,NODEV,WXALLOWED,LOCAL,SWAPPABLE>
vnodecovered 0xe7ef1120 syncer 0xe7ef0dc0 data 0xe024ee00
vfsconf: ops 0xa54080 name "ffs" num 1 ref 9 flags 0x201000
statvfs cache: bsize 800 iosize 4000
blocks 3094879 free 2675034 avail 2520291
files 805502 ffiles 779235 favail 779235
f_fsidx {0xa, 0x4069424e} owner 0 ctime 0x625008a1
syncwrites 393439 asyncwrites = 207663
syncreads 3956437 asyncreads = 0
fstype "ffs" mnton "/usr/obj" mntfrom "/dev/wd0k" mntspec "6102496318219727.k"
locked vnodes:
ddb{1}> show uvm
Current UVM status:
pagesize=4096 (0x1000), pagemask=0xfff, pageshift=12
500888 VM pages: 163515 active, 194787 inactive, 1 wired, 36543 free (0 zero)
min 10% (25) anon, 10% (25) vnode, 5% (12) vtext
freemin=16696, free-target=22261, inactive-target=125887, wired-max=166962
faults=969662943, traps=0, intrs=1259564, ctxswitch=15345883 fpuswitch=3369101
softint=8301783, syscalls=1389148564, kmapent=8
fault counts:
noram=0, noanon=0, noamap=0, pgwait=0, pgrele=0
ok relocks(total)=658182(660858), anget(retries)=781627373(0),
amapcopy=60369139
neighbor anon/obj pg=69602565/139804775, gets(lock/unlock)=49193315/661794
cases: anon=779876686, anoncow=1750687, obj=42553276, prcopy=6636427,
przero=138845867
daemon and swap counts:
woke=7, revs=1, scans=19585, obscans=19362, anscans=0
busy=0, freed=19361, reactivate=223, deactivate=0
pageouts=1, pending=0, nswget=0
nswapdev=1
swpages=589823, swpginuse=0, swpgonly=0 paging=0
kernel pointers:
objs(kern)=0xaeca70
