Re: [PATCH v5] Fix time/tst-cpuclock1 intermitent failures

[Carlos O'Donell <carlos@redhat.com>]

On 3/23/20 1:20 PM, Lucas A. M. Magalhaes via Libc-alpha 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.

Suggestions below.

Looking forward to v6.

> ---
> 
> Hi,
> 
> 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     |  36 ++++++++++
>  support/timespec.h     |   6 ++
>  support/tst-timespec.c | 147 +++++++++++++++++++++++++++++++++++++++++
>  time/tst-cpuclock1.c   |  48 +++++---------
>  5 files changed, 208 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 \

OK.

>    tst-xreadlink \
>    tst-xsigstack \
>  
> diff --git a/support/timespec.c b/support/timespec.c
> index ea6b947546..53e07566b6 100644
> --- a/support/timespec.c
> +++ b/support/timespec.c
> @@ -19,6 +19,7 @@
>  #include <support/timespec.h>
>  #include <stdio.h>
>  #include <stdint.h>
> +#include <assert.h>
>  
>  void
>  test_timespec_before_impl (const char *file, int line,
> @@ -57,3 +58,38 @@ 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.  */
> +struct timespec
> +support_timespec_normalize (struct timespec t)

Please don't use single variable names. Use "from" or "raw".

> +{
> +  struct timespec r;
> +  r.tv_sec = t.tv_sec + (t.tv_nsec / TIMESPEC_HZ);
> +  r.tv_nsec = t.tv_nsec % TIMESPEC_HZ;
> +  return r;
> +}

Likewise "r" could be "cooked" or "norm".

> +
> +/* 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 = expected.tv_sec * TIMESPEC_HZ + expected.tv_nsec;

This can cause overflow/underflow.

Please review timespec_add.

We should set this to a extreme value just like timepsec_add for both overflow/underflow.

> +  assert(expected_norm != 0);

Why can't expected_norm be zero?

If you have an abstract timespec you may want to check against that.

I would assert that all values are *positive* and write that into the comments
above.

> +  long observed_norm = observed.tv_sec * TIMESPEC_HZ + observed.tv_nsec;
> +  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..9bd6942957 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 t);

Please avoid single character variable names.

> +
> +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.

OK.

> +   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,
> +  }
> +};

Several of the tests above would cause overflow in the normalization.

I'll review them more closely in v6.

> +
> +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;
> +}

OK.

> +
> +#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 value of 0.0025 doesn't seem correct, can you please confirm that?

This is supposed to be a 0.5s wait, and wait of 1ms doesn't seem correct.

>      {
>        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))

OK.

>  	    {
>  	      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))

OK.

>      {
>        printf ("dead - after %ju.%.9ju outside reasonable range\n",
>  	      (uintmax_t) diff.tv_sec, (uintmax_t) diff.tv_nsec);
> 


-- 
Cheers,
Carlos.