Date: Wed, 26 Oct 2016 18:45:18 +0200 From: Ulrich =?utf-8?B?U3DDtnJsZWlu?= <uqs@FreeBSD.org> To: Kevin Oberman <rkoberman@gmail.com>, kib@FreeBSD.org, Hans Petter Selasky <hps@selasky.org>, FreeBSD Current <freebsd-current@freebsd.org> Subject: Re: 11.x deadlocking during pfault (was Re: FreeBSD 11.x grinds to a halt after about 48h of uptime) Message-ID: <20161026164518.GD2734@acme.spoerlein.net> In-Reply-To: <20161026164343.GC2734@acme.spoerlein.net> References: <20161015161848.GD2532@acme.spoerlein.net> <6926bd72-35c9-cb21-4785-b50a05e581be@selasky.org> <CAN6yY1toUPRt3zBBJtgDVoFJCmZdgoGaUXznS9BbooN9BbfeEQ@mail.gmail.com> <20161024174327.GB2734@acme.spoerlein.net> <20161026164343.GC2734@acme.spoerlein.net>
next in thread | previous in thread | raw e-mail | index | archive | help
On Wed, 2016-10-26 at 18:43:43 +0200, Ulrich Spörlein wrote: > On Mon, 2016-10-24 at 19:43:27 +0200, Ulrich Spörlein wrote: > > On Sat, 2016-10-15 at 09:36:27 -0700, Kevin Oberman wrote: > > > On Sat, Oct 15, 2016 at 9:26 AM, Hans Petter Selasky <hps@selasky.org> > > > wrote: > > > > > > > On 10/15/16 18:18, Ulrich Spörlein wrote: > > > > > > > >> Hey all, while 11.x is -STABLE now, this happens to my machine ever > > > >> since I upgraded it to 11-CURRENT years ago. I have no idea when this > > > >> started, actually, but what always happens is this: > > > >> > > > >> - System and X11 is up and running, I keep it running over night as I'm > > > >> too lazy to reboot and restart everthing. > > > >> - There's a bunch of xterms, Chrome, Clementine-Player and some other > > > >> programs running > > > >> - Coming back to the machine the next day (or the day after) it will > > > >> exit the screensaver just fine and then either I can use it for a couple > > > >> of seconds before it freezes, or it's pretty much dead already. The > > > >> mouse cursor still moves for a bit, but the also freezes (so it this a > > > >> GPU problem??) > > > >> > > > >> Now what I currently see on the screen is a clock widget stuck at 18:04 > > > >> but conky itself has last updated at 18:00:18 ... > > > >> > > > >> This time I had some SSH sessions from another machine to see some more > > > >> useful things. There was nothing in various logs under /var/log (I also > > > >> can't run dmesg anymore ...) > > > >> I had top(1) running in a loop, this is the last output: > > > >> > > > >> last pid: 25633; load averages: 0.27, 0.39, 0.36 up 1+23:03:28 > > > >> 18:00:12 > > > >> 202 processes: 2 running, 188 sleeping, 11 zombie, 1 waiting > > > >> > > > >> Mem: 8873M Active, 1783M Inact, 5072M Wired, 567M Buf, 132M Free > > > >> ARC: 1844M Total, 469M MFU, 268M MRU, 16K Anon, 96M Header, 1012M Other > > > >> Swap: 4096M Total, 2395M Used, 1701M Free, 58% Inuse > > > >> > > > >> > > > >> PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU > > > >> COMMAND > > > >> 11 root 8 155 ki31 0K 128K CPU0 0 364.6H 772.95% > > > >> idle > > > >> 3122 uqs 15 28 0 7113M 5861M uwait 0 > > > >> 94:44 13.96% chrome > > > >> 2887 uqs 28 22 0 1394M 237M > > > >> select 2 172:53 6.98% chrome > > > >> 2890 uqs 11 21 0 > > > >> 1034M 178M select 5 231:21 1.95% chrome > > > >> 1062 root 9 > > > >> 21 0 440M 47220K select 0 67:09 0.98% Xorg > > > >> 3002 uqs > > > >> 15 25 5 1159M 172M uwait 2 19:09 0.00% chrome > > > >> 3139 uqs 17 25 5 1163M 156M uwait 2 16:15 0.00% > > > >> chrome > > > >> 3001 uqs 18 25 5 1639M 575M uwait 0 16:05 0.00% > > > >> chrome > > > >> 12 root 24 -64 - 0K 384K WAIT -1 10:53 0.00% > > > >> intr > > > >> 3129 uqs 12 20 0 2820M 1746M uwait 6 8:36 0.00% > > > >> chrome > > > >> 2822 uqs 9 20 0 217M 81300K select 0 5:10 0.00% > > > >> conky > > > >> 3174 root 1 20 0 21532K 3188K select 0 4:20 0.00% > > > >> systat > > > >> 3130 uqs 16 20 0 1058M 131M uwait 4 3:03 0.00% > > > >> chrome > > > >> 2998 uqs 16 20 0 1110M 123M uwait 2 2:53 0.00% > > > >> chrome > > > >> 3165 uqs 10 20 0 1209M 215M uwait 6 2:52 0.00% > > > >> chrome > > > >> 3142 uqs 11 25 5 1344M 195M uwait 2 2:46 0.00% > > > >> chrome > > > >> 2876 uqs 19 20 0 580M 37164K select 3 2:42 0.00% > > > >> clementine-player > > > >> 20 root 2 -16 - 0K 32K psleep 6 2:25 0.00% > > > >> pagedaemon > > > >> > > > >> I also had systat -vm running and it continued to update its screen ... > > > >> for a short while, this is the last update before SSH died: > > > >> > > > >> > > > >> Mem usage: 0k%Phy 5%Kmem > > > >> Mem: KB REAL VIRTUAL VN PAGER SWAP > > > >> PAGER > > > >> Tot Share Tot Share Free in out in > > > >> out > > > >> Act 11051k 67868 71051992 255448 61840 count > > > >> All 11051k 67924 71058776 262100 pages > > > >> Proc: > > > >> Interrupts > > > >> r p d s w Csw Trp Sys Int Sof Flt ioflt 224 > > > >> total > > > >> 25 730 11 724 109 404 101 13 cow 2 > > > >> ehci0 16 > > > >> zfod 3 > > > >> ehci1 23 > > > >> 0.0%Sys 0.1%Intr 0.0%User 0.0%Nice 99.9%Idle ozfod 16 > > > >> cpu0:timer > > > >> | | | | | | | | | | %ozfod > > > >> xhci0 264 > > > >> daefr 3 em0 > > > >> 265 > > > >> 50 dtbuf prcfr 94 > > > >> hdac1 266 > > > >> Namei Name-cache Dir-cache 349167 desvn totfr > > > >> ahci0 270 > > > >> Calls hits % hits % 349155 numvn react 5 > > > >> cpu1:timer > > > >> 121 121 100 253501 frevn pdwak 1 > > > >> cpu2:timer > > > >> pdpgs 29 > > > >> cpu7:timer > > > >> Disks md0 ada0 ada1 pass0 pass1 pass2 intrn 12 > > > >> cpu3:timer > > > >> KB/t 0.00 0.00 0.00 0.00 0.00 0.00 5318892 wire 41 > > > >> cpu6:timer > > > >> tps 0 0 0 0 0 0 9261404 act 12 > > > >> cpu5:timer > > > >> MB/s 0.00 0.00 0.00 0.00 0.00 0.00 1598184 inact 6 > > > >> cpu4:timer > > > >> %busy 0 0 0 0 0 0 cache > > > >> vgapci0 > > > >> 61840 free > > > >> 712304 buf > > > >> > > > >> > > > >> Why do I have a Chrome tab using about 6G? What other sort of debugging > > > >> output can be helpful to get to the bottom of this? The machine still > > > >> responds to pings just fine, TCP connections get set up but the SSH > > > >> handshake never completes. > > > >> > > > >> This always happens between 30-50h and is super annoying and has been > > > >> going on for >1year. Help? > > > >> > > > >> Note, I cut the power to the monitor overnight to save electricity, can > > > >> this mess up something in the Radeon card or X server? What combinations > > > >> would be most useful to try next? > > > >> > > > >> > > > > Hi, > > > > > > > > Sounds like a memory leak. Can you track the memory use over time? > > > > > > > > Did you look at the output from: > > > > > > > > vmstat -m ? > > > > > > > > --HPS > > > > > > > > > I have noted significant memory leakage in chromium for some time. If I > > > leave it running overnight, my system is essentially frozen. If I terminate > > > the chromium process, it slowly comes back to life. I always keep a gkrellm > > > session on-screen where the memory and swap utilization is continuously > > > displayed and that clearly shows resources declining. > > > > That is not what is happening to my system though, it actually > > deadlocks. There's no way to recover from it, it seems. > > > > So I killed Chromium overnight each day, and I'm at this: > > > > % top -Sbores > > last pid: 44526; load averages: 0.10, 0.11, 0.56 up 7+09:53:30 19:33:25 > > 156 processes: 2 running, 153 sleeping, 1 waiting > > > > Mem: 315M Active, 550M Inact, 5671M Wired, 515M Buf, 9324M Free > > ARC: 1852M Total, 541M MFU, 196M MRU, 16K Anon, 93M Header, 1022M Other > > Swap: 4096M Total, 2186M Used, 1910M Free, 53% Inuse > > > > > > PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND > > 2755 uqs 10 20 0 1697M 311M select 1 47:23 0.00% conky > > 2736 uqs 32 20 0 699M 116M select 7 94:29 0.00% clementine-player > > 3000 uqs 12 20 0 1126M 69380K select 5 9:48 0.00% digikam > > 960 root 9 20 0 448M 59076K select 0 250:22 0.00% Xorg > > 72608 uqs 8 20 0 939M 55432K uwait 5 0:01 0.00% chrome > > 72599 uqs 9 52 0 929M 55116K uwait 0 0:00 0.00% chrome > > 2567 root 1 20 0 89948K 42964K select 1 1:51 0.00% bsnmpd > > 70476 uqs 1 20 0 93656K 25712K select 2 0:05 0.00% xterm > > 2730 uqs 5 20 0 208M 14988K select 1 0:22 0.00% clock-applet > > 880 root 1 20 0 22628K 12500K select 3 0:20 0.00% ntpd > > 2726 uqs 4 20 0 206M 12456K select 6 0:09 0.00% mateweather-applet > > 44352 uqs 1 20 0 75224K 12348K select 4 0:00 0.00% xterm > > 43049 uqs 1 20 0 75224K 11792K select 5 0:00 0.00% xterm > > 3074 uqs 2 20 0 308M 9692K select 1 0:02 0.00% kdeinit4 > > 2671 uqs 1 20 0 144M 9488K select 1 0:13 0.00% openbox > > 3072 uqs 1 20 0 210M 8284K select 3 0:00 0.00% kdeinit4 > > 2724 uqs 4 20 0 154M 8256K select 2 0:19 0.00% wnck-applet > > 2701 uqs 5 20 0 177M 8144K select 2 0:01 0.00% mate-panel > > > > > > 7d running, pretty good. But look closer, the system is doing pretty > > much nothing but did swap out 2G. What? > > > > > Try closing your chromium at night and see if that fixes the problem. > > > > It's better, but I'm not sure it's a real fix. I've now turned off > > "hardware acceleration" in Chromium, though chrome://gpu didn't real > > inspire confidence that it was actually using any h/w accel at all. > > > > > > > If you have never tried gkrellm (sysutils/gkrellm2), it is a the best > > > system monitor I have found. though pulls in a lot of dependencies. It also > > > can run as a server with remote systems displaying the data. Handy to > > > monitor servers. > > > > I had a cacti-setup that would also monitor my workstation (through a > > OpenVPN tunnel), but that has bit-rotted and Apache only gives me 500s > > on that cacti URL and nothing in the logs, oh well ...) > > > > Hooking up a serial console and testing whether DDB works is probably > > the next best step to take ... > > Sigh, I forgot to shut down Chrome overnight, and my system is > deadlocked again. I can still switch virtual desktops in X11 and a > running xterm accepts keyboard input, but it is 18:35 now and I see that > my X11 clock has last updated at 17:18 and conky is stuck at 17:14:11 > > my top-in-a-loop is stuck here and no longer loops: > > last pid: 73731; load averages: 0.23, 0.24, 0.23 up 9+07:34:15 17:14:10 > 160 processes: 3 running, 146 sleeping, 11 zombie > > Mem: 9302M Active, 763M Inact, 5682M Wired, 752M Buf, 113M Free > ARC: 1731M Total, 549M MFU, 129M MRU, 16K Anon, 91M Header, 963M Other > Swap: > > > PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND > 960 root 9 21 0 451M 55796K CPU7 7 299:15 2.98% Xorg > 53884 uqs 27 22 0 904M 250M CPU4 4 105:05 2.98% chrome > 54081 uqs 15 21 0 3601M 2527M uwait 6 38:11 0.98% chrome > 2736 uqs 33 20 0 697M 84620K select 5 95:38 0.00% clementine-player > 2755 uqs 10 20 0 2111M 721M select 0 60:47 0.00% conky > 78943 uqs 1 20 0 21532K 3328K select 7 13:12 0.00% systat > 54048 uqs 15 25 5 1093M 159M uwait 4 9:51 0.00% chrome > 3000 uqs 12 20 0 1126M 53248K select 7 9:50 0.00% digikam > 53999 uqs 19 25 5 1525M 514M uwait 5 6:28 0.00% chrome > 2703 uqs 1 20 0 169M 5948K select 0 5:40 0.00% mate-volume-control > 2707 uqs 1 20 0 60240K 2516K select 7 5:21 0.00% autocutsel > 54077 uqs 15 20 0 1803M 821M uwait 6 3:51 0.00% chrome > 78869 uqs 1 20 0 93480K 6636K select 7 3:38 0.00% sshd > 38396 uqs 1 20 0 75224K 3896K select 0 3:18 0.00% xterm > 2567 root 1 20 0 89948K 43892K select 6 2:25 0.00% bsnmpd > 876 root 9 52 0 30120K 3468K uwait 7 2:20 0.00% nscd > 883 root 1 20 0 10444K 1708K select 0 2:16 0.00% powerd > 2586 haldaemon 2 20 0 56620K 3920K select 1 2:04 0.00% hald > > > systat -vm: > > 10 users Load 0.21 0.23 0.23 Oct 26 17:14 > Mem usage: 0k%Phy 5%Kmem > Mem: KB REAL VIRTUAL VN PAGER SWAP PAGER > Tot Share Tot Share Free in out in out > Act 10545k 51036 67451248 249344 61912 count 120 3 > All 10550k 55504 67480212 275720 pages 807 3 > Proc: Interrupts > r p d s w Csw Trp Sys Int Sof Flt 149 ioflt 845 total > 6 781 12 9327 6923 24k 318 18 6649 20 cow 2 ehci0 16 > 5064 zfod 3 ehci1 23 > 4.7%Sys 0.0%Intr 1.7%User 0.0%Nice 93.6%Idle 16 ozfod 106 cpu0:timer > | | | | | | | | | | %ozfod xhci0 264 > ==> 927 daefr 45 em0 265 > 51 dtbuf 545 prcfr 94 hdac1 266 > Namei Name-cache Dir-cache 349167 desvn 1787 totfr 175 ahci0 270 > Calls hits % hits % 337762 numvn react 50 cpu1:timer > 935 901 96 170078 frevn pdwak 48 cpu3:timer > 1435985 pdpgs 66 cpu2:timer > Disks md0 ada0 ada1 pass0 pass1 pass2 intrn 77 cpu7:timer > KB/t 0.00 22.59 0.00 0.00 0.00 0.00 5819100 wire 75 cpu4:timer > tps 17 168 0 0 0 0 9723008 act 51 cpu6:timer > MB/s 0.00 3.70 0.00 0.00 0.00 0.00 636300 inact 53 cpu5:timer > %busy 0 3 0 0 0 0 cache vgapci0 > 61912 free > 770732 buf > > > I'm unable to scroll back the vmstat -m output in my tmux pane (running on a > different system, this is super strange), so all I can show is this: > > > inodedep 16 12293K - 2770872 512 > bmsafemap 9 49K - 2136243 256,8192 > newblk 28 24582K - 4111401 256 > indirdep 4 1K - 865983 128,16384 > freefrag 6 1K - 682027 128 > freeblks 3 1K - 1318985 256 > freefile 3 1K - 1272832 64 > diradd 2 1K - 1306741 128 > mkdir 0 0K - 5120 128 > dirrem 0 0K - 1305358 128 > newdirblk 0 0K - 2610 64 > freework 9 1K - 1566489 64,128 > sbdep 0 0K - 45661 64 > savedino 0 0K - 186280 256 > softdep 6 3K - 6 512 > ufs_dirhash 1533 767K - 109513 16,32,64,128,256,512,1024,2048,4096 > ufs_quota 1 2048K - 1 > ufs_mount 18 55K - 18 512,2048,4096,8192 > vm_pgdata 1 2048K - 2 128 > UMAHash 23 5385K - 108 512,1024,2048,4096,8192,16384,32768,65536 > memdesc 1 4K - 1 4096 > atkbddev 2 1K - 2 64 > entropy 1 1K - 894489 32,4096 > apmdev 1 1K - 1 128 > madt_table 0 0K - 1 4096 > SCSI ENC 25 100K - 120744 16,64,256,2048,32768 > io_apic 1 2K - 1 2048 > MCA 18 3K - 18 64,128 > msi 16 2K - 16 128 > nexusdev 5 1K - 5 16 > hdaa 5 54K - 5 2048,16384,32768 > hdac 1 1K - 1 1024 > hdacc 1 1K - 1 32 > linux 29 2K - 29 64 > solaris 295750 228696K - 140520323 16,32,64,128,256,512,1024,2048,4096,8192,32768 > kstat_data 6 1K - 6 64 > eli data 22 4K - 6218901 64,256,512,1024,2048,4096,8192,16384,32768,65536 > ksem 1 8K - 1 8192 > nullfs_hash 1 2048K - 1 > nullfs_node 9 1K - 41 64 > nullfs_mount 9 1K - 9 32 > fdesc_mount 1 1K - 1 16 > gem_name 46 14K - 122 32,4096 > drm_global 2 1K - 2 128,256 > drm_dma 1 1K - 1 32 > drm_sarea 1 1K - 1 16 > drm_driver 91 2278K - 125 16,32,64,128,256,512,1024,2048,4096,8192,32768 > drm_minor 2 1K - 2 128 > drm_files 1 1K - 3 512 > drm_ctxbitmap 1 4K - 1 4096 > drm_sman 41 6K - 42 128 > drm_hashtab 3 4129K - 4 128,32768 > drm_kms 69 19K - 163 16,32,64,128,256,512,2048,4096,8192 > drm_vblank 7 1K - 7 32,256 > ttm_pd 16 17K - 18 16,128,2048,65536 > ttm_rman 2 1K - 2 256 > ttm_zone 2 1K - 2 64 > ttm_poolmgr 1 1K - 1 512 > > > Now what? > > The xterm I have running locally with a stuck top is showing the top 3 chrome > processes in pfault state and it has "Swap: 11M In" in the header, so clearly > 11.x is prone to deadlock during page faults and or swapping. It has last > updated on 17:14:13 (compare to the other top at 17:14:10 not showing pfault > state yet). Addendum: I still see the HDD indication light flickering every couple of seconds, so something is still doing I/O. My SSH sessions into the machine haven't time out, and the screensaver (just DPMS blank) is also still kicking in correctly.
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20161026164518.GD2734>