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}>