Re: [PATCH] libstdc++: testsuite: async.cc early timeout

[Jonathan Wakely <jwakely@redhat.com>]

On Thu, 5 May 2022 at 07:56, Alexandre Oliva via Libstdc++
<libstdc++@gcc.gnu.org> wrote:
>
>
> The async call and future variable initialization may take a while to
> complete on uniprocessors, especially if the async call and other
> unrelated processes run before context switches back to the main
> thread.
>
> Taking steady_begin only then sometimes causes the 11*100ms in the
> slow clock, counted from before the async call, to not be enough for
> the measured wait to last 1s in the steady clock.  I've seen it fall
> short of 1s by as little as a third of a tenth of a second in some
> cases, but in one surprisingly extreme case the elapsed wait time got
> only up to 216.7ms.
>
> Initializing both timestamps next to each other, before the async
> call, appears to avoid the problem entirely.  I've renamed the
> variable moved out of the block so as to avoid name hiding in the
> subsequent block, that has another steady_begin variable.
>
> The second wait fails a lot less frequently, but the 2s limit has been
> exceeded, so I'm bumping up the max sleep to ~4s, and the tolerance to
> 3s.
>
>
> I wasn't sure about whether to leave the added outputs that I put in to
> confirm the failure modes.  Please let me know in case they're
> undersirable, and I'll take them out.
>
> Regstrapped on x86_64-linux-gnu, ppc64le-linux-gnu, and also tested on
> ppc- and ppc64-vx7r2.  Ok to install?

Hi Alex,

This one slipped through the cracks, sorry.

Leaving the outputs seems useful in this case. For timing-sensitive
tests like this it's useful to have the output for exactly how long it
took when there's a FAIL in the logs.

The patch is OK for trunk now (and should still apply cleanly).



>
>
> for  libstdc++-v3/ChangeLog
>
>         * testsuite/30_threads/async/async.cc (test04): Initialize
>         steady_start, renamed from steady_begin, next to slow_start.
>         Increase tolerance for final wait.
> ---
>  libstdc++-v3/testsuite/30_threads/async/async.cc |   17 ++++++++++++-----
>  1 file changed, 12 insertions(+), 5 deletions(-)
>
> diff --git a/libstdc++-v3/testsuite/30_threads/async/async.cc b/libstdc++-v3/testsuite/30_threads/async/async.cc
> index 38943ff1a9a5e..a36e1aee8bdef 100644
> --- a/libstdc++-v3/testsuite/30_threads/async/async.cc
> +++ b/libstdc++-v3/testsuite/30_threads/async/async.cc
> @@ -20,6 +20,7 @@
>  // with this library; see the file COPYING3.  If not see
>  // <http://www.gnu.org/licenses/>.
>
> +#include <iostream>
>
>  #include <future>
>  #include <thread>
> @@ -133,6 +134,7 @@ void test04()
>  {
>    using namespace std::chrono;
>
> +  auto const steady_start = steady_clock::now();
>    auto const slow_start = slow_clock::now();
>    future<void> f1 = async(launch::async, []() {
>        std::this_thread::sleep_for(std::chrono::seconds(2));
> @@ -140,21 +142,26 @@ void test04()
>
>    // Wait for ~1s
>    {
> -    auto const steady_begin = steady_clock::now();
>      auto const status = f1.wait_until(slow_start + milliseconds(100));
>      VERIFY(status == std::future_status::timeout);
> -    auto const elapsed = steady_clock::now() - steady_begin;
> +    auto const elapsed = steady_clock::now() - steady_start;
> +    if (elapsed < seconds(1))
> +      std::cout << elapsed.count () << "ns < 1s" << std::endl;
>      VERIFY(elapsed >= seconds(1));
>      VERIFY(elapsed < seconds(2));
>    }
>
> -  // Wait for up to ~2s more
> +  // Wait for up to ~4s more, but since the async sleep completes, the
> +  // actual wait may be shorter than 1s.  Tolerate 3s because 2s
> +  // hasn't been enough in some extreme cases.
>    {
>      auto const steady_begin = steady_clock::now();
> -    auto const status = f1.wait_until(slow_start + milliseconds(300));
> +    auto const status = f1.wait_until(slow_start + milliseconds(500));
>      VERIFY(status == std::future_status::ready);
>      auto const elapsed = steady_clock::now() - steady_begin;
> -    VERIFY(elapsed < seconds(2));
> +    if (elapsed >= seconds(3))
> +      std::cout << elapsed.count () << "ns > 2s" << std::endl;
> +    VERIFY(elapsed < seconds(3));
>    }
>  }
>
>
>
> --
> Alexandre Oliva, happy hacker                https://FSFLA.org/blogs/lxo/
>    Free Software Activist                       GNU Toolchain Engineer
> Disinformation flourishes because many people care deeply about injustice
> but very few check the facts.  Ask me about <https://stallmansupport.org>
>