On Tue, Nov 22, 2022 at 05:47:44PM +0000, Miod Vallat wrote:
> > Here is a diff. Maybe bluhm@ can try this on the macppc machine that
> > triggered the original "vref used where vget required" problem?
>
> On a similar machine it panics after a few hours with:
>
> panic: uvn_flush: PGO_SYNCIO return 'try again' error (impossible)
same here, took me 3:39 hours
panic: uvn_flush: PGO_SYNCIO return 'try again' error (impossible)
Stopped at db_enter+0x24: lwz r11,12(r1)
TID PID UID PRFLAGS PFLAGS CPU COMMAND
*316489 81760 21 0x2 0 1K c++
186567 88345 21 0x2 0 0 c++
db_enter() at db_enter+0x20
panic(8f85a4) at panic+0x158
uvn_flush(0,9000,4000,ffffffff) at uvn_flush+0x820
uvm_vnp_terminate(238827b8) at uvm_vnp_terminate+0x70
vclean(2820f822,e37a6514,e8123960) at vclean+0xdc
vgonel(e8123a24,b1c52908) at vgonel+0x70
getnewvnode(0,341a3,22f89509,909610) at getnewvnode+0x240
ffs_vget(56bf5c85,1000,0) at ffs_vget+0xcc
ufs_lookup() at ufs_lookup+0xb00
VOP_LOOKUP(e8123d20,e0ca3c38,238827b8) at VOP_LOOKUP+0x44
vfs_lookup(56) at vfs_lookup+0x4a8
namei(ffffffff) at namei+0x2a8
vn_open(0,e37a6514,e8123c30) at vn_open+0xc0
doopenat(2001,5a5ae178,fffef45c,ffffff9c,0,0) at doopenat+0x1b4
end trace frame: 0xe8123e90, count: 0
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}>
> The trace (transcribed by hand) is
> uvn_flush+0x820
> uvm_vnp_terminate+0x79
> vclean+0xdc
> vgonel+0x70
> getnewvnode+0x240
> ffs_vget+0xcc
> ffs_inode_alloc+0x13c
> ufs_makeinode+0x94
> ufs_create+0x58
> VOP_CREATE+0x48
> vn_open+0x188
> doopenat+0x1b4
ddb{1}> trace
db_enter() at db_enter+0x20
panic(8f85a4) at panic+0x158
uvn_flush(0,9000,4000,ffffffff) at uvn_flush+0x820
uvm_vnp_terminate(238827b8) at uvm_vnp_terminate+0x70
vclean(2820f822,e37a6514,e8123960) at vclean+0xdc
vgonel(e8123a24,b1c52908) at vgonel+0x70
getnewvnode(0,341a3,22f89509,909610) at getnewvnode+0x240
ffs_vget(56bf5c85,1000,0) at ffs_vget+0xcc
ufs_lookup() at ufs_lookup+0xb00
VOP_LOOKUP(e8123d20,e0ca3c38,238827b8) at VOP_LOOKUP+0x44
vfs_lookup(56) at vfs_lookup+0x4a8
namei(ffffffff) at namei+0x2a8
vn_open(0,e37a6514,e8123c30) at vn_open+0xc0
doopenat(2001,5a5ae178,fffef45c,ffffff9c,0,0) at doopenat+0x1b4
sys_open(e8123f58,aacc64d6,e8123f50) at sys_open+0x34
trap(0) at trap+0x8d4
trapagain() at trapagain+0x4
--- syscall (number 5) ---
End of kernel: 0xfffef3c0
end trace frame: 0xfffef3c0, count: -17
ddb{1}> show register
r0 0x144b6c panic+0x15c
r1 0xe81237d0
r2 0xab9c60 cpu_info+0x4c8
r3 0xab9c60 cpu_info+0x4c8
r4 0xb00000 db_elf_line_at_pc.path+0x1bc
r5 0x1
r6 0
r7 0xe7cb9000
r8 0
r9 0
r10 0
r11 0x624940af
r12 0x7d635f61
r13 0
r14 0x3b ddbsize+0xb
r15 0x5
r16 0x40e4598 _end+0x35c4754
r17 0x1b
r18 0x9000 tlbdsmsize+0x8f18
r19 0xe8123878
r20 0
r21 0xe8123884
r22 0
r23 0x10
r24 0x5000 tlbdsmsize+0x4f18
r25 0
r26 0xb0c64c uvm+0x10
r27 0
r28 0
r29 0xab9f28 cpu_info+0x790
r30 0x8f85a4 acx100_txpower_maxim+0x7490
r31 0x1b
lr 0x848af0 db_enter+0x24
cr 0x48482602
xer 0x20000000
ctr 0x4ab3e4 openpic_splx
iar 0x848af0 db_enter+0x24
msr 0x9032 tlbdsmsize+0x8f4a
dar 0
dsisr 0
db_enter+0x24: lwz r11,12(r1)
ddb{1}> show panic
*cpu1: uvn_flush: PGO_SYNCIO return 'try again' error (impossible)
ddb{1}> show uvm
Current UVM status:
pagesize=4096 (0x1000), pagemask=0xfff, pageshift=12
500872 VM pages: 47375 active, 65511 inactive, 1 wired, 278921 free (13303
zero)
min 10% (25) anon, 10% (25) vnode, 5% (12) vtext
freemin=16695, free-target=22260, inactive-target=0, wired-max=166957
faults=205167249, traps=0, intrs=601834, ctxswitch=11667040 fpuswitch=1818402
softint=1432338, syscalls=287584088, kmapent=11
fault counts:
noram=0, noanon=0, noamap=0, pgwait=0, pgrele=0
ok relocks(total)=241266(242663), anget(retries)=141999836(0),
amapcopy=24524315
neighbor anon/obj pg=9973263/96744262, gets(lock/unlock)=34934368/242837
cases: anon=140506255, anoncow=1493581, obj=30776338, prcopy=4156459,
przero=28234615
daemon and swap counts:
woke=0, revs=0, scans=0, obscans=0, anscans=0
busy=0, freed=0, reactivate=0, deactivate=0
pageouts=0, pending=0, nswget=0
nswapdev=1
swpages=589823, swpginuse=0, swpgonly=0 paging=0
kernel pointers:
objs(kern)=0xb0a638
ddb{1}> ps
PID TID PPID UID S FLAGS WAIT COMMAND
*81760 316489 13955 21 7 0x2 c++
88345 186567 50974 21 7 0x2 c++
13955 26906 44729 21 3 0x10008a sigsusp sh
50974 191157 44729 21 3 0x10008a sigsusp sh
44729 47046 1083 21 3 0x10008a sigsusp make
1083 113096 68827 21 3 0x10008a sigsusp sh
68827 491773 29873 21 3 0x10008a sigsusp make
29873 198420 62918 21 3 0x10008a sigsusp sh
62918 182180 42548 21 3 0x10008a sigsusp make
42548 171704 10781 21 3 0x10008a sigsusp sh
10781 427946 68572 21 3 0x10008a sigsusp make
68572 431243 25302 21 3 0x10008a sigsusp sh
25302 356746 68913 21 3 0x10008a sigsusp make
68913 519691 76790 0 3 0x10008a sigsusp sh
76790 369737 61961 0 3 0x10008a sigsusp make
61961 127106 88182 0 3 0x10008a sigsusp make
88182 51147 76247 0 3 0x10008a sigsusp sh
76247 38040 5823 0 3 0x82 piperd perl
5823 283365 90425 0 3 0x10008a sigsusp ksh
90425 437797 54490 0 3 0x9a kqread sshd
36905 403407 1 0 3 0x100083 ttyin getty
79327 250152 1 0 3 0x100098 kqread cron
3278 179734 1 99 3 0x1100090 kqread sndiod
85877 320788 1 110 3 0x100090 kqread sndiod
16675 410797 91309 95 3 0x1100092 kqread smtpd
36528 419171 91309 103 3 0x1100092 kqread smtpd
47154 12738 91309 95 3 0x1100092 kqread smtpd
92186 491655 91309 95 3 0x100092 kqread smtpd
1707 221756 91309 95 3 0x1100092 kqread smtpd
30665 520358 91309 95 3 0x1100092 kqread smtpd
91309 41904 1 0 3 0x100080 kqread smtpd
72960 98098 28233 91 3 0x92 kqread snmpd_metrics
28233 517673 1 0 3 0x100080 kqread snmpd
77661 438123 1 91 3 0x1100092 kqread snmpd
54490 263940 1 0 3 0x88 kqread sshd
63745 63277 0 0 3 0x14280 nfsidl nfsio
96318 498356 0 0 3 0x14280 nfsidl nfsio
80490 323879 0 0 3 0x14280 nfsidl nfsio
29317 85723 0 0 3 0x14280 nfsidl nfsio
91780 401412 1 0 3 0x100080 kqread ntpd
92741 10686 57917 83 3 0x100092 kqread ntpd
57917 278733 1 83 3 0x1100092 kqread ntpd
65482 242899 86751 74 3 0x1100092 bpf pflogd
86751 303168 1 0 3 0x80 netio pflogd
10139 361897 40434 73 3 0x1100090 kqread syslogd
40434 305895 1 0 3 0x100082 netio syslogd
78505 27615 1 0 3 0x100080 kqread resolvd
98603 13252 32298 77 3 0x100092 kqread dhcpleased
18233 459763 32298 77 3 0x100092 kqread dhcpleased
32298 310295 1 0 3 0x80 kqread dhcpleased
32480 337897 76925 115 3 0x100092 kqread slaacd
66451 101312 76925 115 3 0x100092 kqread slaacd
76925 315691 1 0 3 0x100080 kqread slaacd
92775 517955 0 0 3 0x14200 bored smr
61893 63448 0 0 3 0x40014200 idle1
31979 106349 0 0 2 0x14200 zerothread
38344 29087 0 0 3 0x14200 aiodoned aiodoned
72585 398464 0 0 3 0x14200 syncer update
6150 427581 0 0 3 0x14200 cleaner cleaner
23088 163934 0 0 3 0x14200 reaper reaper
3558 477023 0 0 3 0x14200 pgdaemon pagedaemon
4436 87244 0 0 3 0x14200 usbtsk usbtask
59846 520545 0 0 3 0x14200 usbatsk usbatsk
82324 304123 0 0 3 0x14200 bored sensors
54561 519070 0 0 3 0x14200 bored softnet
23022 472355 0 0 3 0x14200 bored softnet
25804 440410 0 0 3 0x14200 bored softnet
26404 389530 0 0 3 0x14200 bored softnet
93595 256016 0 0 3 0x14200 bored systqmp
50909 244852 0 0 3 0x14200 bored systq
69922 288822 0 0 3 0x40014200 bored softclock
24407 248936 0 0 3 0x40014200 idle0
1 337472 0 0 3 0x82 wait init
0 0 -1 0 3 0x10200 scheduler swapper
ddb{1}>
ddb{1}> mach ddbcpu 0
Stopped at db_enter+0x24: lwz r11,12(r1)
db_enter() at db_enter+0x20
openpic_ext_intr() at openpic_ext_intr+0x2dc
extint_call() at extint_call
ddbsize() at ddbsize+0xc
openpic_ext_intr() at openpic_ext_intr+0x368
extint_call() at extint_call
mtx_leave(a944a8) at mtx_leave+0x90
dosoftint(e802c800) at dosoftint+0x40
openpic_splx(56bf5c85) at openpic_splx+0xf0
splx(c65fb0) at splx+0x30
decr_intr(9ef33000) at decr_intr+0x2e8
decrintr() at decrintr+0x100
End of kernel: 0xfffc6970
end trace frame: 0xfffc6970, count: 3
ddb{0}> trace
db_enter() at db_enter+0x20
openpic_ext_intr() at openpic_ext_intr+0x2dc
extint_call() at extint_call
ddbsize() at ddbsize+0xc
openpic_ext_intr() at openpic_ext_intr+0x368
extint_call() at extint_call
mtx_leave(a944a8) at mtx_leave+0x90
dosoftint(e802c800) at dosoftint+0x40
openpic_splx(56bf5c85) at openpic_splx+0xf0
splx(c65fb0) at splx+0x30
decr_intr(9ef33000) at decr_intr+0x2e8
decrintr() at decrintr+0x100
End of kernel: 0xfffc6970
end trace frame: 0xfffc6970, count: -12
ddb{0}> show register
r0 0x4aac24 openpic_ext_intr+0x2e0
r1 0xc65d88 _end+0x145f44
r2 0xb7620ae0
r3 0xab9798 cpu_info
r4 0xe7cd90a0
r5 0xe7cd90b0
r6 0xaf68c0 ipi_count
r7 0
r8 0
r9 0x4141cc mc_init+0xec
r10 0xb10000 tcp_debug+0x29f8
r11 0x6217a7e7
r12 0xd0dd7a22
r13 0
r14 0
r15 0x1
r16 0xe0001c00
r17 0xab0000 baddynamicports+0x2510
r18 0xb0c4e4 uvmexp
r19 0xaf6900 openpic_pri_share
r20 0xaf60c0 openpic_handler
r21 0xaf6934 openpic_irqloop
r22 0x8000 tlbdsmsize+0x7f18
r23 0x200a0 tlbdsmsize+0x1ffb8
r24 0xa90000 evergreen_asic+0x150
r25 0
r26 0xaf0000 uvm_map_init.kernel_map_entry+0x14c60
r27 0xaf0000 uvm_map_init.kernel_map_entry+0x14c60
r28 0xab9798 cpu_info
r29 0x160 tlbdsmsize+0x78
r30 0x7
r31 0
lr 0x848af0 db_enter+0x24
cr 0x42144088
xer 0
ctr 0x4a9b24 openpic_gen_acknowledge_irq
iar 0x848af0 db_enter+0x24
msr 0x1032 tlbdsmsize+0xf4a
dar 0
dsisr 0
db_enter+0x24: lwz r11,12(r1)
ddb{0}> ps
PID TID PPID UID S FLAGS WAIT COMMAND
81760 316489 13955 21 7 0x2 c++
*88345 186567 50974 21 7 0x2 c++
13955 26906 44729 21 3 0x10008a sigsusp sh
50974 191157 44729 21 3 0x10008a sigsusp sh
44729 47046 1083 21 3 0x10008a sigsusp make
1083 113096 68827 21 3 0x10008a sigsusp sh
68827 491773 29873 21 3 0x10008a sigsusp make
29873 198420 62918 21 3 0x10008a sigsusp sh
62918 182180 42548 21 3 0x10008a sigsusp make
42548 171704 10781 21 3 0x10008a sigsusp sh
10781 427946 68572 21 3 0x10008a sigsusp make
68572 431243 25302 21 3 0x10008a sigsusp sh
25302 356746 68913 21 3 0x10008a sigsusp make
68913 519691 76790 0 3 0x10008a sigsusp sh
76790 369737 61961 0 3 0x10008a sigsusp make
61961 127106 88182 0 3 0x10008a sigsusp make
88182 51147 76247 0 3 0x10008a sigsusp sh
76247 38040 5823 0 3 0x82 piperd perl
5823 283365 90425 0 3 0x10008a sigsusp ksh
90425 437797 54490 0 3 0x9a kqread sshd
36905 403407 1 0 3 0x100083 ttyin getty
79327 250152 1 0 3 0x100098 kqread cron
3278 179734 1 99 3 0x1100090 kqread sndiod
85877 320788 1 110 3 0x100090 kqread sndiod
16675 410797 91309 95 3 0x1100092 kqread smtpd
36528 419171 91309 103 3 0x1100092 kqread smtpd
47154 12738 91309 95 3 0x1100092 kqread smtpd
92186 491655 91309 95 3 0x100092 kqread smtpd
1707 221756 91309 95 3 0x1100092 kqread smtpd
30665 520358 91309 95 3 0x1100092 kqread smtpd
91309 41904 1 0 3 0x100080 kqread smtpd
72960 98098 28233 91 3 0x92 kqread snmpd_metrics
28233 517673 1 0 3 0x100080 kqread snmpd
77661 438123 1 91 3 0x1100092 kqread snmpd
54490 263940 1 0 3 0x88 kqread sshd
63745 63277 0 0 3 0x14280 nfsidl nfsio
96318 498356 0 0 3 0x14280 nfsidl nfsio
80490 323879 0 0 3 0x14280 nfsidl nfsio
29317 85723 0 0 3 0x14280 nfsidl nfsio
91780 401412 1 0 3 0x100080 kqread ntpd
92741 10686 57917 83 3 0x100092 kqread ntpd
57917 278733 1 83 3 0x1100092 kqread ntpd
65482 242899 86751 74 3 0x1100092 bpf pflogd
86751 303168 1 0 3 0x80 netio pflogd
10139 361897 40434 73 3 0x1100090 kqread syslogd
40434 305895 1 0 3 0x100082 netio syslogd
78505 27615 1 0 3 0x100080 kqread resolvd
98603 13252 32298 77 3 0x100092 kqread dhcpleased
18233 459763 32298 77 3 0x100092 kqread dhcpleased
32298 310295 1 0 3 0x80 kqread dhcpleased
32480 337897 76925 115 3 0x100092 kqread slaacd
66451 101312 76925 115 3 0x100092 kqread slaacd
76925 315691 1 0 3 0x100080 kqread slaacd
92775 517955 0 0 3 0x14200 bored smr
61893 63448 0 0 3 0x40014200 idle1
31979 106349 0 0 2 0x14200 zerothread
38344 29087 0 0 3 0x14200 aiodoned aiodoned
72585 398464 0 0 3 0x14200 syncer update
6150 427581 0 0 3 0x14200 cleaner cleaner
23088 163934 0 0 3 0x14200 reaper reaper
3558 477023 0 0 3 0x14200 pgdaemon pagedaemon
4436 87244 0 0 3 0x14200 usbtsk usbtask
59846 520545 0 0 3 0x14200 usbatsk usbatsk
82324 304123 0 0 3 0x14200 bored sensors
54561 519070 0 0 3 0x14200 bored softnet
23022 472355 0 0 3 0x14200 bored softnet
25804 440410 0 0 3 0x14200 bored softnet
26404 389530 0 0 3 0x14200 bored softnet
93595 256016 0 0 3 0x14200 bored systqmp
50909 244852 0 0 3 0x14200 bored systq
69922 288822 0 0 3 0x40014200 bored softclock
24407 248936 0 0 3 0x40014200 idle0
1 337472 0 0 3 0x82 wait init
0 0 -1 0 3 0x10200 scheduler swapper
ddb{0}>
