Occasionally, when using the “time” bash built-in, I get bogus output,
like this:
real 0m34.671s
user 0m24.755s
sys .+(.0*-)m,/.222s
real 0m23.049s
user 0m15.599s
sys 153122387m27.677s
This is not corruption caused by concurrently running programs, it's
actually what bash prints, as shown by strace:
getrusage(RUSAGE_SELF, {ru_utime={0, 17593}, ru_stime={0, 11077}, ...}) = 0
getrusage(RUSAGE_CHILDREN, {ru_utime={415, 207092}, ru_stime={18446744072088255844, 829991}, ...}) = 0
write(2, "\nreal\t0m22.872s\nuser\t0m15.744s\n", 31) = 31
write(2, "sys\t/+,-.--,)m*.607s\n", 21) = 21
I assume that the number formatting code in bash is buggy and cannot
print large values, hence the garbled output. But the more concerning
bug is the invalid getrusage value from the kernel.
I can reproduce this at will using glibc malloc/tst-malloc-thread-exit
test case. I have attached a stripped-down version which can compile
outside of the glibc sources, using:
$ cat tst-malloc-thread-exit.c
/* Test malloc with concurrent thread termination.
Copyright (C) 2015-2017 Free Software Foundation, Inc.
This file is part of the GNU C Library.
The GNU C Library is free software; you can redistribute it and/or
modify it under the terms of the GNU Lesser General Public
License as published by the Free Software Foundation; either
version 2.1 of the License, or (at your option) any later version.
The GNU C Library is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
Lesser General Public License for more details.
You should have received a copy of the GNU Lesser General Public
License along with the GNU C Library; if not, see
<http://www.gnu.org/licenses/>. */
/* This thread spawns a number of outer threads, equal to the arena
limit. The outer threads run a loop which start and join two
different kinds of threads: the first kind allocates (attaching an
arena to the thread; malloc_first_thread) and waits, the second
kind waits and allocates (wait_first_threads). Both kinds of
threads exit immediately after waiting. The hope is that this will
exhibit races in thread termination and arena management,
particularly related to the arena free list. */
#include <errno.h>
#include <malloc.h>
#include <pthread.h>
#include <stdbool.h>
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
static bool termination_requested;
static int inner_thread_count = 4;
static size_t malloc_size = 32;
static void
__attribute__ ((noinline, noclone))
unoptimized_free (void *ptr)
{
free (ptr);
}
static void *
malloc_first_thread (void * closure)
{
pthread_barrier_t *barrier = closure;
void *ptr = malloc (malloc_size);
pthread_barrier_wait (barrier);
unoptimized_free (ptr);
return NULL;
}
static void *
wait_first_thread (void * closure)
{
pthread_barrier_t *barrier = closure;
pthread_barrier_wait (barrier);
void *ptr = malloc (malloc_size);
unoptimized_free (ptr);
return NULL;
}
static void *
outer_thread (void *closure)
{
pthread_t *threads = calloc (sizeof (*threads), inner_thread_count);
while (!__atomic_load_n (&termination_requested, __ATOMIC_RELAXED))
{
pthread_barrier_t barrier;
pthread_barrier_init (&barrier, NULL, inner_thread_count + 1);
for (int i = 0; i < inner_thread_count; ++i)
{
void *(*func) (void *);
if ((i % 2) == 0)
func = malloc_first_thread;
else
func = wait_first_thread;
pthread_create (threads + i, NULL, func, &barrier);
}
pthread_barrier_wait (&barrier);
for (int i = 0; i < inner_thread_count; ++i)
pthread_join (threads[i], NULL);
pthread_barrier_destroy (&barrier);
}
free (threads);
return NULL;
}
int
main (void)
{
/* The number of threads should be smaller than the number of
arenas, so that there will be some free arenas to add to the
arena free list. */
enum { outer_thread_count = 2 };
if (mallopt (M_ARENA_MAX, 8) == 0)
{
printf ("error: mallopt (M_ARENA_MAX) failed\n");
return 1;
}
/* Leave some room for shutting down all threads gracefully. */
int timeout = 3;
pthread_t *threads = calloc (sizeof (*threads), outer_thread_count);
for (long i = 0; i < outer_thread_count; ++i)
pthread_create (threads + i, NULL, outer_thread, NULL);
struct timespec ts = {timeout, 0};
if (nanosleep (&ts, NULL))
{
printf ("error: error: nanosleep: %m\n");
abort ();
}
__atomic_store_n (&termination_requested, true, __ATOMIC_RELAXED);
for (long i = 0; i < outer_thread_count; ++i)
pthread_join (threads[i], NULL);
free (threads);
return 0;
}
$ gcc -O2 -std=gnu99 tst-malloc-thread-exit.c -lpthread
To reproduce, just run:
$ time ./a.out
I've seen the bogus result happen on every call for some z/VM instances,
and on others
I see this with kernel-4.11.0-2.fc26.s390x from Fedora. This could be a
regression because I have never noticed it before when running the glibc
testsuite under earlier kernels.
Thanks,
Florian
--
To unsubscribe from this list: send the line "unsubscribe linux-s390" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
