| Message ID | orwnf0foz2.fsf@lxoliva.fsfla.org |
|---|---|
| State | New |
| Headers | show |
| Series | libstdc++: testsuite: async.cc early timeout | expand |
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> >
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.
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)); } }