From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from us-smtp-delivery-124.mimecast.com (us-smtp-delivery-124.mimecast.com [170.10.133.124]) by sourceware.org (Postfix) with ESMTPS id 062FB3858D20 for ; Fri, 3 Feb 2023 11:30:27 +0000 (GMT) DMARC-Filter: OpenDMARC Filter v1.4.2 sourceware.org 062FB3858D20 Authentication-Results: sourceware.org; dmarc=pass (p=none dis=none) header.from=redhat.com Authentication-Results: sourceware.org; spf=pass smtp.mailfrom=redhat.com DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=redhat.com; s=mimecast20190719; t=1675423826; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:cc:mime-version:mime-version:content-type:content-type: in-reply-to:in-reply-to:references:references; bh=HwoQUGvnRNcXQwEkM4HArDhlNK1gi/INMSNyQ20GLb8=; b=JiFTEouDCaRTszaXxJLMtA6wlhgA4oaO7VLUPsRXJmF2jMXxLxVD44GVtMyBZIkvEaJyWc v3C7181xGyK7l7+LiXGhAttVi6U7xjgBZq0jKzUWlTzsmKz/mQ2Tklvw6SVMp8SkCw37+e usooGhh27ViEAV+D0HBi9iHkiqwBfKc= Received: from mail-lj1-f199.google.com (mail-lj1-f199.google.com [209.85.208.199]) by relay.mimecast.com with ESMTP with STARTTLS (version=TLSv1.3, cipher=TLS_AES_128_GCM_SHA256) id us-mta-508-q7qtvEZNMvuUKJUdDXXfUg-1; Fri, 03 Feb 2023 06:30:25 -0500 X-MC-Unique: q7qtvEZNMvuUKJUdDXXfUg-1 Received: by mail-lj1-f199.google.com with SMTP id o2-20020a2ebd82000000b0029051ecb8d2so1208150ljq.20 for ; Fri, 03 Feb 2023 03:30:25 -0800 (PST) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=cc:to:subject:message-id:date:from:in-reply-to:references :mime-version:x-gm-message-state:from:to:cc:subject:date:message-id :reply-to; bh=HwoQUGvnRNcXQwEkM4HArDhlNK1gi/INMSNyQ20GLb8=; b=ahc8ER2JSLfsooOWSukvNPmOX347SHcWSLfGRFfRxDHaX/TMS9H8oqBII6Al1M2deZ gcSA4RrYhVqBSsSRDKEdlnmGs2FBwAMqWeIwEx260d6TYR7GoaMg+Drwhs0lcsRQafCH 7yjUADWiyhEcCA7eMAnNYdmHZW5p5iXRwQ9ZnmNuOkyFiOC60MfVaraKGJ6BpI6P9RIq +SJAFpJy84pgolPeY5K/DIIvzg3zw3aYzaCmv3zb58b1cAEsjbVIPAGUqbfECz8uIv8K ZTNT7FnWa8qXKKuloKRZHYdDyLvfT5iQu9di0mgi7KB5sFQpqRq2t/6sHQ7xmCbN1OfJ 2mfQ== X-Gm-Message-State: AO0yUKVVu+/ihsGlU0LwhWQHq95BT67Qseyf4iOq49zioKRYz/8Fw+HA lnYGT/rOV8w+GqbNwBGbaw6zYA2xY5D/y+rOELP7peJOsPzeTb0CUudKEmP7vQ1EbZwtaSPJZ5w HrSOVN7bI4CzSGk/T3/9ZZc0msKdhGKRSzA== X-Received: by 2002:a05:651c:1253:b0:28c:efbc:24a6 with SMTP id h19-20020a05651c125300b0028cefbc24a6mr1514639ljh.88.1675423824100; Fri, 03 Feb 2023 03:30:24 -0800 (PST) X-Google-Smtp-Source: AK7set8wP0WFCAmuyijZVRWXFgIKKTfh1qCR+4pTqKPCGhf4AASdMMaTcgdUg5u9fWZ0XBkJyQPJYDc2MajPQ7PSfhk= X-Received: by 2002:a05:651c:1253:b0:28c:efbc:24a6 with SMTP id h19-20020a05651c125300b0028cefbc24a6mr1514635ljh.88.1675423823848; Fri, 03 Feb 2023 03:30:23 -0800 (PST) MIME-Version: 1.0 References: In-Reply-To: From: Jonathan Wakely Date: Fri, 3 Feb 2023 11:30:12 +0000 Message-ID: Subject: Re: [PATCH] libstdc++: testsuite: async.cc early timeout To: Alexandre Oliva Cc: gcc-patches@gcc.gnu.org, libstdc++@gcc.gnu.org X-Mimecast-Spam-Score: 0 X-Mimecast-Originator: redhat.com Content-Type: text/plain; charset="UTF-8" X-Spam-Status: No, score=-12.0 required=5.0 tests=BAYES_00,DKIMWL_WL_HIGH,DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,DKIM_VALID_EF,GIT_PATCH_0,KAM_SHORT,RCVD_IN_DNSWL_NONE,RCVD_IN_MSPIKE_H2,SPF_HELO_NONE,SPF_NONE,TXREP autolearn=ham autolearn_force=no version=3.4.6 X-Spam-Checker-Version: SpamAssassin 3.4.6 (2021-04-09) on server2.sourceware.org List-Id: On Thu, 5 May 2022 at 07:56, Alexandre Oliva via Libstdc++ 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 > // . > > +#include > > #include > #include > @@ -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 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 >