Skip site navigation (1)Skip section navigation (2)
Date:      Fri, 8 May 2020 09:14:24 -0700
From:      Mark Millard <marklmi@yahoo.com>
To:        "vangyzen@freebsd.org" <vangyzen@FreeBSD.org>, svn-src-head@freebsd.org, FreeBSD Current <freebsd-current@freebsd.org>, FreeBSD Hackers <freebsd-hackers@freebsd.org>, FreeBSD PowerPC ML <freebsd-ppc@freebsd.org>
Cc:        Brandon Bergren <bdragon@FreeBSD.org>, Justin Hibbits <chmeeedalf@gmail.com>
Subject:   Re: svn commit: r360233 - in head: contrib/jemalloc . . . : This partially breaks a 2-socket 32-bit powerpc (old PowerMac G4) based on head -r360311
Message-ID:  <624CE71B-2C50-4E77-85A2-42D9FA140AD0@yahoo.com>
In-Reply-To: <F5953A6B-56CE-4D1C-8C18-58D44B639881@yahoo.com>
References:  <C24EE1A1-FAED-42C2-8204-CA7B1D20A369@yahoo.com> <8479DD58-44F6-446A-9CA5-D01F0F7C1B38@yahoo.com> <17ACDA02-D7EF-4F26-874A-BB3E935CD072@yahoo.com> <695E6836-F860-4557-B7DE-CC1EDB347F18@yahoo.com> <DCABCD83-27B0-4F2D-9410-69102294A98E@yahoo.com> <121B9B09-141B-4DC3-918B-1E7CFB99E779@yahoo.com> <8AAB0462-3FA8-490C-8D8D-7C15B1C9E2DE@yahoo.com> <18E62746-80DB-4195-977D-4FF32D0129EE@yahoo.com> <F5953A6B-56CE-4D1C-8C18-58D44B639881@yahoo.com>

next in thread | previous in thread | raw e-mail | index | archive | help
[More details for a sshd failure. The other
examples are omitted. The sshd failure also shows
a all-zeros-up-to-a-page-boundary issue, just for
a different address range.]

On 2020-May-7, at 12:06, Mark Millard <marklmi@yahoo.com> wrote:
>=20
> [mountd failure example: also at sz_size2index_lookup assert
> for the same zero'd memory problem.]
>=20
>> On 2020-May-7, at 00:46, Mark Millard <marklmi@yahoo.com> wrote:
>>=20
>> [__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.]
>>=20
>> On 2020-May-6, at 16:57, Mark Millard <marklmi at yahoo.com> wrote:
>>=20
>>> [This explores process crashes that happen during system
>>> shutdown, in a context not having MALLOC_PRODUCTION=3D .
>>> So assert failures are reported as the stopping points.]
>>>=20
>>> 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.
>>>=20
>>>=20
>>> sshd hit an assert, failing slab =3D=3D extent_slab_get(extent) :
>>>=20
>>> (gdb) bt=20
>>> #0  thr_kill () at thr_kill.S:4
>>> #1  0x50927170 in __raise (s=3D6) 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=3D<optimized out>, =
ptr=3D<optimized out>, tcache=3D<optimized out>, alloc_ctx=3D<optimized =
out>, slow_path=3D<optimized out>)
>>>  at =
/usr/src/contrib/jemalloc/include/jemalloc/internal/arena_inlines_b.h:315
>>> #4  idalloctm (tsdn=3D0x500dd040, ptr=3D0x5008a180, =
tcache=3D0x500dd160, alloc_ctx=3D<optimized out>, is_internal=3D<optimized=
 out>, slow_path=3D<optimized out>)
>>>  at =
/usr/src/contrib/jemalloc/include/jemalloc/internal/jemalloc_internal_inli=
nes_c.h:118
>>> #5  0x5087b0a4 in ifree (tsd=3D0x500dd040, ptr=3D0x5008a180, =
tcache=3D0x500dd160, slow_path=3D<optimized out>) at =
jemalloc_jemalloc.c:2590
>>> #6  0x5087acac in __je_free_default (ptr=3D0x5008a180) at =
jemalloc_jemalloc.c:2784
>>> #7  0x5087b294 in __free (ptr=3D0x5008a180) at =
jemalloc_jemalloc.c:2852
>>> #8  0x10029464 in server_accept_loop (config_s=3D<optimized out>, =
sock_in=3D<optimized out>, sock_out=3D<optimized out>, =
newsock=3D<optimized out>) at /usr/src/crypto/openssh/sshd.c:1185
>>> #9  main (ac=3D<optimized out>, av=3D0xffffde3c) at =
/usr/src/crypto/openssh/sshd.c:2009
>>>=20
>>> . . .
>>> (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=3D<optimized out>, =
ptr=3D<optimized out>, tcache=3D<optimized out>, alloc_ctx=3D<optimized =
out>, slow_path=3D<optimized out>)
>>>  at =
/usr/src/contrib/jemalloc/include/jemalloc/internal/arena_inlines_b.h:315
>>> 315			assert(slab =3D=3D extent_slab_get(extent));
>>>=20
>>> (gdb) list
>>> 310			rtree_ctx =3D tsd_rtree_ctx(tsdn_tsd(tsdn));
>>> 311			extent_t *extent =3D rtree_extent_read(tsdn, =
&extents_rtree,
>>> 312			    rtree_ctx, (uintptr_t)ptr, true);
>>> 313			assert(szind =3D=3D extent_szind_get(extent));
>>> 314			assert(szind < SC_NSIZES);
>>> 315			assert(slab =3D=3D extent_slab_get(extent));
>>> 316		}
>>> 317=09
>>> 318		if (likely(slab)) {
>>> 319			/* Small allocation. */
>>>=20
>>> More fully:
>>>=20
>>> 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 =3D=3D NULL);
>>> 289		assert(ptr !=3D NULL);
>>> 290=09
>>> 291		if (unlikely(tcache =3D=3D NULL)) {
>>> 292			arena_dalloc_no_tcache(tsdn, ptr);
>>> 293			return;
>>> 294		}
>>> 295=09
>>> 296		szind_t szind;
>>> 297		bool slab;
>>> 298		rtree_ctx_t *rtree_ctx;
>>> 299		if (alloc_ctx !=3D NULL) {
>>> 300			szind =3D alloc_ctx->szind;
>>> 301			slab =3D alloc_ctx->slab;
>>> 302			assert(szind !=3D SC_NSIZES);
>>> 303		} else {
>>> 304			rtree_ctx =3D 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=09
>>> 309		if (config_debug) {
>>> 310			rtree_ctx =3D tsd_rtree_ctx(tsdn_tsd(tsdn));
>>> 311			extent_t *extent =3D rtree_extent_read(tsdn, =
&extents_rtree,
>>> 312			    rtree_ctx, (uintptr_t)ptr, true);
>>> 313			assert(szind =3D=3D extent_szind_get(extent));
>>> 314			assert(szind < SC_NSIZES);
>>> 315			assert(slab =3D=3D extent_slab_get(extent));
>>> 316		}
>>> 317=09
>>> 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	}
>>=20
>> . . .

The machine code for:

309		if (config_debug) {
310			rtree_ctx =3D tsd_rtree_ctx(tsdn_tsd(tsdn));
311			extent_t *extent =3D rtree_extent_read(tsdn, =
&extents_rtree,
312			    rtree_ctx, (uintptr_t)ptr, true);
313			assert(szind =3D=3D extent_szind_get(extent));
314			assert(szind < SC_NSIZES);
315			assert(slab =3D=3D extent_slab_get(extent));
316		}

was dropping the address in "extent" the next instruction
after finding it: replacing with with a field's value.
So by the time the status of the assert could be known,
examining extent was a difficulty.

So I touched the source code to force the address to be
kept and to give a place to breakpoint on failure before
calling another routine:

# svnlite diff =
/usr/src/contrib/jemalloc/include/jemalloc/internal/arena_inlines_b.h
Index: =
/usr/src/contrib/jemalloc/include/jemalloc/internal/arena_inlines_b.h
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
--- =
/usr/src/contrib/jemalloc/include/jemalloc/internal/arena_inlines_b.h	=
(revision 360322)
+++ =
/usr/src/contrib/jemalloc/include/jemalloc/internal/arena_inlines_b.h	=
(working copy)
@@ -308,11 +308,11 @@
=20
 	if (config_debug) {
 		rtree_ctx =3D tsd_rtree_ctx(tsdn_tsd(tsdn));
-		extent_t *extent =3D rtree_extent_read(tsdn, =
&extents_rtree,
+		extent_t * volatile extent =3D rtree_extent_read(tsdn, =
&extents_rtree,
 		    rtree_ctx, (uintptr_t)ptr, true);
 		assert(szind =3D=3D extent_szind_get(extent));
 		assert(szind < SC_NSIZES);
-		assert(slab =3D=3D extent_slab_get(extent));
+		assert((slab =3D=3D extent_slab_get(extent)) ?true =
:extent=3D=3DNULL);
 	}
=20
 	if (likely(slab)) {


The ":extent=3D=3DNULL" should be guaranteed to produce :false as a =
result
but with more code involved to get there. It gave me a place to =
breakpoint
on failure.

(gdb) bt -full
#0  0x50883258 in arena_dalloc (tsdn=3D<optimized out>, ptr=3D<optimized =
out>, tcache=3D<optimized out>, alloc_ctx=3D<optimized out>, =
slow_path=3D<optimized out>)
    at =
/usr/src/contrib/jemalloc/include/jemalloc/internal/arena_inlines_b.h:315
        extent =3D 0x51007fc0
        slab =3D <optimized out>
        szind =3D <optimized out>
        rtree_ctx =3D 0x500dd06c
        extent =3D <optimized out>
#1  idalloctm (tsdn=3D0x500dd040, ptr=3D0x5008a180, tcache=3D0x500dd160, =
alloc_ctx=3D<optimized out>, is_internal=3D<optimized out>, =
slow_path=3D<optimized out>)
    at =
/usr/src/contrib/jemalloc/include/jemalloc/internal/jemalloc_internal_inli=
nes_c.h:118
No locals.
#2  0x5087b0e4 in ifree (tsd=3D0x500dd040, ptr=3D0x5008a180, =
tcache=3D0x500dd160, slow_path=3D<optimized out>) at =
jemalloc_jemalloc.c:2590
        alloc_ctx =3D {szind =3D 0, slab =3D true}
        rtree_ctx =3D <optimized out>
        usize =3D <optimized out>
#3  0x5087acec in __je_free_default (ptr=3D0x5008a180) at =
jemalloc_jemalloc.c:2784
        tcache =3D 0x500dd160
        tsd =3D <optimized out>
#4  0x5087b2d4 in __free (ptr=3D0x5008a180) at jemalloc_jemalloc.c:2852
        log_var =3D <optimized out>
        log_var =3D <optimized out>
#5  0x10029464 in server_accept_loop (config_s=3D<optimized out>, =
sock_in=3D<optimized out>, sock_out=3D<optimized out>, =
newsock=3D<optimized out>) at /usr/src/crypto/openssh/sshd.c:1185
        from =3D {ss_len =3D 16 '\020', ss_family =3D 2 '\002', =
__ss_pad1 =3D "\317\200\300\250\001\031", __ss_align =3D 0,=20
          __ss_pad2 =3D "\000\000\000\000\000\000\000\002Am", '\000' =
<repeats 19 times>, "\065\341I\000\000\000\000^\264\234\331", '\000' =
<repeats 12 times>, =
"^\262\027\034-a\241H\000\000\000\000\000\000\000\000^\264\235Y,\024\247\0=
30\000\000\000\000\000\000\000\000V\312\331f6-N\370\000\000\000\000\000\00=
0\000\000\000\000\002\000\000\000\000\000\000\000\000\b"}
        rnd =3D '\000' <repeats 255 times>
        startup_p =3D {6, 7}
        startups =3D 1
        i =3D <optimized out>
        maxfd =3D 6
        fdset =3D <optimized out>
        fromlen =3D <optimized out>
        ret =3D <optimized out>
        j =3D <optimized out>
        pid =3D <optimized out>
        laddr =3D <optimized out>
        raddr =3D <optimized out>
#6  main (ac=3D<optimized out>, av=3D0xffffde3c) at =
/usr/src/crypto/openssh/sshd.c:2009
        config_s =3D {8, 9}
        on =3D 1
        ssh =3D 0x0
        logfile =3D <optimized out>
        newsock =3D -1
        sock_out =3D -1
        sock_in =3D -1
        connection_info =3D <optimized out>
        i =3D <optimized out>
        opt =3D <optimized out>
        line =3D <optimized out>
        r =3D <optimized out>
        key =3D <optimized out>
        pubkey =3D <optimized out>
        keytype =3D <optimized out>
        fp =3D <optimized out>
        j =3D <optimized out>
        new_umask =3D <optimized out>
        already_daemon =3D <optimized out>
        remote_port =3D <optimized out>
        remote_ip =3D <optimized out>
        rdomain =3D <optimized out>
--Type <RET> for more, q to quit, c to continue without paging--
        laddr =3D <optimized out>
        authctxt =3D <optimized out>
        obytes =3D <optimized out>
        ibytes =3D <optimized out>

(gdb) list
310			rtree_ctx =3D tsd_rtree_ctx(tsdn_tsd(tsdn));
311			extent_t * volatile extent =3D =
rtree_extent_read(tsdn, &extents_rtree,
312			    rtree_ctx, (uintptr_t)ptr, true);
313			assert(szind =3D=3D extent_szind_get(extent));
314			assert(szind < SC_NSIZES);
315			assert((slab =3D=3D extent_slab_get(extent)) =
?true :extent=3D=3DNULL);
316		}
317=09
318		if (likely(slab)) {
319			/* Small allocation. */

(gdb) print/x extent
$6 =3D 0x51007fc0

(gdb) print/x *extent
$2 =3D {e_bits =3D 0x0, e_addr =3D 0x0, {e_size_esn =3D 0x0, e_bsize =3D =
0x0}, ql_link =3D {qre_next =3D 0x0, qre_prev =3D 0x0}, ph_link =3D =
{phn_prev =3D 0x0, phn_next =3D 0x0, phn_lchild =3D 0x0}, {e_slab_data =3D=
 {
      bitmap =3D {0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xffffffff, 0xffffffff, =
0xffffffff, 0xffffffff, 0xffffffff, 0xffffffff, 0xffffffff, 0xffffffff, =
0xffffffff, 0xffffffff, 0xfff8}}, {e_alloc_time =3D {
        ns =3D 0x0}, e_prof_tctx =3D {repr =3D 0x0}}}}

It looks like the prefix of the above has been stomped on
to be zeros. Checking addresses as well:

(gdb) x/64x extent
0x51007fc0:	0x00000000	0x00000000	0x00000000	=
0x00000000
0x51007fd0:	0x00000000	0x00000000	0x00000000	=
0x00000000
0x51007fe0:	0x00000000	0x00000000	0x00000000	=
0x00000000
0x51007ff0:	0x00000000	0x00000000	0x00000000	=
0x00000000
0x51008000:	0xffffffff	0xffffffff	0xffffffff	=
0xffffffff
0x51008010:	0xffffffff	0xffffffff	0xffffffff	=
0xffffffff
0x51008020:	0xffffffff	0xffffffff	0x0000fff8	=
0x00000000
0x51008030:	0x00000000	0x00000000	0x00000000	=
0x00000000
0x51008040:	0x00000800	0x0014f000	0x5008b000	=
0x00005000
0x51008050:	0x51008040	0x51008040	0x00000000	=
0x00000000
0x51008060:	0x00000000	0x00000000	0x00000000	=
0x00000000
0x51008070:	0x00000000	0x00000000	0x00000000	=
0x00000000
0x51008080:	0x00000000	0x00000000	0x00000000	=
0x00000000
0x51008090:	0x00000000	0x00000000	0x00000000	=
0x00000000
0x510080a0:	0x00000000	0x00000000	0x00000000	=
0x00000000
0x510080b0:	0x00000000	0x00000000	0x00000000	=
0x00000000

Note that the non-zero values start at: 0x51008000, again a page
boundary, like the other examples in prior notes for other cases.
This appears to be another example of memory having been stomped
on/replaced that likely previously had the intended values.

The first prior non-zero values are at:

0x51005a30:	0x00000000	0x51008740	0x0000000f	=
0x01000000
0x51005a40:	0x51008740	0x0000000f	0x01000000	=
0x51008740
0x51005a50:	0x0000000f	0x01000000	0x51008740	=
0x0000000f
0x51005a60:	0x01000000	0x51008740	0x0000000f	=
0x01000000
0x51005a70:	0x51008740	0x0000000f	0x01000000	=
0x51008740
0x51005a80:	0x0000000f	0x01000000	0x51008940	=
0x00000014
0x51005a90:	0x01000000	0x510089c0	0x00000014	=
0x01000000
0x51005aa0:	0x51008a40	0x00000018	0x01000000	=
0x51008ac0
0x51005ab0:	0x00000018	0x01000000	0x51008b40	=
0x00000018
0x51005ac0:	0x01000000	0x51008bc0	0x00000018	=
0x01000000
0x51005ad0:	0x51008c40	0x00000018	0x01000000	=
0x51008cc0
0x51005ae0:	0x00000001	0x01000000	0x00000000	=
0x00000000

So the pages for address ranges 0x51006yyy and 0x51007yyy seem to be
all-zero, along with the tail of the page for the range 0x51005yyy.

#2 (ifree) in the backtrace shows the alloc_ctx content:

         alloc_ctx =3D {szind =3D 0, slab =3D true}

So slab=3D=3Dtrue but the bit in extent->e_bits=3D=3Dfalse, leading to
the failed assert.

Before going to sleep for the night, I could ssh into the
old PowerMac without this detection. After getting up, trying
the same got the failure detection. I did not have the machine
doing anything else special between.

The other examples in the other programs are similar: just
waiting long enough with normal background processing going
on eventually leads to the context for the next explicit use
(or exit) to detect the problem.

I'm still no where near identifying when the stomped-on memory
range is trashed with zeros in code terms in any example
program.

But sshd, dhclient, rpcbind, nfsd, and sendmail all seem to
have some common subject area(s) involved in their
implementation. So I suspect something common across those
is essentially involved.


For reference:

In #0:

(gdb) print/x rtree_ctx
$5 =3D 0x500dd06c

(gdb) print/x *rtree_ctx
$4 =3D {cache =3D {{leafkey =3D 0x50000000, leaf =3D 0x51004fc0}, =
{leafkey =3D 0x1, leaf =3D 0x0}, {leafkey =3D 0x1, leaf =3D 0x0}, =
{leafkey =3D 0x50c00000, leaf =3D 0x51008dc0}, {leafkey =3D 0x1,=20
      leaf =3D 0x0} <repeats 12 times>}, l2_cache =3D {{leafkey =3D 0x1, =
leaf =3D 0x0}, {leafkey =3D 0x1, leaf =3D 0x0}, {leafkey =3D 0x1, leaf =3D=
 0x0}, {leafkey =3D 0x1, leaf =3D 0x0}, {leafkey =3D 0x1, leaf =3D 0x0}, =
{
      leafkey =3D 0x1, leaf =3D 0x0}, {leafkey =3D 0x1, leaf =3D 0x0}, =
{leafkey =3D 0x1, leaf =3D 0x0}}}



=3D=3D=3D
Mark Millard
marklmi at yahoo.com
( dsl-only.net went
away in early 2018-Mar)




Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?624CE71B-2C50-4E77-85A2-42D9FA140AD0>