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>