From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from us-smtp-delivery-74.mimecast.com (us-smtp-delivery-74.mimecast.com [63.128.21.74]) by sourceware.org (Postfix) with ESMTP id A0C57385B836 for ; Mon, 23 Mar 2020 21:06:42 +0000 (GMT) DMARC-Filter: OpenDMARC Filter v1.3.2 sourceware.org A0C57385B836 Received: from mail-qv1-f70.google.com (mail-qv1-f70.google.com [209.85.219.70]) (Using TLS) by relay.mimecast.com with ESMTP id us-mta-156-FNoyvAXUO9Kd7YMyaSBSKA-1; Mon, 23 Mar 2020 17:06:38 -0400 X-MC-Unique: FNoyvAXUO9Kd7YMyaSBSKA-1 Received: by mail-qv1-f70.google.com with SMTP id f12so3879825qvw.1 for ; Mon, 23 Mar 2020 14:06:38 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:subject:to:references:from:organization :message-id:date:user-agent:mime-version:in-reply-to :content-language:content-transfer-encoding; bh=jh/4IE+PaBU952znYjhyKZ1xuvNbGwsNHydD3wTdoxg=; b=mSnbkqnJVTnd3d2cEm8cg9uYW7w0ofIaLyBlQGvikid/a22dgIi9T7Vd2+nwXHPTd3 wuDNLBeN2Pi+m8nAKHvnnl/uDIyOL640SoxS062JFouDWyrJp0skktL764q1r8LanGib qv++SgNp2YdplUiQdaTRW66n3dfJuL4ihjounOgj8nbNmwJ+NPMozQSqMsDaNmBagAwM 675f8iDrsjVhpW7anBo4GimcZMKAmAiO1JX335L7iaL58vGF/RyLsOSnCrva6GVC+cKe QaJLMZCqjulRqbLttLfo07gHK3eVQ0ngFhwkey6jvk2WBA18GSpIlK9BaDfWm5v/dY9H WJ2Q== X-Gm-Message-State: ANhLgQ3AvDhagBBW/ndvdjU0KiyDLmCW9mx5zXvRnKkFEAL8E6HF4yl0 7J0OnrGeNgA67UNle4thVJdRidVuJXFJxSigcoUFaM6bUtuwHEpuJyH8rO1CY2QYDoJ/uP05Rn6 okGtI39refT40Mv1iN2y+ X-Received: by 2002:ae9:ebc1:: with SMTP id b184mr22367674qkg.49.1584997597080; Mon, 23 Mar 2020 14:06:37 -0700 (PDT) X-Google-Smtp-Source: ADFU+vv5WB0CQ6aIuigffH6IQzy5AUFWBO3ljewPutGv4ObLn2B17QHgR+SzLZt3fy1d8plKeQLZSw== X-Received: by 2002:ae9:ebc1:: with SMTP id b184mr22367643qkg.49.1584997596612; Mon, 23 Mar 2020 14:06:36 -0700 (PDT) Received: from [192.168.1.4] (198-84-170-103.cpe.teksavvy.com. [198.84.170.103]) by smtp.gmail.com with ESMTPSA id f203sm12035545qke.100.2020.03.23.14.06.35 (version=TLS1_3 cipher=TLS_AES_128_GCM_SHA256 bits=128/128); Mon, 23 Mar 2020 14:06:36 -0700 (PDT) Subject: Re: [PATCH v5] Fix time/tst-cpuclock1 intermitent failures To: "Lucas A. M. Magalhaes" , libc-alpha@sourceware.org References: <20200310162001.11737-1-lamm@linux.ibm.com> <20200323172008.11370-1-lamm@linux.ibm.com> From: Carlos O'Donell Organization: Red Hat Message-ID: Date: Mon, 23 Mar 2020 17:06:34 -0400 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101 Thunderbird/68.5.0 MIME-Version: 1.0 In-Reply-To: <20200323172008.11370-1-lamm@linux.ibm.com> Content-Language: en-US X-Mimecast-Spam-Score: 0 X-Mimecast-Originator: redhat.com Content-Type: text/plain; charset=windows-1252 Content-Transfer-Encoding: 7bit X-Spam-Status: No, score=-27.5 required=5.0 tests=BAYES_00, DKIMWL_WL_HIGH, DKIM_SIGNED, DKIM_VALID, DKIM_VALID_AU, DKIM_VALID_EF, GIT_PATCH_0, GIT_PATCH_1, GIT_PATCH_2, GIT_PATCH_3, KAM_SHORT, RCVD_IN_DNSWL_NONE, SPF_HELO_NONE, SPF_PASS, TXREP autolearn=ham autolearn_force=no version=3.4.2 X-Spam-Checker-Version: SpamAssassin 3.4.2 (2018-09-13) on server2.sourceware.org X-BeenThere: libc-alpha@sourceware.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Libc-alpha mailing list List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 23 Mar 2020 21:06:45 -0000 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 > #include > #include > +#include > > 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 > + . */ > + > +#include > +#include > +#include > + > +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 > 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 > #include > #include > +#include > > /* 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.