On Thu, Apr 28, 2022 at 08:47:53PM +0200, Martin Pieuchot wrote:
> On 28/04/22(Thu) 16:54, Sebastien Marie wrote:
> > On Thu, Apr 28, 2022 at 04:04:41PM +0200, Alexander Bluhm wrote:
> > > On Wed, Apr 27, 2022 at 09:16:48AM +0200, Sebastien Marie wrote:
> > > > Here a new diff (sorry for the delay) which add a new
> > > > vnode_history_record()
> > > > point inside uvn_detach() (when 'uvn' object has UVM_VNODE_CANPERSIST
> > > > flag sets).
> > >
> > > [-- MARK -- Thu Apr 28 14:10:00 2022]
> > > uvn_io: start: 0x23ae1400, type VREG, use 0, write 0, hold 0, flags
> > > (VBIOONFREELIST)
> > > tag VT_UFS, ino 495247, on dev 0, 10 flags 0x100, effnlink 1,
> > > nlink 1
> > > mode 0100660, owner 21, group 21, size 13647873
> > > ==> vnode_history_print 0x23ae1400, next=6
> > > [3] c++[44194] usecount 2>1
> > > #0 0x626946ec
> > > [4] reaper[10898] usecount 1>1
> > > #0 entropy_pool0+0xf54
> >
> > even if the stacktrace is somehow grabage, the "usecount 1>1" is due to
> > VH_NOP
> > (no increment neither decrement), so it is the vnode_history_record() newly
> > added at:
> >
> > @@ -323,6 +325,10 @@ uvn_detach(struct uvm_object *uobj)
> > * let it "stick around".
> > */
> > if (uvn->u_flags & UVM_VNODE_CANPERSIST) {
> > + extern void vnode_history_record(struct vnode *, int);
> > +
> > + vnode_history_record(vp, 0);
> > +
> > /* won't block */
> > uvn_flush(uobj, 0, 0, PGO_DEACTIVATE|PGO_ALLPAGES);
> > goto out;
> >
> > mpi@, it confirms that uvn_flush() is called without PGO_FREE for this uvn.
>
> Thanks!
>
> Has vclean() been called for this vnode? If so the problem might indeed
> be related to the `uo_refs' fix I just committed, if not that might be
> the bug.
I tried with this commit. Did not help.
Full console log:
http://bluhm.genua.de/release/results/2022-04-28T18%3A58%3A33Z/bsdcons-ot26.txt
[-- MARK -- Fri Apr 29 11:50:00 2022]
uvn_io: start: 0x3c8701d0, type VREG, use 0, write 0, hold 834, flags
(VBIOONFREELIST)
tag VT_UFS, ino 729103, on dev 0, 10 flags 0x100, effnlink 1, nlink 1
mode 0100660, owner 21, group 21, size 13647873
==> vnode_history_print 0x3c8701d0, next=6
[4] reaper[77961] usecount 1>1
#0 udl_decomp_table+0x428
[5] reaper[77961] usecount 1>0
#0 splx+0x30
#1 0xfffffffc
#2 vrele+0x5c
#3 uvn_detach+0x160
#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: 0x3c8701d0, type VREG, use 0, write 0, hold 834,
flags (VBIOONFREELIST)
tag VT_UFS, ino 729103, on dev 0, 10 flags 0x100, effnlink 1, nlink 1
mode 0100660, owner 21, group 21, size 13647873
==> vnode_history_print 0x3c8701d0, next=6
[4] reaper[77961] usecount 1>1
#0 udl_decomp_table+0x428
[5] reaper[77961] usecount 1>0
#0 splx+0x30
#1 0xfffffffc
#2 vrele+0x5c
#3 uvn_detach+0x160
#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
196635 94068 21 0x2 0 1 c++
*178725 15770 0 0x14000 0x200 0K pagedaemon
db_enter() at db_enter+0x20
panic(948e9d) at panic+0x158
vn_lock(49535400,682000) at vn_lock+0x1c4
uvn_io(ac4198,ae2774,e7ebbc50,75468c,e4010000) at uvn_io+0x254
uvn_put(3e9be6ca,e7ebbdd4,3c8dc460,5e49200) at uvn_put+0x64
uvm_pager_put(0,0,e7ebbd70,304068,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(db17175f) 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: Thu Apr 28 21:25:23 CEST
2022\012
[email protected]:/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(948e9d) at panic+0x158
vn_lock(49535400,682000) at vn_lock+0x1c4
uvn_io(ac4198,ae2774,e7ebbc50,75468c,e4010000) at uvn_io+0x254
uvn_put(3e9be6ca,e7ebbdd4,3c8dc460,5e49200) at uvn_put+0x64
uvm_pager_put(0,0,e7ebbd70,304068,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(db17175f) at uvm_pageout+0x398
fork_trampoline() at fork_trampoline+0x14
end trace frame: 0x0, count: -10
ddb{0}> show register
r0 0x699cbc panic+0x15c
r1 0xe7ebbb60
r2 0
r3 0xadc6d8 cpu_info
r4 0xae0000 openpic_handler+0x338
r5 0x1
r6 0
r7 0xe7bb9000
r8 0
r9 0x91da88 pppdumpb.digits
r10 0x14
r11 0x528fb57b
r12 0xcfe4c932
r13 0
r14 0xae5238 bcstats
r15 0xae1f38 uvmexp
r16 0
r17 0
r18 0
r19 0x682000 ath_init1+0x274
r20 0x1000 tlbdsmsize+0xf18
r21 0x1000 tlbdsmsize+0xf18
r22 0xa851a4 netlock
r23 0xe4010000
r24 0x3c8dc478
r25 0x3c8dc47c
r26 0x92a661 apollo_udma66_tim+0x815
r27 0
r28 0
r29 0xadc998 cpu_info+0x2c0
r30 0x948e9d cy_pio_rec+0x13cae
r31 0xae2064 uvmexp+0x12c
lr 0x545808 db_enter+0x24
cr 0x48228204
xer 0x20000000
ctr 0x64c7d0 openpic_splx
iar 0x545808 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
15118 66765 86566 21 2 0x2 c++
86566 139858 64251 21 3 0x10008a sigsusp sh
94068 196635 34577 21 7 0x2 c++
34577 19123 64251 21 3 0x10008a sigsusp sh
64251 432339 39975 21 3 0x10008a sigsusp make
39975 273557 62325 21 3 0x10008a sigsusp sh
62325 181090 31928 21 3 0x10008a sigsusp make
31928 157508 51033 21 3 0x10008a sigsusp sh
51033 340777 69375 21 3 0x10008a sigsusp make
69375 76969 43720 21 3 0x10008a sigsusp sh
43720 253419 61897 21 3 0x10008a sigsusp make
61897 222655 90202 21 3 0x10008a sigsusp sh
90202 401583 85313 21 3 0x10008a sigsusp make
85313 243078 73285 0 3 0x10008a sigsusp sh
73285 198664 97456 0 3 0x10008a sigsusp make
97456 25132 35892 0 3 0x10008a sigsusp make
35892 467203 87785 0 3 0x10008a sigsusp sh
87785 517790 37066 0 3 0x82 piperd perl
37066 330515 90599 0 3 0x10008a sigsusp ksh
90599 445319 75135 0 3 0x9a kqread sshd
35456 450482 1 0 3 0x100083 ttyin getty
8757 427917 1 0 3 0x100098 kqread cron
44124 321980 1 99 3 0x1100090 kqread sndiod
30682 392120 1 110 3 0x100090 kqread sndiod
52962 206176 30728 95 3 0x1100092 kqread smtpd
38157 79399 30728 103 3 0x1100092 kqread smtpd
79345 468308 30728 95 3 0x1100092 kqread smtpd
13375 227106 30728 95 3 0x100092 kqread smtpd
71153 165822 30728 95 3 0x1100092 kqread smtpd
35276 21510 30728 95 3 0x1100092 kqread smtpd
30728 148050 1 0 3 0x100080 kqread smtpd
71506 370430 1 0 3 0x100080 kqread snmpd
40984 218935 1 91 3 0x1000092 kqread snmpd
75135 58900 1 0 3 0x88 kqread sshd
87889 444106 0 0 3 0x14280 nfsidl nfsio
53919 271998 0 0 3 0x14280 nfsidl nfsio
96640 478322 0 0 3 0x14280 nfsidl nfsio
88955 371685 0 0 3 0x14280 nfsidl nfsio
84379 519557 1 0 3 0x100080 kqread ntpd
8617 323569 55861 83 3 0x100092 kqread ntpd
55861 426326 1 83 3 0x1100092 kqread ntpd
40267 243708 37334 74 3 0x1100092 bpf pflogd
37334 49499 1 0 3 0x80 netio pflogd
89223 372187 2046 73 3 0x1100090 kqread syslogd
2046 113830 1 0 3 0x100082 netio syslogd
8710 361261 1 0 3 0x100080 kqread resolvd
39389 102719 80532 77 3 0x100092 kqread dhcpleased
87082 315065 80532 77 3 0x100092 kqread dhcpleased
80532 87629 1 0 3 0x80 kqread dhcpleased
52574 305193 35246 115 3 0x100092 kqread slaacd
42617 153438 35246 115 3 0x100092 kqread slaacd
35246 345779 1 0 3 0x100080 kqread slaacd
59819 107466 0 0 3 0x14200 bored smr
70106 522943 0 0 3 0x40014200 idle1
69432 27131 0 0 2 0x14200 zerothread
77434 402615 0 0 3 0x14200 aiodoned aiodoned
9297 268489 0 0 3 0x14200 syncer update
98492 347055 0 0 3 0x14200 cleaner cleaner
77961 314855 0 0 3 0x14200 reaper reaper
*15770 178725 0 0 7 0x14200 pagedaemon
29391 161074 0 0 3 0x14200 usbtsk usbtask
63565 209279 0 0 3 0x14200 usbatsk usbatsk
40508 227442 0 0 2 0x14200 sensors
13820 477396 0 0 3 0x14200 bored softnet
40002 375787 0 0 2 0x14200 systqmp
14639 12992 0 0 3 0x14200 bored systq
46933 12073 0 0 2 0x40014200 softclock
11482 8994 0 0 3 0x40014200 idle0
1 409452 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
500886 VM pages: 304636 active, 25274 inactive, 1 wired, 58155 free (1554
zero)
min 10% (25) anon, 10% (25) vnode, 5% (12) vtext
freemin=16696, free-target=22261, inactive-target=120079, wired-max=166962
faults=572918659, traps=0, intrs=853456, ctxswitch=12939276 fpuswitch=2497811
softint=4785000, syscalls=815549575, kmapent=10
fault counts:
noram=0, noanon=0, noamap=0, pgwait=0, pgrele=0
ok relocks(total)=340537(342120), anget(retries)=446835432(0),
amapcopy=42403653
neighbor anon/obj pg=36926596/122892163, gets(lock/unlock)=42735896/342317
cases: anon=445203347, anoncow=1632085, obj=36786343, prcopy=5947773,
przero=83349111
daemon and swap counts:
woke=1, revs=1, scans=30482, obscans=30328, anscans=0
busy=0, freed=30327, reactivate=154, deactivate=0
pageouts=1, pending=0, nswget=0
nswapdev=1
swpages=589823, swpginuse=0, swpgonly=0 paging=0
kernel pointers:
objs(kern)=0xad8398
