Re: svn commit: r360233 - in head: contrib/jemalloc . . . : This partially breaks a 2-socket 32-bit powerpc (old PowerMac G4) based on head -r360311

From: Mark Millard <marklmi_at_yahoo.com>
Date: Thu, 7 May 2020 00:46:30 -0700
[__je_sz_size2index_tab seems messed up in 2 of the
asserting contexts: first 384 are zero in both. More
before that is also messed up (all zero). I show the
details later below.]

On 2020-May-6, at 16:57, Mark Millard <marklmi at yahoo.com> wrote:

> [This explores process crashes that happen during system
> shutdown, in a context not having MALLOC_PRODUCTION= .
> So assert failures are reported as the stopping points.]
> 
> It looks like shutdown -p now, shutdown -r now, and the
> like can lead some processes to assert during their exit
> attempt, including a sshd failure (that I've not seen
> before), rpcbind, and nfsd. I show information about the
> observed asserts for those below.
> 
> 
> sshd hit an assert, failing slab == extent_slab_get(extent) :
> 
> (gdb) bt 
> #0  thr_kill () at thr_kill.S:4
> #1  0x50927170 in __raise (s=6) at /usr/src/lib/libc/gen/raise.c:52
> #2  0x50886cc0 in abort () at /usr/src/lib/libc/stdlib/abort.c:67
> #3  0x508834b0 in arena_dalloc (tsdn=<optimized out>, ptr=<optimized out>, tcache=<optimized out>, alloc_ctx=<optimized out>, slow_path=<optimized out>)
>    at /usr/src/contrib/jemalloc/include/jemalloc/internal/arena_inlines_b.h:315
> #4  idalloctm (tsdn=0x500dd040, ptr=0x5008a180, tcache=0x500dd160, alloc_ctx=<optimized out>, is_internal=<optimized out>, slow_path=<optimized out>)
>    at /usr/src/contrib/jemalloc/include/jemalloc/internal/jemalloc_internal_inlines_c.h:118
> #5  0x5087b0a4 in ifree (tsd=0x500dd040, ptr=0x5008a180, tcache=0x500dd160, slow_path=<optimized out>) at jemalloc_jemalloc.c:2590
> #6  0x5087acac in __je_free_default (ptr=0x5008a180) at jemalloc_jemalloc.c:2784
> #7  0x5087b294 in __free (ptr=0x5008a180) at jemalloc_jemalloc.c:2852
> #8  0x10029464 in server_accept_loop (config_s=<optimized out>, sock_in=<optimized out>, sock_out=<optimized out>, newsock=<optimized out>) at /usr/src/crypto/openssh/sshd.c:1185
> #9  main (ac=<optimized out>, av=0xffffde3c) at /usr/src/crypto/openssh/sshd.c:2009
> 
> . . .
> (gdb) up
> #2  0x50886cc0 in abort () at /usr/src/lib/libc/stdlib/abort.c:67
> 67		(void)raise(SIGABRT);
> (gdb) up
> #3  0x508834b0 in arena_dalloc (tsdn=<optimized out>, ptr=<optimized out>, tcache=<optimized out>, alloc_ctx=<optimized out>, slow_path=<optimized out>)
>    at /usr/src/contrib/jemalloc/include/jemalloc/internal/arena_inlines_b.h:315
> 315			assert(slab == extent_slab_get(extent));
> 
> (gdb) list
> 310			rtree_ctx = tsd_rtree_ctx(tsdn_tsd(tsdn));
> 311			extent_t *extent = rtree_extent_read(tsdn, &extents_rtree,
> 312			    rtree_ctx, (uintptr_t)ptr, true);
> 313			assert(szind == extent_szind_get(extent));
> 314			assert(szind < SC_NSIZES);
> 315			assert(slab == extent_slab_get(extent));
> 316		}
> 317	
> 318		if (likely(slab)) {
> 319			/* Small allocation. */
> 
> More fully:
> 
> 285	JEMALLOC_ALWAYS_INLINE void
> 286	arena_dalloc(tsdn_t *tsdn, void *ptr, tcache_t *tcache,
> 287	    alloc_ctx_t *alloc_ctx, bool slow_path) {
> 288		assert(!tsdn_null(tsdn) || tcache == NULL);
> 289		assert(ptr != NULL);
> 290	
> 291		if (unlikely(tcache == NULL)) {
> 292			arena_dalloc_no_tcache(tsdn, ptr);
> 293			return;
> 294		}
> 295	
> 296		szind_t szind;
> 297		bool slab;
> 298		rtree_ctx_t *rtree_ctx;
> 299		if (alloc_ctx != NULL) {
> 300			szind = alloc_ctx->szind;
> 301			slab = alloc_ctx->slab;
> 302			assert(szind != SC_NSIZES);
> 303		} else {
> 304			rtree_ctx = tsd_rtree_ctx(tsdn_tsd(tsdn));
> 305			rtree_szind_slab_read(tsdn, &extents_rtree, rtree_ctx,
> 306			    (uintptr_t)ptr, true, &szind, &slab);
> 307		}
> 308	
> 309		if (config_debug) {
> 310			rtree_ctx = tsd_rtree_ctx(tsdn_tsd(tsdn));
> 311			extent_t *extent = rtree_extent_read(tsdn, &extents_rtree,
> 312			    rtree_ctx, (uintptr_t)ptr, true);
> 313			assert(szind == extent_szind_get(extent));
> 314			assert(szind < SC_NSIZES);
> 315			assert(slab == extent_slab_get(extent));
> 316		}
> 317	
> 318		if (likely(slab)) {
> 319			/* Small allocation. */
> 320			tcache_dalloc_small(tsdn_tsd(tsdn), tcache, ptr, szind,
> 321			    slow_path);
> 322		} else {
> 323			arena_dalloc_large(tsdn, ptr, tcache, szind, slow_path);
> 324		}
> 325	}

The following are only shown for contrast with the later
cases of lots of zeros showing up where below shows
non-zero values (taken from sshd.core, which failed
differently):

(gdb) x/4x __je_arenas+16368/4
0x50981ab0 <__je_arenas+16368>:	0x00000000	0x00000000	0x00000000	0x00000009
(gdb) print/x __je_arenas_lock 
$1 = {{{prof_data = {tot_wait_time = {ns = 0x0}, max_wait_time = {ns = 0x0}, n_wait_times = 0x0, n_spin_acquired = 0x0, max_n_thds = 0x0, n_waiting_thds = {repr = 0x0}, n_owner_switches = 0x0, 
        prev_owner = 0x0, n_lock_ops = 0x0}, lock = 0x5008bf00, postponed_next = 0x50974070, locked = {repr = 0x0}}}, witness = {name = 0x50760b04, rank = 0x3, comp = 0x0, opaque = 0x0, link = {
      qre_next = 0x50981b10, qre_prev = 0x50981b10}}, lock_order = 0x0}
(gdb) print/x __je_narenas_auto
$2 = 0x8
(gdb) print/x malloc_conf
$3 = 0x0
(gdb) print/x __je_ncpus
$4 = 0x2
(gdb) print/x __je_manual_arena_base
$5 = 0x9
(gdb) print/x __je_sz_pind2sz_tab 
$6 = {0x1000, 0x2000, 0x3000, 0x4000, 0x5000, 0x6000, 0x7000, 0x8000, 0xa000, 0xc000, 0xe000, 0x10000, 0x14000, 0x18000, 0x1c000, 0x20000, 0x28000, 0x30000, 0x38000, 0x40000, 0x50000, 0x60000, 
  0x70000, 0x80000, 0xa0000, 0xc0000, 0xe0000, 0x100000, 0x140000, 0x180000, 0x1c0000, 0x200000, 0x280000, 0x300000, 0x380000, 0x400000, 0x500000, 0x600000, 0x700000, 0x800000, 0xa00000, 0xc00000, 
  0xe00000, 0x1000000, 0x1400000, 0x1800000, 0x1c00000, 0x2000000, 0x2800000, 0x3000000, 0x3800000, 0x4000000, 0x5000000, 0x6000000, 0x7000000, 0x8000000, 0xa000000, 0xc000000, 0xe000000, 
  0x10000000, 0x14000000, 0x18000000, 0x1c000000, 0x20000000, 0x28000000, 0x30000000, 0x38000000, 0x40000000, 0x50000000, 0x60000000, 0x70000000, 0x70001000}
(gdb) print/x __je_sz_index2size_tab
$7 = {0x8, 0x10, 0x20, 0x30, 0x40, 0x50, 0x60, 0x70, 0x80, 0xa0, 0xc0, 0xe0, 0x100, 0x140, 0x180, 0x1c0, 0x200, 0x280, 0x300, 0x380, 0x400, 0x500, 0x600, 0x700, 0x800, 0xa00, 0xc00, 0xe00, 0x1000, 
  0x1400, 0x1800, 0x1c00, 0x2000, 0x2800, 0x3000, 0x3800, 0x4000, 0x5000, 0x6000, 0x7000, 0x8000, 0xa000, 0xc000, 0xe000, 0x10000, 0x14000, 0x18000, 0x1c000, 0x20000, 0x28000, 0x30000, 0x38000, 
  0x40000, 0x50000, 0x60000, 0x70000, 0x80000, 0xa0000, 0xc0000, 0xe0000, 0x100000, 0x140000, 0x180000, 0x1c0000, 0x200000, 0x280000, 0x300000, 0x380000, 0x400000, 0x500000, 0x600000, 0x700000, 
  0x800000, 0xa00000, 0xc00000, 0xe00000, 0x1000000, 0x1400000, 0x1800000, 0x1c00000, 0x2000000, 0x2800000, 0x3000000, 0x3800000, 0x4000000, 0x5000000, 0x6000000, 0x7000000, 0x8000000, 0xa000000, 
  0xc000000, 0xe000000, 0x10000000, 0x14000000, 0x18000000, 0x1c000000, 0x20000000, 0x28000000, 0x30000000, 0x38000000, 0x40000000, 0x50000000, 0x60000000, 0x70000000}
(gdb) print/x __je_sz_size2index_tab
$2 = {0x0, 0x0, 0x1, 0x2, 0x2, 0x3, 0x3, 0x4, 0x4, 0x5, 0x5, 0x6, 0x6, 0x7, 0x7, 0x8, 0x8, 0x9, 0x9, 0x9, 0x9, 0xa, 0xa, 0xa, 0xa, 0xb, 0xb, 0xb, 0xb, 0xc, 0xc, 0xc, 0xc, 0xd, 0xd, 0xd, 0xd, 0xd, 
  0xd, 0xd, 0xd, 0xe, 0xe, 0xe, 0xe, 0xe, 0xe, 0xe, 0xe, 0xf, 0xf, 0xf, 0xf, 0xf, 0xf, 0xf, 0xf, 0x10, 0x10, 0x10, 0x10, 0x10, 0x10, 0x10, 0x10, 0x11 <repeats 16 times>, 0x12 <repeats 16 times>, 
  0x13 <repeats 16 times>, 0x14 <repeats 16 times>, 0x15 <repeats 32 times>, 0x16 <repeats 32 times>, 0x17 <repeats 32 times>, 0x18 <repeats 32 times>, 0x19 <repeats 64 times>, 
  0x1a <repeats 64 times>, 0x1b <repeats 64 times>, 0x1c <repeats 64 times>}


> rpcbind hit an assert, failing ret == sz_size2index_compute(size) :
> 
> (gdb) bt
> #0  thr_kill () at thr_kill.S:4
> #1  0x502f2170 in __raise (s=6) at /usr/src/lib/libc/gen/raise.c:52
> #2  0x50251d04 in abort () at /usr/src/lib/libc/stdlib/abort.c:79
> #3  0x5024f260 in sz_size2index_lookup (size=<optimized out>) at /usr/src/contrib/jemalloc/include/jemalloc/internal/sz.h:159
> #4  sz_size2index (size=<optimized out>) at /usr/src/contrib/jemalloc/include/jemalloc/internal/sz.h:166
> #5  imalloc_body (sopts=0xffffb360, dopts=0xffffb340, tsd=0x5009a018) at jemalloc_jemalloc.c:2066
> #6  0x50244874 in imalloc (sopts=0xffffb360, dopts=0xffffb340) at /usr/src/contrib/jemalloc/include/jemalloc/internal/tsd.h:331
> #7  0x50244fe8 in __calloc (num=1, size=96) at jemalloc_jemalloc.c:2498
> #8  0x50265690 in svc_xprt_alloc () at /usr/src/lib/libc/rpc/svc.c:541
> #9  0x502635f4 in makefd_xprt (fd=14, sendsize=9000, recvsize=9000) at /usr/src/lib/libc/rpc/svc_vc.c:250
> #10 0x502644b4 in rendezvous_request (xprt=0x5004c000, msg=<optimized out>) at /usr/src/lib/libc/rpc/svc_vc.c:315
> #11 0x50265a98 in svc_getreq_common (fd=<optimized out>) at /usr/src/lib/libc/rpc/svc.c:640
> #12 0x50265d1c in svc_getreq_poll (pfdp=<optimized out>, pollretval=1) at /usr/src/lib/libc/rpc/svc.c:739
> #13 0x10018568 in my_svc_run () at /usr/src/usr.sbin/rpcbind/rpcb_svc_com.c:1167
> #14 0x10014ad8 in main (argc=<optimized out>, argv=<optimized out>) at /usr/src/usr.sbin/rpcbind/rpcbind.c:250
> (gdb) up 3
> #3  0x5024f260 in sz_size2index_lookup (size=<optimized out>) at /usr/src/contrib/jemalloc/include/jemalloc/internal/sz.h:159
> 159		assert(ret == sz_size2index_compute(size));
> (gdb) print ret
> $1 = 0
> 
> 154	JEMALLOC_ALWAYS_INLINE szind_t
> 155	sz_size2index_lookup(size_t size) {
> 156		assert(size <= SC_LOOKUP_MAXCLASS);
> 157		szind_t ret = (sz_size2index_tab[(size + (ZU(1) << SC_LG_TINY_MIN) - 1)
> 158						 >> SC_LG_TINY_MIN]);
> 159		assert(ret == sz_size2index_compute(size));
> 160		return ret;
> 161	}

gdb reports for sz_size2index_tab (really JEMALLOC_N(sz_size2index_tab),
i.e., __je_sz_size2index_tab):

(gdb) print/x __je_sz_size2index_tab
$1 = {0x0 <repeats 384 times>, 0x1a, 0x1b <repeats 64 times>, 0x1c <repeats 64 times>}

Also:

(gdb) x/4x __je_arenas+16368/4
0x5034cab0 <__je_arenas+16368>:	0x00000000	0x00000000	0x00000000	0x00000000
(gdb) print/x __je_arenas_lock                                                                                                                 
$8 = {{{prof_data = {tot_wait_time = {ns = 0x0}, max_wait_time = {ns = 0x0}, n_wait_times = 0x0, n_spin_acquired = 0x0, max_n_thds = 0x0, n_waiting_thds = {repr = 0x0}, n_owner_switches = 0x0, 
        prev_owner = 0x0, n_lock_ops = 0x0}, lock = 0x0, postponed_next = 0x0, locked = {repr = 0x0}}}, witness = {name = 0x0, rank = 0x0, comp = 0x0, opaque = 0x0, link = {qre_next = 0x0, 
      qre_prev = 0x0}}, lock_order = 0x0}
(gdb) print/x __je_narenas_auto
$9 = 0x0
(gdb) print/x malloc_conf      
$10 = 0x0
(gdb) print/x __je_ncpus 
$11 = 0x0
(gdb) print/x __je_manual_arena_base
$12 = 0x0
(gdb) print/x __je_sz_pind2sz_tab   
$13 = {0x0 <repeats 72 times>}
(gdb) print/x __je_sz_index2size_tab
$14 = {0x0 <repeats 104 times>}


> nfsd hit an assert, failing ret == sz_size2index_compute(size)

[Correction: That should have referenced sz_index2size_lookup(index).]

> (also, but a different caller of sz_size2index):

[Correction: The "also" comment should be ignored:
sz_index2size_lookup(index) is referenced below.]

> 
> (gdb) bt
> #0  thr_kill () at thr_kill.S:4
> #1  0x502b2170 in __raise (s=6) at /usr/src/lib/libc/gen/raise.c:52
> #2  0x50211cc0 in abort () at /usr/src/lib/libc/stdlib/abort.c:67
> #3  0x50206104 in sz_index2size_lookup (index=<optimized out>) at /usr/src/contrib/jemalloc/include/jemalloc/internal/sz.h:200
> #4  sz_index2size (index=<optimized out>) at /usr/src/contrib/jemalloc/include/jemalloc/internal/sz.h:207
> #5  ifree (tsd=0x50094018, ptr=0x50041028, tcache=0x50094138, slow_path=<optimized out>) at jemalloc_jemalloc.c:2583
> #6  0x50205cac in __je_free_default (ptr=0x50041028) at jemalloc_jemalloc.c:2784
> #7  0x50206294 in __free (ptr=0x50041028) at jemalloc_jemalloc.c:2852
> #8  0x50287ec8 in ns_src_free (src=0x50329004, srclistsize=<optimized out>) at /usr/src/lib/libc/net/nsdispatch.c:452
> #9  ns_dbt_free (dbt=0x50329000) at /usr/src/lib/libc/net/nsdispatch.c:436
> #10 vector_free (vec=0x50329000, count=<optimized out>, esize=12, free_elem=<optimized out>) at /usr/src/lib/libc/net/nsdispatch.c:253
> #11 nss_atexit () at /usr/src/lib/libc/net/nsdispatch.c:578
> #12 0x5028d958 in __cxa_finalize (dso=0x0) at /usr/src/lib/libc/stdlib/atexit.c:240
> #13 0x502117f8 in exit (status=0) at /usr/src/lib/libc/stdlib/exit.c:74
> #14 0x10013f9c in child_cleanup (signo=<optimized out>) at /usr/src/usr.sbin/nfsd/nfsd.c:969
> #15 <signal handler called>
> #16 0x00000000 in ?? ()
> 
> (gdb) up 3
> #3  0x50206104 in sz_index2size_lookup (index=<optimized out>) at /usr/src/contrib/jemalloc/include/jemalloc/internal/sz.h:200
> 200		assert(ret == sz_index2size_compute(index));
> 
> (ret is optimized out.)
> 
> 197	JEMALLOC_ALWAYS_INLINE size_t
> 198	sz_index2size_lookup(szind_t index) {
> 199		size_t ret = (size_t)sz_index2size_tab[index];
> 200		assert(ret == sz_index2size_compute(index));
> 201		return ret;
> 202	}

(gdb) print/x __je_sz_index2size_tab
$3 = {0x0 <repeats 104 times>}

Also:

(gdb) x/4x __je_arenas+16368/4
0x5030cab0 <__je_arenas+16368>:	0x00000000	0x00000000	0x00000000	0x00000000
(gdb) print/x __je_arenas_lock                                                                                                                 
$8 = {{{prof_data = {tot_wait_time = {ns = 0x0}, max_wait_time = {ns = 0x0}, n_wait_times = 0x0, n_spin_acquired = 0x0, max_n_thds = 0x0, n_waiting_thds = {repr = 0x0}, n_owner_switches = 0x0, 
        prev_owner = 0x0, n_lock_ops = 0x0}, lock = 0x0, postponed_next = 0x0, locked = {repr = 0x0}}}, witness = {name = 0x0, rank = 0x0, comp = 0x0, opaque = 0x0, link = {qre_next = 0x0, 
      qre_prev = 0x0}}, lock_order = 0x0}
(gdb) print/x __je_narenas_auto
$9 = 0x0
(gdb) print/x malloc_conf      
$10 = 0x0
(gdb) print/x __je_ncpus 
$11 = 0x0
(gdb) print/x __je_manual_arena_base
$12 = 0x0
(gdb) print/x __je_sz_pind2sz_tab   
$13 = {0x0 <repeats 72 times>}
(gdb) print/x __je_sz_size2index_tab
$1 = {0x0 <repeats 384 times>, 0x1a, 0x1b <repeats 64 times>, 0x1c <repeats 64 times>}

> Booting and immediately trying something like:
> 
> service nfsd stop
> 
> did not lead to a failure. But may be after
> a while it would and be less drastic than a
> reboot or power down.

More detail:

So, for rpcbind and nfds at some point a large part of
__je_sz_size2index_tab is being stomped on, as is all of
__je_sz_index2size_tab and more.

For rpcbind, the following area is zero but in a
live process is not all-zero (I show the partially
non-zero live-process context instead of the all-zero
.core file content):

0x5034cab0 <__je_arenas+16368>:	0x00000000	0x00000000	0x00000000	0x00000009
0x5034cac0 <__je_arenas_lock>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5034cad0 <__je_arenas_lock+16>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5034cae0 <__je_arenas_lock+32>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5034caf0 <__je_arenas_lock+48>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5034cb00 <__je_arenas_lock+64>:	0x00000000	0x5033f070	0x00000000	0x00000000
0x5034cb10 <__je_arenas_lock+80>:	0x5012bb04	0x00000003	0x00000000	0x00000000
0x5034cb20 <__je_arenas_lock+96>:	0x5034cb10	0x5034cb10	0x00000000	0x00000000

Then the memory in the crash continues to be zero until:

0x5034d000 <__je_sz_size2index_tab+384>:	0x1a1b1b1b	0x1b1b1b1b	0x1b1b1b1b	0x1b1b1b1b

Notice the interesting page boundary for where non-zero
is first available again!

Between __je_arenas_lock and __je_sz_size2index_tab are:

0x5034cb30 __je_narenas_auto
0x5034cb38 malloc_conf
0x5034cb3c __je_ncpus
0x5034cb40 __je_manual_arena_base
0x5034cb80 __je_sz_pind2sz_tab
0x5034ccc0 __je_sz_index2size_tab
0x5034ce80 __je_sz_size2index_tab

For nfsd, it is similar (again showing the partially
non-zero live process context instead of the all-zeros
from the .core file):

0x5030cab0 <__je_arenas+16368>:	0x00000000	0x00000000	0x00000000	0x00000009
0x5030cac0 <__je_arenas_lock>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5030cad0 <__je_arenas_lock+16>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5030cae0 <__je_arenas_lock+32>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5030caf0 <__je_arenas_lock+48>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5030cb00 <__je_arenas_lock+64>:	0x00000000	0x502ff070	0x00000000	0x00000000
0x5030cb10 <__je_arenas_lock+80>:	0x500ebb04	0x00000003	0x00000000	0x00000000
0x5030cb20 <__je_arenas_lock+96>:	0x5030cb10	0x5030cb10	0x00000000	0x00000000

Then the memory in the crash continues to be zero until:

0x5030d000 <__je_sz_size2index_tab+384>:	0x1a1b1b1b	0x1b1b1b1b	0x1b1b1b1b	0x1b1b1b1b

Notice the interesting page boundary for where non-zero
is first available again!

Between __je_arenas_lock and __je_sz_size2index_tab are:

0x5030cb30 __je_narenas_auto
0x5030cb38 malloc_conf
0x5030cb3c __je_ncpus
0x5030cb40 __je_manual_arena_base
0x5030cb80 __je_sz_pind2sz_tab
0x5030ccc0 __je_sz_index2size_tab
0x5030ce80 __je_sz_size2index_tab


Note: because __je_arenas is normally
mostly zero for these contexts, I can
not tell where the memory trashing
started, only where it replaced non-zero
values with zeros.

===
Mark Millard
marklmi at yahoo.com
( dsl-only.net went
away in early 2018-Mar)
Received on Thu May 07 2020 - 05:46:40 UTC

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