On 25/05/23(Thu) 16:33, Kurt Miller wrote: > On May 22, 2023, at 2:27 AM, Claudio Jeker <clau...@openbsd.org> wrote: > > I have seen these WITNESS warnings on other systems as well. I doubt this > > is the problem. IIRC this warning is because sys_mount() is doing it wrong > > but it is not really an issue since sys_mount is not called often. > > Yup. I see that now that I have tested witness on several arches. They all > show this lock order reversal right after booting the system. I guess this > means what I am seeing isn’t something that witness detects. > > On -current with my T4-1, I can reliably reproduce the issues I am seeing. > While the problem is intermittent I can’t get very far into the jdk build > without > tripping it. Instructions for reproducing the issue are: > > Add wxallowed to /usr/local/ and /usr/ports (or wherever WRKOBJDIR has > been changed to) > > doas pkg_add jdk zip unzip cups-libs bash gmake libiconv giflib > > cd /usr/ports/devel/jdk/1.8 > FLAVOR=native_bootstrap make > > There are two stages to the problem. A java command (or javac or javah) > gets stuck making forward progress and nearly all of its cpu time is in > sys time category. You can see this in top as 1500-3000% CPU time on > the java process. ktrace of the process in this state shows endless > sched_yield() calls. Debugging shows many threads in > pthread_cond_wait(3). The condition vars are configured to use > CLOCK_MONOTONIC. > > The second stage of the problem is when things lock up. While java is > spinning in this sched_yield() state, if you display the process arguments in > top (pressing the right arrow) you trip the lockups. top stops responding. > getty will reprompt if enter is pressed, but locks up if a username is > entered. > Most processes lock up when doing anything after this point. ddb ps at this > stage shows top waiting on vmmaplk and the rest of the stuck processes > waiting on sysctllk (sshd, systat, login).
So it seems the java process is holding the `sysctl_lock' for too long and block all other sysctl(2). This seems wrong to me. We should come up with a clever way to prevent vslocking too much memory. A single lock obviously doesn't fly with that many CPUs. Once that's improved it should be easier to debug the java issue. sched_yield() is called from _spinlock() in librthread. sparc64 should use the futex version of pthread_cond_wait(3) which doesn't rely on _spinlock() and sched_yield(2). So I'm puzzled. This seems like a poor man scheduling issue hoping that another thread/process will make progress. Can you figure out where this sched_yield() is coming from? > I tried bisecting when this was introduced but as I go back in time with > kernels it becomes more intermittent and I didn’t notice that so I would need > to redo the bisecting. I can say I have seen the problem reproduce as far > back as Feb 16th kernel. When I updated the jdk in late January I didn’t > notice > it but it could have been a lucky build as I tend to only do one > native_bootstrap > build of the jdk when updating as a way to test the resulting package. > > Here is some sample output of top, systat and ddb ps output on -current in > my last reproduction of the problem. > > load averages: 15.27, 4.25, 1.68 > > oracle.intricatesoftware.com 16:13:10 > 64 processes: 62 idle, 2 on processor > up 0 > days 00:04:58 > 64 CPUs: 0.0% user, 1.8% nice, 55.5% sys, 0.4% spin, 0.1% intr, 42.2% > idle > Memory: Real: 143M/2676M act/tot Free: 13G Cache: 2334M Swap: 0K/16G > PID USERNAME PRI NICE SIZE RES STATE WAIT TIME CPU COMMAND > 38582 _pbuild 10 5 290M 64M onproc/19 fsleep 17:16 2892.14% javac > > 3 users Load 15.27 4.25 1.68 oracle.intricatesof > 16:13:09 > > memory totals (in KB) PAGING SWAPPING Interrupts > real virtual free in out in out 12777 total > Active 146752 146752 13198032 ops vcons0 > All 2740160 2740160 29713104 pages 5 > vpci0:0 > 2 mpii0 > Proc:r d s w Csw Trp Sys Int Sof Flt forks mpii1 > 18 148 78089 18666 8090 94097 18891 fkppw 2 em0 > fksvm 31 ehci0 > 0.1%Int 0.3%Spn 55.1%Sys 1.8%Usr 42.7%Idle pwait 12737 clock > | | | | | | | | | | | relck > ============================> rlkok > noram > Namei Sys-cache Proc-cache No-cache ndcpy > Calls hits % hits % miss % fltcp > zfod > cow > Disks cd0 sd0 sd1 sd2 cd1 sd3 66409 fmin > seeks 88545 ftarg > xfers 3 itarg > speed 18K 2 wired > sec 0.0 pdfre > pdscn > pzidl 1 IPKTS > 13 kmape 1 OPKTS > > ddb{0}> ps > PID TID PPID UID S FLAGS WAIT COMMAND > 94135 299634 9252 0 3 0x82 sysctllk sshd > 38582 227559 44647 55 3 0x200083 fsleep javac > 38582 430054 44647 55 3 0x4200083 fsleep javac > 38582 454002 44647 55 7 0x4200003 javac > 38582 92205 44647 55 3 0x4200083 fsleep javac > 38582 391595 44647 55 7 0x4200003 javac > 38582 306671 44647 55 7 0x4200003 javac > 38582 444915 44647 55 7 0x4200003 javac > 38582 68842 44647 55 7 0x4200003 javac > 38582 210759 44647 55 7 0x4200003 javac > 38582 295002 44647 55 3 0x4200003 uobjlk javac > 38582 20089 44647 55 7 0x4200003 javac > 38582 426972 44647 55 7 0x4200003 javac > 38582 485651 44647 55 7 0x4200003 javac > 38582 198526 44647 55 7 0x4200003 javac > 38582 140392 44647 55 7 0x4200003 javac > 38582 426536 44647 55 7 0x4200003 javac > 38582 237845 44647 55 3 0x4200003 vmmaplk javac > 38582 11519 44647 55 7 0x4200003 javac > 38582 493801 44647 55 7 0x4200003 javac > 38582 431112 44647 55 7 0x4200003 javac > 38582 5954 44647 55 3 0x4200003 uobjlk javac > 38582 334521 44647 55 7 0x4200003 javac > 38582 63717 44647 55 7 0x4200003 javac > 38582 278840 44647 55 3 0x4200003 uobjlk javac > 38582 288942 44647 55 3 0x4200003 vmmaplk javac > 38582 358539 44647 55 3 0x4200003 vmmaplk javac > 38582 292341 44647 55 3 0x4200003 uobjlk javac > 38582 71353 44647 55 7 0x4200003 javac > 38582 173462 44647 55 7 0x4200003 javac > 38582 369162 44647 55 7 0x4200003 javac > 38582 103608 44647 55 3 0x4200003 uobjlk javac > 38582 283692 44647 55 7 0x4200003 javac > 38582 73296 44647 55 7 0x4200003 javac > 38582 107123 44647 55 7 0x4200003 javac > 38582 190345 44647 55 7 0x4200003 javac > 38582 519032 44647 55 7 0x4200003 javac > 38582 512468 44647 55 7 0x4200003 javac > 38582 30652 44647 55 7 0x4200003 javac > 38582 379236 44647 55 3 0x4200003 uobjlk javac > 38582 269178 44647 55 7 0x4200003 javac > 38582 268232 44647 55 3 0x4200003 uobjlk javac > 38582 352770 44647 55 7 0x4200003 javac > 38582 377632 44647 55 7 0x4200003 javac > 38582 244819 44647 55 7 0x4200003 javac > 38582 72610 44647 55 7 0x4200003 javac > 38582 469953 44647 55 3 0x4200083 fsleep javac > 38582 371383 44647 55 3 0x4200083 fsleep javac > 38582 158857 44647 55 3 0x4200083 fsleep javac > 38582 11735 44647 55 3 0x4200083 fsleep javac > 38582 84102 44647 55 3 0x4200083 fsleep javac > 38582 75248 44647 55 3 0x4200083 fsleep javac > 38582 375420 44647 55 3 0x4200083 fsleep javac > 38582 518610 44647 55 3 0x4200083 fsleep javac > 38582 127230 44647 55 3 0x4200003 vmmaplk javac > 38582 83423 44647 55 3 0x4200083 fsleep javac > 38582 159603 44647 55 3 0x4200083 fsleep javac > 38582 31091 44647 55 3 0x4200083 fsleep javac > 38582 390888 44647 55 3 0x4200083 fsleep javac > 38582 166886 44647 55 3 0x4200083 fsleep javac > 38582 377933 44647 55 3 0x4200083 fsleep javac > 38582 376867 44647 55 3 0x4200083 fsleep javac > 38582 110280 44647 55 3 0x4200083 fsleep javac > 38582 396501 44647 55 3 0x4200083 fsleep javac > 38582 337157 44647 55 3 0x4200083 fsleep javac > 38582 312539 44647 55 3 0x4200083 fsleep javac > 38582 439725 44647 55 3 0x4200083 fsleep javac > 38582 174728 44647 55 3 0x4200083 fsleep javac > 38582 350117 44647 55 3 0x4200083 fsleep javac > 38582 336583 44647 55 3 0x4200083 fsleep javac > 44647 53285 6389 55 3 0x100089 sigsusp sh > 6389 9627 3586 55 3 0x10008b sigsusp sh > 3586 519556 31484 55 3 0x83 wait gmake > 29401 282226 87417 55 3 0x100083 piperd tee > 31484 384291 87417 55 3 0x81 wait bash > 10686 220950 84161 55 3 0x100083 piperd tee > 87417 52900 84161 55 3 0x81 wait bash > 84161 354717 90894 55 3 0x83 wait bash > 90894 299418 54844 55 3 0x100089 sigsusp sh > 54844 38202 23322 55 3 0x10008b sigsusp sh > 23322 499463 12410 55 3 0x83 wait gmake > 2137 306483 5971 1000 3 0x83 sysctllk systat > 96354 374280 1 1000 3 0x1000b0 kqread ssh-agent > 5971 326285 53265 1000 3 0x10008b sigsusp ksh > 53265 95696 81543 1000 3 0x98 kqread sshd > 81543 262878 9252 0 3 0x82 kqread sshd > 12410 25695 53684 1000 3 0x10008b sigsusp make > 53684 389550 2559 1000 3 0x10008b sigsusp sh > 91269 101622 48618 1000 3 0x100003 vmmaplk top > 26730 50864 1 1000 3 0x1000b0 kqread ssh-agent > 48618 194268 38192 1000 3 0x10008b sigsusp ksh > 38192 94599 15809 1000 3 0x98 kqread sshd > 15809 420302 9252 0 3 0x82 kqread sshd > 2559 172546 11253 1000 3 0x10008b sigsusp make > 48347 451749 1 1000 3 0x1000b0 kqread ssh-agent > 11253 329919 75474 1000 3 0x10008b sigsusp ksh > 75474 434695 24864 1000 3 0x98 kqread sshd > 24864 460675 9252 0 3 0x82 kqread sshd > 80339 457654 1 0 3 0x83 sysctllk login > 2783 471804 1 0 3 0x100098 kqread cron > 13986 329572 1 99 3 0x1100090 kqread sndiod > 17161 216329 1 110 3 0x100090 kqread sndiod > 7125 459497 81420 95 3 0x1100092 kqread smtpd > 34588 306264 81420 103 3 0x1100092 kqread smtpd > 35539 431962 81420 95 3 0x1100092 kqread smtpd > 95046 110434 81420 95 3 0x100092 kqread smtpd > 75832 395854 81420 95 3 0x1100092 kqread smtpd > 90905 131444 81420 95 3 0x1100092 kqread smtpd > 81420 40917 1 0 3 0x100080 kqread smtpd > 9252 412804 1 0 3 0x88 kqread sshd > 77215 300303 47896 0 3 0x80 nfsd nfsd > 39163 328218 47896 0 3 0x80 nfsd nfsd > 18940 88416 47896 0 3 0x80 nfsd nfsd > 30770 448875 47896 0 3 0x80 nfsd nfsd > 47896 35491 1 0 3 0x80 netcon nfsd > 69834 381834 1172 0 3 0x80 kqread mountd > 1172 8898 1 0 3 0x100080 kqread mountd > 34849 159509 1 28 3 0x1100090 kqread portmap > 99111 374653 1 0 3 0x100080 kqread ntpd > 96514 463552 69056 83 3 0x100092 sysctllk ntpd > 69056 185686 1 83 3 0x1100092 sysctllk ntpd > 76215 96020 37258 74 3 0x1100092 bpf pflogd > 37258 158509 1 0 3 0x80 netio pflogd > 74134 93758 35337 73 3 0x1100090 kqread syslogd > 35337 436947 1 0 3 0x100082 netio syslogd > 49461 134918 1 0 3 0x100080 kqread resolvd > 15802 138340 35598 77 3 0x100092 kqread dhcpleased > 85374 145907 35598 77 3 0x100092 kqread dhcpleased > 35598 69070 1 0 3 0x80 kqread dhcpleased > 78965 485143 22355 115 3 0x100092 kqread slaacd > 49372 473630 22355 115 3 0x100092 kqread slaacd > 22355 252711 1 0 3 0x100080 kqread slaacd > 77472 293410 0 0 3 0x14200 bored smr > 96287 2177 0 0 3 0x14200 pgzero zerothread > 22397 479660 0 0 3 0x14200 aiodoned aiodoned > 40550 268537 0 0 3 0x14200 syncer update > 30711 491254 0 0 3 0x14200 cleaner cleaner > 19845 282487 0 0 3 0x14200 reaper reaper > 85959 130144 0 0 3 0x14200 pgdaemon pagedaemon > 70483 182566 0 0 3 0x14200 usbtsk usbtask > 51296 152380 0 0 3 0x14200 usbatsk usbatsk > 16787 444929 0 0 3 0x14200 bored sensors > 63429 82409 0 0 7 0x40014200 idle63 > 92645 493403 0 0 7 0x40014200 idle62 > 20350 375563 0 0 7 0x40014200 idle61 > 35222 74521 0 0 7 0x40014200 idle60 > 33426 375581 0 0 7 0x40014200 idle59 > 22679 177213 0 0 7 0x40014200 idle58 > 14639 386227 0 0 7 0x40014200 idle57 > 39400 120262 0 0 7 0x40014200 idle56 > 12654 7800 0 0 7 0x40014200 idle55 > 48608 174405 0 0 3 0x40014200 idle54 > 94678 113021 0 0 7 0x40014200 idle53 > 6170 359112 0 0 3 0x40014200 idle52 > 92056 451703 0 0 7 0x40014200 idle51 > 94062 149790 0 0 3 0x40014200 idle50 > 7490 352645 0 0 7 0x40014200 idle49 > 58618 321162 0 0 3 0x40014200 idle48 > 34596 30496 0 0 3 0x40014200 idle47 > 42019 493114 0 0 7 0x40014200 idle46 > 19753 346089 0 0 3 0x40014200 idle45 > 35289 255668 0 0 7 0x40014200 idle44 > 71157 135665 0 0 7 0x40014200 idle43 > 2489 156561 0 0 7 0x40014200 idle42 > 69267 449921 0 0 3 0x40014200 idle41 > 17078 23764 0 0 3 0x40014200 idle40 > 18986 140559 0 0 7 0x40014200 idle39 > 31565 508859 0 0 3 0x40014200 idle38 > 83892 503397 0 0 3 0x40014200 idle37 > 3971 218332 0 0 3 0x40014200 idle36 > 56087 426177 0 0 3 0x40014200 idle35 > 8255 404604 0 0 3 0x40014200 idle34 > 88769 308362 0 0 7 0x40014200 idle33 > 17805 369954 0 0 7 0x40014200 idle32 > 44764 388232 0 0 7 0x40014200 idle31 > 6184 164272 0 0 7 0x40014200 idle30 > 57793 246870 0 0 3 0x40014200 idle29 > 94847 282657 0 0 3 0x40014200 idle28 > 20730 274685 0 0 7 0x40014200 idle27 > 49977 358582 0 0 3 0x40014200 idle26 > 76662 491808 0 0 3 0x40014200 idle25 > 339 381654 0 0 7 0x40014200 idle24 > 95798 435838 0 0 7 0x40014200 idle23 > 17729 220014 0 0 3 0x40014200 idle22 > 32933 457100 0 0 3 0x40014200 idle21 > 93991 300506 0 0 7 0x40014200 idle20 > 83270 35155 0 0 3 0x40014200 idle19 > 113 190949 0 0 7 0x40014200 idle18 > 47202 13764 0 0 3 0x40014200 idle17 > 26572 32690 0 0 7 0x40014200 idle16 > 79156 94305 0 0 3 0x40014200 idle15 > 91078 227738 0 0 3 0x40014200 idle14 > 92007 190955 0 0 3 0x40014200 idle13 > 30258 465800 0 0 7 0x40014200 idle12 > 21174 286794 0 0 7 0x40014200 idle11 > 38572 384863 0 0 3 0x40014200 idle10 > 39753 266722 0 0 7 0x40014200 idle9 > 2402 328673 0 0 3 0x40014200 idle8 > 7204 135132 0 0 3 0x40014200 idle7 > 50857 147720 0 0 3 0x40014200 idle6 > 98253 405788 0 0 3 0x40014200 idle5 > 45666 511079 0 0 3 0x40014200 idle4 > 31437 507896 0 0 3 0x40014200 idle3 > 22223 410682 0 0 7 0x40014200 idle2 > 66020 259824 0 0 3 0x40014200 idle1 > 1702 438104 0 0 3 0x14200 bored softnet3 > 79408 470282 0 0 3 0x14200 bored softnet2 > 65184 187165 0 0 3 0x14200 bored softnet1 > 19984 214261 0 0 3 0x14200 bored softnet0 > 96155 318872 0 0 3 0x14200 bored systqmp > 56400 116597 0 0 3 0x14200 bored systq > 90431 390796 0 0 3 0x40014200 bored softclock > *64111 191058 0 0 7 0x40014200 idle0 > 18862 308472 0 0 3 0x14200 kmalloc kmthread > 1 421752 0 0 3 0x82 wait init > 0 0 -1 0 3 0x10200 scheduler swapper > >