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

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

[Alexandre Oliva]

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?


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>

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

[Jonathan Wakely]

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

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

[Alexandre Oliva]

On Feb  3, 2023, Jonathan Wakely <jwakely@redhat.com> wrote:

> This one slipped through the cracks, sorry.

Oh, nice, thanks, I'd missed the review too, for a whole month :-)

I've just found the unread message.  I'll have a happier weekend.  I did
not even recall this patch was still pending, and this very test was the
one remaining issue for which I got occasional fails on
arm-vx7r2/gcc-12, and I still hadn't started looking into it.

We may still have other fails in this test (we used to have two
different fail modes in async.cc, the other is probably yet to be
upstreamed, but it was just an xfail), but this is progress :-)

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

Thanks, I'm checking it in now.

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

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