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

Mark Millard via svn-src-head <[email protected]>
Newsgroups gmane.os.freebsd.current.scm,gmane.os.freebsd.current,gmane.os.freebsd.devel.hackers,gmane.os.freebsd.devel.ppc
Message-ID <[email protected]>
[mountd failure example: also at sz_size2index_lookup assert
for the same zero'd memory problem.]

> On 2020-May-7, at 00:46, Mark Millard <[email protected]> wrote:
> 
> [__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.
> 

I got a mountd assert failure in sz_size2index_lookup
while attempting __calloc during makefd_xprt.

(gdb) bt
#0  thr_kill () at thr_kill.S:4
#1  0x50301170 in __raise (s=6) at /usr/src/lib/libc/gen/raise.c:52
#2  0x50260cc0 in abort () at /usr/src/lib/libc/stdlib/abort.c:67
#3  0x5025e260 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=0xffffd000, dopts=0xffffcfe0, tsd=0x50094018) at jemalloc_jemalloc.c:2066
#6  0x50253874 in imalloc (sopts=0xffffd000, dopts=0xffffcfe0) at /usr/src/contrib/jemalloc/include/jemalloc/internal/tsd.h:331
#7  0x50253fe8 in __calloc (num=1, size=96) at jemalloc_jemalloc.c:2498
#8  0x50274690 in svc_xprt_alloc () at /usr/src/lib/libc/rpc/svc.c:541
#9  0x502725f4 in makefd_xprt (fd=10, sendsize=9000, recvsize=9000) at /usr/src/lib/libc/rpc/svc_vc.c:250
#10 0x502734b4 in rendezvous_request (xprt=0x5007b120, msg=<optimized out>) at /usr/src/lib/libc/rpc/svc_vc.c:315
#11 0x50274a98 in svc_getreq_common (fd=<optimized out>) at /usr/src/lib/libc/rpc/svc.c:640
#12 0x502748e0 in svc_getreqset (readfds=<optimized out>) at /usr/src/lib/libc/rpc/svc.c:611
#13 0x1001434c in main (argc=<optimized out>, argv=0xffffde3c) at /usr/src/usr.sbin/mountd/mountd.c:683

(gdb) up 3
#3  0x5025e260 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));

Again there is that area of memory that has been zeroed, with
the same stopping point in __je_sz_size2index_tab:

(gdb) print/x __je_narenas_auto
$2 = 0x0
(gdb) print/x malloc_conf 
$3 = 0x0
(gdb) print/x __je_ncpus
$4 = 0x0
(gdb) print/x __je_manual_arena_base
$5 = 0x0
(gdb) print/x __je_sz_pind2sz_tab
$6 = {0x0 <repeats 72 times>}
(gdb) print/x __je_sz_size2index_tab
$7 = {0x0 <repeats 384 times>, 0x1a, 0x1b <repeats 64 times>, 0x1c <repeats 64 times>}

Showing where the zeroing stopped:

. . .
(gdb) x/156x __je_sz_size2index_tab
0x5035be80 <__je_sz_size2index_tab>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035be90 <__je_sz_size2index_tab+16>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bea0 <__je_sz_size2index_tab+32>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035beb0 <__je_sz_size2index_tab+48>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bec0 <__je_sz_size2index_tab+64>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bed0 <__je_sz_size2index_tab+80>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bee0 <__je_sz_size2index_tab+96>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bef0 <__je_sz_size2index_tab+112>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bf00 <__je_sz_size2index_tab+128>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bf10 <__je_sz_size2index_tab+144>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bf20 <__je_sz_size2index_tab+160>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bf30 <__je_sz_size2index_tab+176>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bf40 <__je_sz_size2index_tab+192>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bf50 <__je_sz_size2index_tab+208>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bf60 <__je_sz_size2index_tab+224>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bf70 <__je_sz_size2index_tab+240>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bf80 <__je_sz_size2index_tab+256>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bf90 <__je_sz_size2index_tab+272>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bfa0 <__je_sz_size2index_tab+288>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bfb0 <__je_sz_size2index_tab+304>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bfc0 <__je_sz_size2index_tab+320>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bfd0 <__je_sz_size2index_tab+336>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bfe0 <__je_sz_size2index_tab+352>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035bff0 <__je_sz_size2index_tab+368>:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035c000 <__je_sz_size2index_tab+384>:	0x1a1b1b1b	0x1b1b1b1b	0x1b1b1b1b	0x1b1b1b1b
0x5035c010 <__je_sz_size2index_tab+400>:	0x1b1b1b1b	0x1b1b1b1b	0x1b1b1b1b	0x1b1b1b1b
0x5035c020 <__je_sz_size2index_tab+416>:	0x1b1b1b1b	0x1b1b1b1b	0x1b1b1b1b	0x1b1b1b1b
0x5035c030 <__je_sz_size2index_tab+432>:	0x1b1b1b1b	0x1b1b1b1b	0x1b1b1b1b	0x1b1b1b1b
0x5035c040 <__je_sz_size2index_tab+448>:	0x1b1c1c1c	0x1c1c1c1c	0x1c1c1c1c	0x1c1c1c1c
0x5035c050 <__je_sz_size2index_tab+464>:	0x1c1c1c1c	0x1c1c1c1c	0x1c1c1c1c	0x1c1c1c1c
0x5035c060 <__je_sz_size2index_tab+480>:	0x1c1c1c1c	0x1c1c1c1c	0x1c1c1c1c	0x1c1c1c1c
0x5035c070 <__je_sz_size2index_tab+496>:	0x1c1c1c1c	0x1c1c1c1c	0x1c1c1c1c	0x1c1c1c1c
0x5035c080 <__je_sz_size2index_tab+512>:	0x1c000000	0x00000000	0x50303474	0x00000000
0x5035c090:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035c0a0:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035c0b0:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035c0c0:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035c0d0:	0x00000000	0x00000000	0x00000000	0x00000000
0x5035c0e0:	0x00000000	0x00000000	0x00000000	0x00000000

Again: a nice page boundary: 0x5035c000 for where the
zeros stop.

Note that, despite the address ranges shifting around
between programs, the same global variables are being
stomped on, stopping at the same index into
__je_sz_size2index_tab in each of the 3 programs. It
always is page aligned there in my context.

(The sshd example is different. I've yet to explore it
much.)



===
Mark Millard
marklmi at yahoo.com
( dsl-only.net went
away in early 2018-Mar)
lmpx.com only provides a reader for public news (NNTP) servers. It is not affiliated with the servers or forums shown here and is not responsible for the content of articles, which is written by their respective authors.