[prev in list] [next in list] [prev in thread] [next in thread]
List: glibc-alpha
Subject: Re: [PATCH v6] Fix time/tst-cpuclock1 intermitent failures
From: Carlos O'Donell via Libc-alpha <libc-alpha () sourceware ! org>
Date: 2020-03-31 19:02:05
Message-ID: a67d28fc-f8dd-729e-5d31-a82aa5a27ca0 () redhat ! com
[Download RAW message or body]
On 3/31/20 7:34 AM, Lucas A. M. Magalhaes wrote:
> This test fails intermittently in systems with heavy load as
> CLOCK_PROCESS_CPUTIME_ID is subject to scheduler pressure. Thus the
> test boundaries were relaxed to keep it from failing on such systems.
>
> A refactor of the spent time checking was made with some support
> functions. With the advantage to representing time jitter in percent
> of the target.
>
> The values used by the test boundaries are all empirical.
Comments below.
> ---
>
> Hi,
>
> changes on V6:
> - add overflow handling
> - change variables names
>
> changes on V5:
> - add tests for support_timespec_check_in_range
> - fix support_timespec_normalize
> - add comments
> - fix style
>
> changes on V4:
> - move functions to support/timespec.c
> - simplify functions
>
> changes on V3:
> - refactor support functions
> - use existing timespec-sub function
>
> changes on V2:
> - Add support functions
> ---
> support/Makefile | 1 +
> support/timespec.c | 54 +++++++++++++++
> support/timespec.h | 6 ++
> support/tst-timespec.c | 147 +++++++++++++++++++++++++++++++++++++++++
> time/tst-cpuclock1.c | 48 +++++---------
> 5 files changed, 226 insertions(+), 30 deletions(-)
> create mode 100644 support/tst-timespec.c
>
> diff --git a/support/Makefile b/support/Makefile
> index 6e38b87ebe..cacaac96a5 100644
> --- a/support/Makefile
> +++ b/support/Makefile
> @@ -233,6 +233,7 @@ tests = \
> tst-test_compare \
> tst-test_compare_blob \
> tst-test_compare_string \
> + tst-timespec \
> tst-xreadlink \
> tst-xsigstack \
>
> diff --git a/support/timespec.c b/support/timespec.c
> index ea6b947546..0f840c2764 100644
> --- a/support/timespec.c
> +++ b/support/timespec.c
> @@ -19,6 +19,8 @@
> #include <support/timespec.h>
> #include <stdio.h>
> #include <stdint.h>
> +#include <assert.h>
> +#include <intprops.h>
>
> void
> test_timespec_before_impl (const char *file, int line,
> @@ -57,3 +59,55 @@ test_timespec_equal_or_after_impl (const char *file, int line,
> (intmax_t) diff.tv_sec, (intmax_t) diff.tv_nsec);
> }
> }
> +
> +/* Returns t normalized timespec with .tv_nsec < TIMESPEC_HZ
> + and the overflows added to .tv_sec. It assumes times are
> + positive. */
> +struct timespec
> +support_timespec_normalize (struct timespec time)
> +{
> + struct timespec norm;
> + if (INT_ADD_WRAPV (time.tv_sec, (time.tv_nsec / TIMESPEC_HZ), &norm.tv_sec))
> + {
> + norm.tv_sec = (time.tv_nsec < 0) ? TYPE_MINIMUM (time_t):TYPE_MAXIMUM (time_t);
> + }
> + norm.tv_nsec = time.tv_nsec % TIMESPEC_HZ;
> + return norm;
> +}
> +
> +#define TIMESPEC_SHRINK(time, shrinked) \
> +{ \
> + if (INT_MULTIPLY_WRAPV(time.tv_sec, TIMESPEC_HZ, &shrinked)) \
> + { \
> + shrinked = (time.tv_sec < 0) ? TYPE_MINIMUM(long): TYPE_MAXIMUM(long); \
> + } \
> + if (INT_ADD_WRAPV(shrinked, time.tv_nsec, &shrinked)) \
> + { \
> + shrinked = (time.tv_nsec < 0) ? TYPE_MINIMUM(long): TYPE_MAXIMUM(long); \
> + } \
> +} \
> +
> +/* Returns TRUE if the observed time is within the given percentage bounds of
> +the expected time, and FALSE otherwise.
> +For example the call
> +
> +support_timespec_check_in_range(expected, observed, .5, 1.2);
> +
> +will check if
> +
> +.5 <= observed/expected <= 1.2
> +
> +In other words it will check if observed time is within 50% to 120% of
> +the expected time. */
> +int
> +support_timespec_check_in_range (struct timespec expected, struct timespec observed,
> + double lower_bound, double upper_bound)
> +{
> + assert (upper_bound >= lower_bound);
> + long expected_norm, observed_norm;
> + TIMESPEC_SHRINK(expected, expected_norm);
Add /* Don't divide by zero. */
> + assert(expected_norm != 0);
> + TIMESPEC_SHRINK(observed, observed_norm);
> + double ratio = (double)observed_norm / expected_norm;
> + return (lower_bound <= ratio && ratio <= upper_bound);
> +}
> diff --git a/support/timespec.h b/support/timespec.h
> index c5852dfe75..86040627c2 100644
> --- a/support/timespec.h
> +++ b/support/timespec.h
> @@ -48,6 +48,12 @@ void test_timespec_equal_or_after_impl (const char *file, int line,
> const struct timespec left,
> const struct timespec right);
>
> +struct timespec support_timespec_normalize (struct timespec time);
> +
> +int support_timespec_check_in_range (struct timespec expected, struct timespec observed,
> + double lower_bound, double upper_bound);
> +
> +
> /* Check that the timespec on the left represents a time before the
> time on the right. */
> #define TEST_TIMESPEC_BEFORE(left, right) \
> diff --git a/support/tst-timespec.c b/support/tst-timespec.c
> new file mode 100644
> index 0000000000..06d817a421
> --- /dev/null
> +++ b/support/tst-timespec.c
> @@ -0,0 +1,147 @@
> +/* Test for support_timespec_check_in_range function.
> + Copyright (C) 2020 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
> + <https://www.gnu.org/licenses/>. */
> +
> +#include <support/timespec.h>
> +#include <support/check.h>
> +#include <limits.h>
> +
> +struct timespec_test_case
> +{
> + struct timespec expected;
> + struct timespec observed;
> + double upper_bound;
> + double lower_bound;
> + int result;
> +};
> +
> +struct timespec_test_case test_cases[] = {
> + // 0 - In range
> + {.expected = { .tv_sec = 1, .tv_nsec = 0},
> + .observed = {.tv_sec = 1, .tv_nsec = 0},
> + .upper_bound = 1, .lower_bound = 1, .result = 1,
> + },
> + // 1 - Out of range
> + {.expected = { .tv_sec = 1, .tv_nsec = 0},
> + .observed = {.tv_sec = 2, .tv_nsec = 0},
> + .upper_bound = 1, .lower_bound = 1, .result = 0,
> + },
> + // 2 - Upper Bound
> + {.expected = { .tv_sec = 1, .tv_nsec = 0},
> + .observed = {.tv_sec = 2, .tv_nsec = 0},
> + .upper_bound = 2, .lower_bound = 1, .result = 1,
> + },
> + // 3 - Lower Bound
> + {.expected = { .tv_sec = 1, .tv_nsec = 0},
> + .observed = {.tv_sec = 0, .tv_nsec = 0},
> + .upper_bound = 1, .lower_bound = 0, .result = 1,
> + },
> + // 4 - Out of range by nanosecs
> + {.expected = { .tv_sec = 1, .tv_nsec = 0},
> + .observed = {.tv_sec = 1, .tv_nsec = 500},
> + .upper_bound = 1, .lower_bound = 1, .result = 0,
> + },
> + // 5 - In range by nanosecs
> + {.expected = { .tv_sec = 1, .tv_nsec = 0},
> + .observed = {.tv_sec = 1, .tv_nsec = 50000},
> + .upper_bound = 1.3, .lower_bound = 1, .result = 1,
> + },
> + // 6 - Big nanosecs
> + {.expected = { .tv_sec = 1, .tv_nsec = 0},
> + .observed = {.tv_sec = 0, .tv_nsec = 4000000},
> + .upper_bound = 1, .lower_bound = .001, .result = 1,
> + },
> + // 7 - In range Negative values
> + {.expected = { .tv_sec = -1, .tv_nsec = 0},
> + .observed = {.tv_sec = -1, .tv_nsec = 0},
> + .upper_bound = 1, .lower_bound = 1, .result = 1,
> + },
> + // 8 - Out of range Negative values
> + {.expected = { .tv_sec = -1, .tv_nsec = 0},
> + .observed = {.tv_sec = -1, .tv_nsec = 0},
> + .upper_bound = -1, .lower_bound = -1, .result = 0,
> + },
> + // 9 - Negative values with negative nanosecs
> + {.expected = { .tv_sec = -1, .tv_nsec = 0},
> + .observed = {.tv_sec = -1, .tv_nsec = -2000},
> + .upper_bound = 1, .lower_bound = 1, .result = 0,
> + },
> + // 10 - Strict bounds
> + {.expected = { .tv_sec = -1, .tv_nsec = 0},
> + .observed = {.tv_sec = -1, .tv_nsec = -20000},
> + .upper_bound = 1.00002, .lower_bound = 1.0000191, .result = 1,
> + },
> + // 11 - Strict bounds with loose upper bound
> + {.expected = { .tv_sec = 1, .tv_nsec = 20000},
> + .observed = {.tv_sec = 1, .tv_nsec = 30000},
> + .upper_bound = 1.0000100000, .lower_bound = 1.0000099998, .result = 1,
> + },
> + // 12 - Strict bounds with loose lower bound
> + {.expected = { .tv_sec = 1, .tv_nsec = 20000},
> + .observed = {.tv_sec = 1, .tv_nsec = 30000},
> + .upper_bound = 1.0000099999, .lower_bound = 1.00000999979, .result = 1,
> + },
> + // 13 - Strict bounds highest precision
> + {.expected = { .tv_sec = 1, .tv_nsec = 20000},
> + .observed = {.tv_sec = 1, .tv_nsec = 30000},
> + .upper_bound = 1.00000999980001, .lower_bound = 1.00000999979999, .result = 1,
> + },
> + /* Maximum/Minimum long values */
> + // 14
> + {.expected = { .tv_sec = LONG_MAX, .tv_nsec = LONG_MAX},
> + .observed = {.tv_sec = LONG_MAX, .tv_nsec = LONG_MAX -1},
> + .upper_bound = 1, .lower_bound = .9, .result = 1,
> + },
> + // 15
> + {.expected = { .tv_sec = LONG_MAX, .tv_nsec = LONG_MAX},
> + .observed = {.tv_sec = LONG_MAX, .tv_nsec = LONG_MAX},
> + .upper_bound = 1, .lower_bound = 1, .result = 1,
> + },
> + // 16
> + {.expected = { .tv_sec = LONG_MAX, .tv_nsec = LONG_MAX},
> + .observed = {.tv_sec = LONG_MIN, .tv_nsec = LONG_MIN},
> + .upper_bound = 1, .lower_bound = 1, .result = 0,
> + },
> + // 17
> + {.expected = { .tv_sec = LONG_MIN, .tv_nsec = LONG_MIN},
> + .observed = {.tv_sec = LONG_MIN, .tv_nsec = LONG_MIN},
> + .upper_bound = 1, .lower_bound = 1, .result = 1,
> + },
> + // 18
> + {.expected = { .tv_sec = LONG_MIN, .tv_nsec = LONG_MIN},
> + .observed = {.tv_sec = LONG_MAX, .tv_nsec = LONG_MAX},
> + .upper_bound = 1, .lower_bound = 1, .result = 0,
> + }
> +};
> +
> +static int
> +do_test (void)
> +{
> + int i = 0;
> +
> + int ntests = sizeof (test_cases) / sizeof (test_cases);
> + for (i = 0; i < ntests; i++)
> + {
> + TEST_COMPARE (support_timespec_check_in_range
> + (test_cases[i].expected, test_cases[i].observed,
> + test_cases[i].lower_bound,
> + test_cases[i].upper_bound), test_cases[i].result);
> + }
> + return 0;
> +}
> +
> +#include <support/test-driver.c>
> diff --git a/time/tst-cpuclock1.c b/time/tst-cpuclock1.c
> index 0120906f23..fe9bb0a31e 100644
> --- a/time/tst-cpuclock1.c
> +++ b/time/tst-cpuclock1.c
> @@ -26,6 +26,7 @@
> #include <signal.h>
> #include <stdint.h>
> #include <sys/wait.h>
> +#include <support/timespec.h>
>
> /* This function is intended to rack up both user and system time. */
> static void
> @@ -155,16 +156,11 @@ do_test (void)
> printf ("live PID %d after sleep => %ju.%.9ju\n",
> child, (uintmax_t) after.tv_sec, (uintmax_t) after.tv_nsec);
>
> - struct timespec diff = { .tv_sec = after.tv_sec - before.tv_sec,
> - .tv_nsec = after.tv_nsec - before.tv_nsec };
> - if (diff.tv_nsec < 0)
> - {
> - --diff.tv_sec;
> - diff.tv_nsec += 1000000000;
> - }
> - if (diff.tv_sec != 0
> - || diff.tv_nsec > 600000000
> - || diff.tv_nsec < 100000000)
> + /* The bound values are empirically defined by testing this code over high cpu
> + usage and different nice values. */
> + struct timespec diff = timespec_sub (support_timespec_normalize (after),
> + support_timespec_normalize (before));
> + if (!support_timespec_check_in_range (sleeptime, diff, .0025, 1.3))
The 0.0025 is way too low.
Lets be objective about this.
Can you make these bounds the 90% percentile of the samples you have?
> {
> printf ("before - after %ju.%.9ju outside reasonable range\n",
> (uintmax_t) diff.tv_sec, (uintmax_t) diff.tv_nsec);
> @@ -194,19 +190,14 @@ do_test (void)
> }
> else
> {
> - struct timespec d = { .tv_sec = afterns.tv_sec - after.tv_sec,
> - .tv_nsec = afterns.tv_nsec - after.tv_nsec };
> - if (d.tv_nsec < 0)
> - {
> - --d.tv_sec;
> - d.tv_nsec += 1000000000;
> - }
> - if (d.tv_sec > 0
> - || d.tv_nsec < sleeptime.tv_nsec
> - || d.tv_nsec > sleeptime.tv_nsec * 2)
> + /* The bound values are empirically defined by testing this code over
> + high cpu usage and different nice values. */
> + diff = timespec_sub (support_timespec_normalize (afterns),
> + support_timespec_normalize (after));
> + if (!support_timespec_check_in_range (sleeptime, diff, .71, 1.6))
Likewise.
> {
> printf ("nanosleep time %ju.%.9ju outside reasonable range\n",
> - (uintmax_t) d.tv_sec, (uintmax_t) d.tv_nsec);
> + (uintmax_t) diff.tv_sec, (uintmax_t) diff.tv_nsec);
> result = 1;
> }
> }
> @@ -240,15 +231,12 @@ do_test (void)
> /* Should be close to 0.6. */
> printf ("dead PID %d => %ju.%.9ju\n",
> child, (uintmax_t) dead.tv_sec, (uintmax_t) dead.tv_nsec);
> -
> - diff.tv_sec = dead.tv_sec - after.tv_sec;
> - diff.tv_nsec = dead.tv_nsec - after.tv_nsec;
> - if (diff.tv_nsec < 0)
> - {
> - --diff.tv_sec;
> - diff.tv_nsec += 1000000000;
> - }
> - if (diff.tv_sec != 0 || diff.tv_nsec > 200000000)
> + /* The bound values are empirically defined by testing this code over high cpu
> + usage and different nice values. */
> + diff = timespec_sub (support_timespec_normalize (dead),
> + support_timespec_normalize (after));
> + sleeptime.tv_nsec = 100000000;
> + if (!support_timespec_check_in_range (sleeptime, diff, .7, 1.6))
Likewise.
> {
> printf ("dead - after %ju.%.9ju outside reasonable range\n",
> (uintmax_t) diff.tv_sec, (uintmax_t) diff.tv_nsec);
>
--
Cheers,
Carlos.
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic