On Fri, Apr 08, 2022 at 06:38:47AM +0200, Sebastien Marie wrote:
> I have a diff for adding some stacktrace history for vnode (keeping track of
> lasts vref/vrele/vget/vput). but I am not sure it would be efficient to found
> the underline problem.
Now it crashed with a different panic.
[-- MARK -- Thu Apr 7 20:40:00 2022]
uvn_io: start: 0x21627330, type VREG, use 0, write 0, hold 0, flags
(VBIOONFREELIST)
tag VT_UFS, ino 53519, on dev 0, 10 flags 0x100, effnlink 1, nlink 1
mode 0100660, owner 21, group 21, size 13647873
vn_lock: vnode on freelist: 0x21627330, type VREG, use 0, write 0, hold 0,
flags (VBIOONFREELIST)
tag VT_UFS, ino 53519, on dev 0, 10 flags 0x100, effnlink 1, nlink 1
mode 0100660, owner 21, group 21, size 13647873
panic: vn_lock: vp on freelist
Stopped at db_enter+0x24: lwz r11,12(r1)
TID PID UID PRFLAGS PFLAGS CPU COMMAND
274717 97986 21 0x2 0 1 c++
*225451 71080 0 0x14000 0x200 0K pagedaemon
db_enter() at db_enter+0x20
panic(8fb04c) at panic+0x158
vn_lock(21627330,66000) at vn_lock+0x1c8
uvn_io(aea240,ae8324,e7eb7c50,199bec,e4010000) at uvn_io+0x254
uvn_put(27a50962,e7eb7dd4,216e28c0,5310050) at uvn_put+0x64
uvm_pager_put(0,0,e7eb7d70,74d794,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(8ceca09c) 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{0}> x/s version
version: OpenBSD 7.1-current (GENERIC.MP) #0: Wed Apr 6 18:41:30 CEST
2022\012
r...@ot26.obsd-lab.genua.de:/usr/src/sys/arch/macppc/compile/GENERIC.MP\012
ddb{0}> trace
db_enter() at db_enter+0x20
panic(8fb04c) at panic+0x158
vn_lock(21627330,66000) at vn_lock+0x1c8
uvn_io(aea240,ae8324,e7eb7c50,199bec,e4010000) at uvn_io+0x254
uvn_put(27a50962,e7eb7dd4,216e28c0,5310050) at uvn_put+0x64
uvm_pager_put(0,0,e7eb7d70,74d794,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(8ceca09c) at uvm_pageout+0x398
fork_trampoline() at fork_trampoline+0x14
end trace frame: 0x0, count: -10
ddb{0}> show register
r0 0x3d7df8 panic+0x15c
r1 0xe7eb7b60
r2 0
r3 0xae6f80 cpu_info
r4 0xa90000 ch_cd+0x8
r5 0x1
r6 0
r7 0xe7bb9000
r8 0
r9 0xa
r10 0
r11 0xd0fc4cb0
r12 0x4ace9843
r13 0
r14 0xa9c338 bcstats
r15 0xa9ccd0 uvmexp
r16 0
r17 0
r18 0
r19 0x66000 tlbdsmsize+0x65f18
r20 0x1000 tlbdsmsize+0xf18
r21 0x1000 tlbdsmsize+0xf18
r22 0xa87498 netlock
r23 0xe4010000
r24 0x216e28d8
r25 0x216e28dc
r26 0x928213 pppdumpb.digits+0xd247
r27 0
r28 0
r29 0xae7240 cpu_info+0x2c0
r30 0x8fb04c acx100_txpower_maxim+0x15da9
r31 0xa9cdfc uvmexp+0x12c
lr 0x6df6a4 db_enter+0x24
cr 0x48248204
xer 0x20000000
ctr 0x85b7a8 openpic_splx
iar 0x6df6a4 db_enter+0x24
msr 0x9032 tlbdsmsize+0x8f4a
dar 0
dsisr 0
db_enter+0x24: lwz r11,12(r1)
ddb{0}> ps
PID TID PPID UID S FLAGS WAIT COMMAND
97986 274717 16951 21 7 0x2 c++
16951 395571 51575 21 3 0x10008a sigsusp sh
13622 390409 92318 21 2 0x2 c++
92318 345567 51575 21 3 0x10008a sigsusp sh
51575 308476 74048 21 3 0x10008a sigsusp make
45066 332753 41333 0 3 0x100083 ttyin ksh
41333 96843 74563 0 3 0x9a kqread sshd
74048 94540 70207 21 3 0x10008a sigsusp sh
70207 460985 23322 21 3 0x10008a sigsusp make
23322 440955 83159 21 3 0x10008a sigsusp sh
83159 398976 29014 21 3 0x10008a sigsusp make
29014 70968 55226 21 3 0x10008a sigsusp sh
55226 292681 31699 21 3 0x10008a sigsusp make
31699 459869 20042 21 3 0x10008a sigsusp sh
20042 137887 22954 21 3 0x10008a sigsusp make
22954 75917 81198 0 3 0x10008a sigsusp sh
81198 243210 90602 0 3 0x10008a sigsusp make
90602 217537 51289 0 3 0x10008a sigsusp make
51289 192899 38689 0 3 0x10008a sigsusp sh
38689 42714 45197 0 3 0x82 piperd perl
45197 394229 29422 0 3 0x10008a sigsusp ksh
29422 86650 74563 0 3 0x9a kqread sshd
98901 348193 1 0 3 0x100083 ttyin getty
48453 385278 1 0 3 0x100098 kqread cron
84022 308816 1 99 3 0x1100090 kqread sndiod
3398 55862 1 110 3 0x100090 kqread sndiod
12008 85980 7999 95 3 0x1100092 kqread smtpd
71141 288723 7999 103 3 0x1100092 kqread smtpd
45596 32546 7999 95 3 0x1100092 kqread smtpd
37377 361027 7999 95 3 0x100092 kqread smtpd
88102 7058 7999 95 3 0x1100092 kqread smtpd
25527 64177 7999 95 3 0x1100092 kqread smtpd
7999 43557 1 0 3 0x100080 kqread smtpd
44573 503010 1 0 3 0x100080 kqread snmpd
90728 393902 1 91 3 0x1000092 kqread snmpd
74563 8334 1 0 3 0x88 kqread sshd
57095 254815 0 0 3 0x14280 nfsidl nfsio
98840 240703 0 0 3 0x14280 nfsidl nfsio
47343 147034 0 0 3 0x14280 nfsidl nfsio
6753 498959 0 0 3 0x14280 nfsidl nfsio
29201 47631 1 0 3 0x100080 kqread ntpd
33099 484625 56534 83 3 0x100092 kqread ntpd
56534 292689 1 83 3 0x1100092 kqread ntpd
62369 98948 79044 74 2 0x1100492 pflogd
79044 330898 1 0 3 0x80 netio pflogd
65490 435578 84106 73 3 0x1100090 kqread syslogd
84106 423453 1 0 3 0x100082 netio syslogd
88088 477373 1 0 3 0x100080 kqread resolvd
39845 204020 39424 77 3 0x100092 kqread dhcpleased
80876 366475 39424 77 3 0x100092 kqread dhcpleased
39424 8418 1 0 3 0x80 kqread dhcpleased
41200 299883 7545 115 3 0x100092 kqread slaacd
66958 461407 7545 115 3 0x100092 kqread slaacd
7545 304659 1 0 3 0x100080 kqread slaacd
88918 21495 0 0 3 0x14200 bored smr
90991 197558 0 0 3 0x40014200 idle1
47592 55275 0 0 2 0x14200 zerothread
39553 170931 0 0 3 0x14200 aiodoned aiodoned
45170 424622 0 0 3 0x14200 syncer update
64684 246555 0 0 3 0x14200 cleaner cleaner
6705 457967 0 0 3 0x14200 reaper reaper
*71080 225451 0 0 7 0x14200 pagedaemon
9235 383272 0 0 3 0x14200 usbtsk usbtask
47308 402150 0 0 3 0x14200 usbatsk usbatsk
56720 93813 0 0 2 0x14200 sensors
99127 246547 0 0 3 0x14200 bored softnet
25216 413067 0 0 3 0x14200 bored systqmp
81587 391784 0 0 2 0x14200 systq
77165 407318 0 0 2 0x40014200 softclock
69836 337479 0 0 3 0x40014200 idle0
1 223062 0 0 3 0x82 wait init
0 0 -1 0 3 0x10200 scheduler swapper
ddb{0}> show uvm
Current UVM status:
pagesize=4096 (0x1000), pagemask=0xfff, pageshift=12
500889 VM pages: 180425 active, 179629 inactive, 1 wired, 38852 free (1807
zero)
min 10% (25) anon, 10% (25) vnode, 5% (12) vtext
freemin=16696, free-target=22261, inactive-target=127390, wired-max=166963
faults=968940681, traps=0, intrs=1111464, ctxswitch=15241979 fpuswitch=3263613
softint=8081037, syscalls=1385245944, kmapent=8
fault counts:
noram=0, noanon=0, noamap=0, pgwait=0, pgrele=0
ok relocks(total)=632297(635126), anget(retries)=780937546(0),
amapcopy=60251913
neighbor anon/obj pg=68687347/141085425, gets(lock/unlock)=49332093/635960
cases: anon=779173667, anoncow=1763879, obj=42692145, prcopy=6636285,
przero=138674705
daemon and swap counts:
woke=4, revs=1, scans=22318, obscans=22119, anscans=0
busy=0, freed=22118, reactivate=199, deactivate=0
pageouts=1, pending=0, nswget=0
nswapdev=1
swpages=589823, swpginuse=0, swpgonly=0 paging=0
kernel pointers:
objs(kern)=0xaa47b8
ddb{0}> show vnode /f 0x21627330
0x21627330 tag UFS(1) type VREG(1) mount 0xe040f800 typedata 0x0
data 0x1a428920 usecount 0 writecount 0 holdcnt 0 numoutput 0
flag 0x0 lflag 0x0 bioflag 0x4
clean bufs:
dirty bufs:
ddb{0}> show mount 0xe040f800
flags 201818<NOSUID,NODEV,WXALLOWED,LOCAL,SWAPPABLE>
vnodecovered 0x31066230 syncer 0x31066120 data 0xe024ee00
vfsconf: ops 0xa71c7c 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 0x624dc3a0
syncwrites 383151 asyncwrites = 207290
syncreads 3808928 asyncreads = 0
fstype "ffs" mnton "/usr/obj" mntfrom "/dev/wd0k" mntspec "6102496318219727.k"
locked vnodes:
