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 r...@ot26.obsd-lab.genua.de:/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