On Mon, May 02, 2022 at 06:53:08AM +0200, Sebastien Marie wrote: > New diff, with new iteration on vnode_history_*() functions. I added a label > in > the record function. I also changed when showing the stacktrace. powerpc has > poor backtrace support, but now it will at least print some infos even if no > stacktrace recorded (pid, ps_comm, label, v_usecount). > > I added a vnode_history_record() entry inside vclean(). We should have it in > both case: > - if vnode is already inactive (vp->v_usecount == 0) [trace already recorded] > - if vnode is still active (vp->v_usecount != 0) [trace previously not > recorded]
http://bluhm.genua.de/release/results/2022-05-02T12%3A23%3A22Z/bsdcons-ot26.txt [-- MARK -- Tue May 3 16:45:00 2022] uvn_io: start: 0x23b5a9c0, type VREG, use 0, write 0, hold 0, flags (VBIOONFREELIST) tag VT_UFS, ino 365327, on dev 0, 10 flags 0x100, effnlink 1, nlink 1 mode 0100660, owner 21, group 21, size 13647873 ==> vnode_history_print 0x23b5a9c0, next=6 [0] c++[83314] vget, usecount 1>2 #0 mtx_enter_try+0x5c [1] c++[83314] vget, usecount 2>3 #0 mtx_enter_try+0x5c [2] c++[83314] vrele, usecount 3>2 <empty stack trace> [3] c++[83314] vput, usecount 2>1 <empty stack trace> [4] reaper[690] uvn_detach (UVM_VNODE_CANPERSIST), usecount 1>1 #0 0xfffffffc #1 umidi_quirklist+0x148 #2 uvn_detach+0x13c #3 uvm_unmap_detach+0x1a4 #4 uvm_map_teardown+0x184 #5 uvmspace_free+0x60 #6 uvm_exit+0x30 #7 reaper+0x138 #8 fork_trampoline+0x14 [5] reaper[690] vrele, usecount 1>0 <empty stack trace> [6>] c++[73867] vget, usecount 1>2 #0 mtx_enter_try+0x5c [7] c++[73867] vrele, usecount 2>1 <empty stack trace> [8] c++[73867] vref, usecount 1>2 <empty stack trace> [9] c++[73867] vput, usecount 2>1 <empty stack trace> vn_lock: v_usecount == 0: 0x23b5a9c0, type VREG, use 0, write 0, hold 0, flags (VBIOONFREELIST) tag VT_UFS, ino 365327, on dev 0, 10 flags 0x100, effnlink 1, nlink 1 mode 0100660, owner 21, group 21, size 13647873 ==> vnode_history_print 0x23b5a9c0, next=6 [0] c++[83314] vget, usecount 1>2 #0 mtx_enter_try+0x5c [1] c++[83314] vget, usecount 2>3 #0 mtx_enter_try+0x5c [2] c++[83314] vrele, usecount 3>2 <empty stack trace> [3] c++[83314] vput, usecount 2>1 <empty stack trace> [4] reaper[690] uvn_detach (UVM_VNODE_CANPERSIST), usecount 1>1 #0 0xfffffffc #1 umidi_quirklist+0x148 #2 uvn_detach+0x13c #3 uvm_unmap_detach+0x1a4 #4 uvm_map_teardown+0x184 #5 uvmspace_free+0x60 #6 uvm_exit+0x30 #7 reaper+0x138 #8 fork_trampoline+0x14 [5] reaper[690] vrele, usecount 1>0 <empty stack trace> [6>] c++[73867] vget, usecount 1>2 #0 mtx_enter_try+0x5c [7] c++[73867] vrele, usecount 2>1 <empty stack trace> [8] c++[73867] vref, usecount 1>2 < PFLAGS CPU COMMAND 339124 89786 21 0x2 0 1 c++ *246215 93511 0 0x14000 0x200 0K pagedaemon db_enter() at db_enter+0x20 panic(9466dc) at panic+0x158 vn_lock(7c564249,2b7000) at vn_lock+0x1c4 uvn_io(ae78a0,1,e7ebbc50,8650f8,e4010000) at uvn_io+0x254 uvn_put(e5274130,e7ebbdd4,23b952a0,4f1f9f0) at uvn_put+0x64 uvm_pager_put(0,0,e7ebbd70,267900,2000000,80000000,0) at uvm_pager_put+0x15c uvmpd_scan_inactive(0) at uvmpd_scan_inactive+0x224 uvmpd_scan() at uvmpd_scan+0x15c uvm_pageout(19350f3) 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: Mon May 2 14:51:09 CEST 2022\012 r...@ot26.obsd-lab.genua.de:/usr/src/sys/arch/macppc/compile/GENERIC.MP\012 ddb{0}> show panic *cpu0: vn_lock: v_usecount == 0 ddb{0}> trace db_enter() at db_enter+0x20 panic(9466dc) at panic+0x158 vn_lock(7c564249,2b7000) at vn_lock+0x1c4 uvn_io(ae78a0,1,e7ebbc50,8650f8,e4010000) at uvn_io+0x254 uvn_put(e5274130,e7ebbdd4,23b952a0,4f1f9f0) at uvn_put+0x64 uvm_pager_put(0,0,e7ebbd70,267900,2000000,80000000,0) at uvm_pager_put+0x15c uvmpd_scan_inactive(0) at uvmpd_scan_inactive+0x224 uvmpd_scan() at uvmpd_scan+0x15c uvm_pageout(19350f3) at uvm_pageout+0x398 fork_trampoline() at fork_trampoline+0x14 end trace frame: 0x0, count: -10 ddb{0}> show register r0 0x5325c0 panic+0x15c r1 0xe7ebbb60 r2 0 r3 0xaf80e8 cpu_info r4 0xb00000 extract_entropy.extract_pool+0x1e24 r5 0x1 r6 0 r7 0xe7bb9000 r8 0 r9 0 r10 0 r11 0x7986a131 r12 0xa536dde _end+0x9a21fa6 r13 0 r14 0xaf4e90 bcstats r15 0xae0f7c uvmexp r16 0 r17 0 r18 0 r19 0x2b7000 vn_lock+0x130 r20 0x2000 tlbdsmsize+0x1f18 r21 0x2000 tlbdsmsize+0x1f18 r22 0xa887ec netlock r23 0xe4010000 r24 0x23b952b8 r25 0x23b952bc r26 0x927f4b pppdumpm.digits+0xb332 r27 0 r28 0 r29 0xaf83a8 cpu_info+0x2c0 r30 0x9466dc cy_pio_rec+0x11924 r31 0xae10a8 uvmexp+0x12c lr 0x63c344 db_enter+0x24 cr 0x48228204 xer 0x20000000 ctr 0x292f78 openpic_splx iar 0x63c344 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 89786 339124 18956 21 7 0x2 c++ 18956 132327 16031 21 3 0x10008a sigsusp sh 69984 204913 18196 21 2 0x2 c++ 18196 68139 16031 21 3 0x10008a sigsusp sh 16031 461704 55284 21 3 0x10008a sigsusp make 55284 387860 26131 21 3 0x10008a sigsusp sh 26131 129701 8638 21 3 0x10008a sigsusp make 8638 5723 93131 21 3 0x10008a sigsusp sh 93131 150437 70656 21 3 0x10008a sigsusp make 70656 356318 77649 21 3 0x10008a sigsusp sh 77649 417086 69384 21 3 0x10008a sigsusp make 69384 106821 41029 21 3 0x10008a sigsusp sh 41029 33801 47303 21 3 0x10008a sigsusp make 47303 456448 54946 0 3 0x10008a sigsusp sh 54946 79169 65610 0 3 0x10008a sigsusp make 65610 197678 3781 0 3 0x10008a sigsusp make 3781 34391 24626 0 3 0x10008a sigsusp sh 24626 44883 83499 0 3 0x82 piperd perl 83499 489078 31556 0 3 0x10008a sigsusp ksh 31556 300547 31500 0 3 0x9a kqread sshd 30342 257360 1 0 3 0x100083 ttyin getty 22119 70750 1 0 3 0x100098 kqread cron 18055 372758 1 99 3 0x1100090 kqread sndiod 15008 447360 1 110 3 0x100090 kqread sndiod 13426 88175 71372 95 3 0x1100092 kqread smtpd 69885 195544 71372 103 3 0x1100092 kqread smtpd 21127 121140 71372 95 3 0x1100092 kqread smtpd 45089 378581 71372 95 3 0x100092 kqread smtpd 25644 44788 71372 95 3 0x1100092 kqread smtpd 91476 174006 71372 95 3 0x1100092 kqread smtpd 71372 398158 1 0 3 0x100080 kqread smtpd 42333 286401 1 0 3 0x100080 kqread snmpd 96410 279792 1 91 3 0x1000092 kqread snmpd 31500 218012 1 0 3 0x88 kqread sshd 93289 359805 0 0 3 0x14280 nfsidl nfsio 97871 419910 0 0 3 0x14280 nfsidl nfsio 42572 230238 0 0 3 0x14280 nfsidl nfsio 76808 507862 0 0 3 0x14280 nfsidl nfsio 71633 434281 1 0 3 0x100080 kqread ntpd 91354 47535 29153 83 3 0x100092 kqread ntpd 29153 124045 1 83 3 0x1100092 kqread ntpd 79695 44418 51744 74 3 0x1100092 bpf pflogd 51744 381692 1 0 3 0x80 netio pflogd 55907 151738 60426 73 3 0x1100090 kqread syslogd 60426 76092 1 0 3 0x100082 netio syslogd 88148 388608 1 0 3 0x100080 kqread resolvd 27342 343514 35925 77 3 0x100092 kqread dhcpleased 91544 385441 35925 77 3 0x100092 kqread dhcpleased 35925 410197 1 0 3 0x80 kqread dhcpleased 69974 505453 29200 115 3 0x100092 kqread slaacd 21402 354493 29200 115 3 0x100092 kqread slaacd 29200 404409 1 0 3 0x100080 kqread slaacd 75650 317973 0 0 3 0x14200 bored smr 13921 79526 0 0 3 0x40014200 idle1 89472 223474 0 0 2 0x14200 zerothread 29989 442095 0 0 3 0x14200 aiodoned aiodoned 80478 197690 0 0 3 0x14200 syncer update 93421 417382 0 0 3 0x14200 cleaner cleaner 690 224430 0 0 3 0x14200 reaper reaper *93511 246215 0 0 7 0x14200 pagedaemon 4197 277498 0 0 3 0x14200 usbtsk usbtask 36475 273892 0 0 3 0x14200 usbatsk usbatsk 13924 79914 0 0 3 0x14200 bored sensors 36337 12438 0 0 3 0x14200 bored softnet 76457 523170 0 0 3 0x14200 bored systqmp 1779 97134 0 0 2 0x14200 systq 49928 343720 0 0 3 0x40014200 bored softclock 26289 252465 0 0 3 0x40014200 idle0 1 472436 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 500885 VM pages: 175986 active, 176218 inactive, 1 wired, 39146 free (0 zero) min 10% (25) anon, 10% (25) vnode, 5% (12) vtext freemin=16696, free-target=22261, inactive-target=124876, wired-max=166961 faults=969630414, traps=0, intrs=1166825, ctxswitch=14711382 fpuswitch=3180378 softint=8108901, syscalls=1386436019, kmapent=10 fault counts: noram=0, noanon=0, noamap=0, pgwait=0, pgrele=0 ok relocks(total)=627050(629900), anget(retries)=781626468(0), amapcopy=60288578 neighbor anon/obj pg=68697850/141880231, gets(lock/unlock)=49379029/630810 cases: anon=779885897, anoncow=1740571, obj=42638621, prcopy=6736648, przero=138628677 daemon and swap counts: woke=5, revs=1, scans=22691, obscans=22425, anscans=0 busy=0, freed=22424, reactivate=266, deactivate=0 pageouts=1, pending=0, nswget=0 nswapdev=1 swpages=589823, swpginuse=0, swpgonly=0 paging=0 kernel pointers: objs(kern)=0xae6070
