Re: r358252 causes intermittent hangs where processes are stuck sleeping on btalloc

From: Ryan Libby <rlibby_at_freebsd.org>
Date: Mon, 15 Jun 2020 18:44:37 -0700
On Mon, Jun 15, 2020 at 5:06 PM Rick Macklem <rmacklem_at_uoguelph.ca> wrote:
>
> Rick Macklem wrote:
> >r358098 will hang fairly easily, in 1-3 cycles of the kernel build over NFS.
> >I thought this was the culprit, since I did 6 cycles of r358097 without a hang.
> >However, I just got a hang with r358097, but it looks rather different.
> >The r358097 hang did not have any processes sleeping on btalloc. They
> >appeared to be waiting on two different locks in the buffer cache.
> >As such, I think it might be a different problem. (I'll admit I should have
> >made notes about this one before rebooting, but I was flustrated that
> >it happened and rebooted before looking at it mush detail.)
> Ok, so I did 10 cycles of the kernel build over NFS for r358096 and never
> got a hang.
> --> It seems that r358097 is the culprit and r358098 makes it easier
>       to reproduce.
>       --> Basically runs out of kernel memory.
>
> It is not obvious if I can revert these two commits without reverting
> other ones, since there were a bunch of vm changes after these.
>
> I'll take a look, but if you guys have any ideas on how to fix this, please
> let me know.
>
> Thanks, rick

Interesting.  Could you try re-adding UMA_ZONE_NOFREE to the vmem btag
zone to see if that rescues it, on whatever base revision gets you a
reliable repro?

>
> Jeff, to fill you in, I have been getting intermittent hangs on a Pentium 4
> (single core i386) with 1.25Gbytes ram when doing kernel builds using
> head kernels from this winter. (I also saw one when doing a kernel build
> on UFS, so they aren't NFS specific, although easier to reproduce that way.)
> After a typical hang, there will be a bunch of processes sleeping on "btalloc"
> and several processes holding the following lock:
> exclusive sx lock _at_ vm/vm_map.c:4761
> - I have seen hangs where that is the only lock held by any process except
>    the interrupt thread.
> - I have also seen processes waiting on the following locks:
> kern/subr_vmem.c:1343
> kern/subr_vmem.c:633
>
> I can't be absolutely sure r358098 is the culprit, but it seems to make the
> problem more reproducible.
>
> If anyone has a patch suggestion, I can test it.
> Otherwise, I will continue to test r358097 and earlier, to try and see what hangs
> occur. (I've done 8 cycles of testing of r356776 without difficulties, but that
> doesn't guarantee it isn't broken.)
>
> There is a bunch more of the stuff I got for Kostik and Ryan below.
> I can do "db" when it is hung, but it is a screen console, so I need to
> transcribe the output to email by hand. (ie. If you need something
> specific I can do that, but trying to do everything Kostik and Ryan asked
> for isn't easy.)
>
> rick
>
>
>
> Konstantin Belousov wrote:
> >On Fri, May 22, 2020 at 11:46:26PM +0000, Rick Macklem wrote:
> >> Konstantin Belousov wrote:
> >> >On Wed, May 20, 2020 at 11:58:50PM -0700, Ryan Libby wrote:
> >> >> On Wed, May 20, 2020 at 6:04 PM Rick Macklem <rmacklem_at_uoguelph.ca> wrote:
> >> >> >
> >> >> > Hi,
> >> >> >
> >> >> > Since I hadn't upgraded a kernel through the winter, it took me a while
> >> >> > to bisect this, but r358252 seems to be the culprit.
> No longer true. I succeeded in reproducing the hang to-day running a
> r358251 kernel.
>
> I haven't had much luck sofar, but see below for what I have learned.
>
> >> >> >
> >> >> > If I do a kernel build over NFS using my not so big Pentium 4 (single core,
> >> >> > 1.25Gbytes RAM, i386), about every second attempt will hang.
> >> >> > When I do a "ps" in the debugger, I see processes sleeping on btalloc.
> >> >> > If I revert to r358251, I cannot reproduce this.
> As above, this is no longer true.
>
> >> >> >
> >> >> > Any ideas?
> >> >> >
> >> >> > I can easily test any change you might suggest to see if it fixes the
> >> >> > problem.
> >> >> >
> >> >> > If you want more debug info, let me know, since I can easily
> >> >> > reproduce it.
> >> >> >
> >> >> > Thanks, rick
> >> >>
> >> >> Nothing obvious to me.  I can maybe try a repro on a VM...
> >> >>
> >> >> ddb ps, acttrace, alltrace, show all vmem, show page would be welcome.
> >> >>
> >> >> "btalloc" is "We're either out of address space or lost a fill race."
> From what I see, I think it is "out of address space".
> For one of the hangs, when I did "show alllocks", everything except the
> intr thread, was waiting for the
> exclusive sx lock _at_ vm/vm_map.c:4761
>
> >> >
> >> >Yes, I would be not surprised to be out of something on 1G i386 machine.
> >> >Please also add 'show alllocks'.
> >> Ok, I used an up to date head kernel and it took longer to reproduce a hang.
> Go down to Kostik's comment about kern.maxvnodes for the rest of what I've
> learned. (The time it takes to reproduce one of these varies greatly, but I usually
> get one within 3 cycles of a full kernel build over NFS. I have had it happen
> once when doing a kernel build over UFS.)
>
> >> This time, none of the processes are stuck on "btalloc".
> > I'll try and give you most of the above, but since I have to type it in by hand
> > from the screen, I might not get it all. (I'm no real typist;-)
> > > show alllocks
> > exclusive lockmgr ufs (ufs) r = 0 locked _at_ kern/vfs_subr.c: 3259
> > exclusive lockmgr nfs (nfs) r = 0 locked _at_ kern/vfs_lookup.c:737
> > exclusive sleep mutex kernel area domain (kernel arena domain) r = 0 locked _at_ kern/subr_vmem.c:1343
> > exclusive lockmgr bufwait (bufwait) r = 0 locked _at_ kern/vfs_bio.c:1663
> > exclusive lockmgr ufs (ufs) r = 0 locked _at_ kern/vfs_subr.c:2930
> > exclusive lockmgr syncer (syncer) r = 0 locked _at_ kern/vfs_subr.c:2474
> > Process 12 (intr) thread 0x.. (1000008)
> > exclusive sleep mutex Giant (Giant) r = 0 locked _at_ kern/kern_intr.c:1152
> >
> > > ps
> > - Not going to list them all, but here are the ones that seem interesting...
> > 18 0 0 0 DL vlruwt 0x11d939cc [vnlru]
> > 16 0 0 0 DL (threaded)               [bufdaemon]
> > 100069  D  qsleep                      [bufdaemon]
> > 100074  D  -                               [bufspacedaemon-0]
> > 100084  D  sdflush  0x11923284 [/ worker]
> > - and more of these for the other UFS file systems
> > 9 0 0 0   DL psleep  0x1e2f830  [vmdaemon]
> > 8 0 0 0   DL (threaded)               [pagedaemon]
> > 100067  D   psleep 0x1e2e95c   [dom0]
> > 100072  D   launds 0x1e2e968   [laundry: dom0]
> > 100073  D   umarcl 0x12cc720   [uma]
> > … a bunch of usb and cam ones
> > 100025  D   -           0x1b2ee40  [doneq0]
> > …
> > 12 0 0 0 RL  (threaded)               [intr]
> > 100007  I                                     [swi6: task queue]
> > 100008  Run           CPU 0           [swi6: Giant taskq]
> > …
> > 100000  D   swapin 0x1d96dfc    [swapper]
> > - and a bunch more in D state.
> > Does this mean the swapper was trying to swap in?
> >
> > > acttrace
> > - just shows the keyboard
> > kdb_enter() at kdb_enter+0x35/frame
> > vt_kbdevent() at vt_kdbevent+0x329/frame
> > kdbmux_intr() at kbdmux_intr+0x19/frame
> > taskqueue_run_locked() at taskqueue_run_locked+0x175/frame
> > taskqueue_run() at taskqueue_run+0x44/frame
> > taskqueue_swi_giant_run(0) at taskqueue_swi_giant_run+0xe/frame
> > ithread_loop() at ithread_loop+0x237/frame
> > fork_exit() at fork_exit+0x6c/frame
> > fork_trampoline() at 0x../frame
> >
> > > show all vmem
> > vmem 0x.. 'transient arena'
> >   quantum: 4096
> >   size:  23592960
> >   inuse: 0
> >   free: 23592960
> >   busy tags:   0
> >   free tags:    2
> >                      inuse        size       free        size
> >   16777216   0               0           1            23592960
> > vmem 0x.. 'buffer arena'
> >   quantum:  4096
> >   size:   94683136
> >   inuse: 94502912
> >   free: 180224
> >   busy tags:    1463
> >   free tags:      3
> >                        inuse      size         free        size
> >   16384           2             32768     1             16384
> >   32768           39           1277952 1              32768
> >   65536            1422       93192192 0           0
> >   131072          0             0            1              131072
> > vmem 0x.. 'i386trampoline'
> >   quantum:      1
> >   size:               24576
> >   inuse:             20860
> >   free:               3716
> >   busy tags:     9
> >   free tags:      3
> >                        inuse      size      free      size
> >   32                 1             48        1           52
> >   64                  2            208       0           0
> >   128                2            280       0            0
> >   2048              1            2048     1           3664
> >   4096              2            8192     0           0
> >   8192              1            10084   0           0
> > vmem 0x.. 'kernel rwx arena'
> >   quantum:    4096
> >   size: 0
> >   inuse: 0
> >   free:   0
> >   busy tags: 0
> >   free tags:  0
> > vmem 0x.. 'kernel area dom'
> >   quantum:  4096
> >   size: 56623104
> >   inuse: 56582144
> >>   free: 40960
> >>   busy tags: 11224
> >>   free tags: 3
> >I think this is the trouble.
> >
> >Did you tried to reduce kern.maxvnodes ?  What is the default value for
> >the knob on your machine ?
> The default is 84342.
> I have tried 64K, 32K and 128K and they all hung sooner or later.
> For the 32K case, I did see vnodes being recycled for a while before it got hung,
> so it isn't just when it hits the limit.
>
> Although it is much easier for me to reproduce on an NFS mount, I did see
> a hang while doing a kernel build on UFS (no NFS mount on the machine at
> that time).
>
> So, I now know that the problem pre-dates r358252 and is not NFS specific.
>
> I'm not bisecting back further to try and isolate the commit that causes this.
> (Unfortunately, each test cycle can take days. I now know that I have to do
> several of these kernel builds, which take hours each, to see if a hang is going
> to happen.)
>
> I'll post if/when I have more, rick
>
> We scaled maxvnodes for ZFS and UFS, might be NFS is even more demanding,
> having larger node size.
>
> >                 inuse     size          free              size
> >   4096      11091    45428736 0                 0
> >   8192       63         516096     0                 0
> >   16384     12          196608    0                  0
> >   32768      6           196608    0                  0
> >   40960      2           81920      1                  40960
> >   65536      16         1048576   0                 0
> >   94208      1            94208      0                 0
> >   110592     1          110592     0                 0
> >   131072      15       2441216    0                0
> >   262144      15       3997696    0                 0
> >   524288      1         524288      0                 0
> >   1048576     1        1945600     0                0
> > vmem 0x.. 'kernel arena'
> >   quantum: 4096
> >   size: 390070272
> >   inuse: 386613248
> >   free: 3457024
> >   busy tags:  873
> >   free tags:   3
> >                    inuse       size         free        size
> > 4096           35           143360    1            4096
> > 8192           2              16384      2           16384
> > 12288         1              12288      0           0
> > 16384         30             491520   0           0
> > 20480         140           2867200  0          0
> > 65536          1              65536     0           0
> > 131072        631          82706432 0         0
> > 1048576      0              0               1         1339392
> > 2097152      27            56623104   1        2097152
> > 8388608      1              13774848    0       0
> > 16777216    3              74883072   0        0
> > 33554432    1              36753408   0        0
> > 67108864    1              118276096  0       0
> >
> > > alltrace
> > - I can't face typing too much more, but I'll put a few
> >   here that look interesting
> >
> > - for csh
> > sched_switch()
> > mi_switch()
> > kern_yield()
> > getblkx()
> > breadn_flags()
> > ffs_update()
> > ufs_inactive()
> > VOP_INACTIVE()
> > vinactivef()
> > vput_final()
> > vm_object_deallocate()
> > vm_map_process_deferred()
> > kern_munmap()
> > sys_munmap()
> >
> > - For cc
> > sched_switch()
> > mi_switch()
> > sleepq_switch()
> > sleepq_timedwait()
> > _sleep()
> > pause_sbt()
> > vmem_bt_alloc()
> > keg_alloc_slab()
> > zone_import()
> > cache_alloc()
> > cache_alloc_retry()
> > uma_zalloc_arg()
> > bt_fill()
> > vmem_xalloc()
> > vmem_alloc()
> > kmem_alloc()
> > kmem_malloc_domainset()
> > page_alloc()
> > keg_alloc_slab()
> > zone_import()
> > cache_alloc()
> > cache_alloc_retry()
> > uma_zalloc_arg()
> > nfscl_nget()
> > nfs_create()
> > vop_sigdefer()
> > nfs_vnodeops_bypass()
> > VOP_CREATE_APV()
> > vn_open_cred()
> > vn_open()
> > kern_openat()
> > sys_openat()
> >
> > Then there are a bunch of these... for cc, make
> > sched_switch()
> > mi_switch()
> > sleepq_switch()
> > sleepq_catch_signals()
> > sleepq_wait_sig()
> > kern_wait6()
> > sys_wait4()
> >
> > - for vnlru
> > sched_switch()
> > mi_switch()
> > sleepq_switch()
> > sleepq_timedwait()
> > _sleep()
> > vnlru_proc()
> > fork_exit()
> > fork_trampoline()
> >
> > - for syncer
> > sched_switch()
> > mi_switch()
> > critical_exit_preempt()
> > intr_event_handle()
> > intr_execute_handlers()
> > lapic_handle_intr()
> > Xapic_isr1()
> > - interrupt
> > memset()
> > cache_alloc()
> > cache_alloc_retry()
> > uma_zalloc_arg()
> > vmem_xalloc()
> > vmem_bt_alloc()
> > keg_alloc_slab()
> > zone_import()
> > cache_alloc()
> > cache_alloc_retry()
> > uma_zalloc_arg()
> > bt_fill()
> > vmem_xalloc()
> > vmem_alloc()
> > bufkva_alloc()
> > getnewbuf()
> > getblkx()
> > breadn_flags()
> > ffs_update()
> > ffs_sync()
> > sync_fsync()
> > VOP_FSYNC_APV()
> > sched_sync()
> > fork_exit()
> > fork_trampoline()
> >
> > - For bufdaemon (a bunch of these)
> > sched_switch()
> > mi_switch()
> > sleepq_switch()
> > sleepq_timedwait()
> > _sleep()
> > buf_daemon()
> > fork_exit()
> > fork_trampoline()
> >
> > vmdaemon and pagedaemon are basically just like above,
> > sleeping in
> > vm_daemon()
> > or
> > vm_pageout_worker()
> > or
> > vm_pageout_laundry_worker()
> > or
> > uma_reclaim_worker()
> >
> > That's all the typing I can take right now.
> > I can probably make this happen again if you want more specific stuff.
> >
> > rick
> >
> >
> >
> >
> _______________________________________________
> freebsd-current_at_freebsd.org mailing list
> https://lists.freebsd.org/mailman/listinfo/freebsd-current
> To unsubscribe, send any mail to "freebsd-current-unsubscribe_at_freebsd.org"
> _______________________________________________
> freebsd-current_at_freebsd.org mailing list
> https://lists.freebsd.org/mailman/listinfo/freebsd-current
> To unsubscribe, send any mail to "freebsd-current-unsubscribe_at_freebsd.org"
> _______________________________________________
> freebsd-current_at_freebsd.org mailing list
> https://lists.freebsd.org/mailman/listinfo/freebsd-current
> To unsubscribe, send any mail to "freebsd-current-unsubscribe_at_freebsd.org"
Received on Mon Jun 15 2020 - 23:44:51 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:41:24 UTC