From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 85513 invoked by alias); 9 Dec 2018 08:57:26 -0000 Mailing-List: contact gdb-patches-help@sourceware.org; run by ezmlm Precedence: bulk List-Id: List-Subscribe: List-Archive: List-Post: List-Help: , Sender: gdb-patches-owner@sourceware.org Received: (qmail 85500 invoked by uid 89); 9 Dec 2018 08:57:25 -0000 Authentication-Results: sourceware.org; auth=none X-Spam-SWARE-Status: No, score=-2.6 required=5.0 tests=BAYES_00,RCVD_IN_DNSWL_LOW,SPF_PASS autolearn=ham version=3.3.2 spammy=minute, bunch, quit, END X-HELO: mailsec119.isp.belgacom.be Received: from mailsec119.isp.belgacom.be (HELO mailsec119.isp.belgacom.be) (195.238.20.115) by sourceware.org (qpsmtpd/0.93/v0.84-503-g423c35a) with ESMTP; Sun, 09 Dec 2018 08:57:21 +0000 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=skynet.be; i=@skynet.be; q=dns/txt; s=securemail; t=1544345841; x=1575881841; h=message-id:subject:from:to:cc:date:in-reply-to: references:mime-version:content-transfer-encoding; bh=7LfCByfX/RsSKTUMuFY6GAsgSF7CoLO/tr2gVecqEU4=; b=XNBolV5MgELPWlsehp5vevqr83lnG3f7uxGU5+oOO8XAWLzGywonpJmZ x2N5Pm5oqgJTfrMIpsEPNxPCXLJEfg==; Received: from 184.205-67-87.adsl-dyn.isp.belgacom.be (HELO md) ([87.67.205.184]) by relay.skynet.be with ESMTP/TLS/AES256-GCM-SHA384; 09 Dec 2018 09:57:18 +0100 Message-ID: <1544345838.24304.2.camel@skynet.be> Subject: Re: [PATCH] Implement timestamp'ed output on "make check" From: Philippe Waroquiers To: Sergio Durigan Junior , Pedro Alves Cc: Pedro Franco de Carvalho , GDB Patches Date: Sun, 09 Dec 2018 08:57:00 -0000 In-Reply-To: <87efary5gw.fsf@redhat.com> References: <87va47ojas.fsf@linux.vnet.ibm.com> <87a7ljdaax.fsf@redhat.com> <87sgzbohzb.fsf@linux.vnet.ibm.com> <87efavbu02.fsf@redhat.com> <7d58b34f-3082-a266-7f38-79e4f80a533c@redhat.com> <5ca80f12-c329-ac40-f6a9-eb8f2b71cceb@redhat.com> <87sgzao3ib.fsf@linux.vnet.ibm.com> <87o99y301i.fsf@redhat.com> <99703054-f538-0300-2d7b-83c31357f563@redhat.com> <87y391xa44.fsf@redhat.com> <87efary5gw.fsf@redhat.com> Content-Type: text/plain; charset="UTF-8" Mime-Version: 1.0 Content-Transfer-Encoding: 8bit X-IsSubscribed: yes X-SW-Source: 2018-12/txt/msg00113.txt.bz2 On Sat, 2018-12-08 at 18:16 -0500, Sergio Durigan Junior wrote: > On Saturday, December 08 2018, Pedro Alves wrote: > > > On 12/07/2018 10:09 PM, Sergio Durigan Junior wrote: > > > On Friday, December 07 2018, Pedro Alves wrote: > > > > > > > On 12/06/2018 07:52 PM, Sergio Durigan Junior wrote: > > > > > The results can be found at , > > > > > but you're, you just have access to the consolidated gdb.log, not the > > > > > different logs under output/. > > > > > > > > Given the above, then I have to ask: what's the advantage of the > > > > new timestamped output mode? Why not just extract the info out > > > > of the gdb.log file? It's less code to maintain, and you don't > > > > have to remember to run the testsuite in a special mode, nor > > > > record stdout of the test run. > > > > > > When I was writing the timestamp script, I didn't think about extracting > > > the info from gdb.log. So there's that. I agree that it's easier to > > > have the consolidated info at the end, and I can propose a patch for > > > that based on your shell script, > > > > I think you're missing that we don't even need my previous script. As Pedro said: > > > > "Still, the merged gdb.log file seems to already have the completion > > ^^^^^^ > > times, e.g.: > > > > testcase [...]gdb.trace/unavailable.exp completed in 28 seconds" > > > > > > So all we need is something like this: > > > > $ grep "completed in " testsuite/gdb.log | awk '{print $5 " seconds for " $2}' | sort -n | tail -n 10 > > 20 seconds for /home/pedro/gdb/binutils-gdb/src/gdb/testsuite/gdb.base/fork-running-state.exp > > 23 seconds for /home/pedro/gdb/binutils-gdb/src/gdb/testsuite/gdb.base/gnu-ifunc.exp > > 28 seconds for /home/pedro/gdb/binutils-gdb/src/gdb/testsuite/gdb.base/attach-pie-misread.exp > > 28 seconds for /home/pedro/gdb/binutils-gdb/src/gdb/testsuite/gdb.base/foll-vfork.exp > > 29 seconds for /home/pedro/gdb/binutils-gdb/src/gdb/testsuite/gdb.base/attach.exp > > 31 seconds for /home/pedro/gdb/binutils-gdb/src/gdb/testsuite/gdb.base/checkpoint.exp > > 32 seconds for /home/pedro/gdb/binutils-gdb/src/gdb/testsuite/gdb.base/checkpoint-ns.exp > > 37 seconds for /home/pedro/gdb/binutils-gdb/src/gdb/testsuite/gdb.base/dprintf-detach.exp > > 49 seconds for /home/pedro/gdb/binutils-gdb/src/gdb/testsuite/gdb.base/gdb-sigterm.exp > > 78 seconds for /home/pedro/gdb/binutils-gdb/src/gdb/testsuite/gdb.base/break-interp.exp > > Ah, sorry, indeed I was missing this point. Well, in any case, we need > some kind of script, right? I think it'd be a good idea to generate > this report at the end of the test run, and put it into a file under the > testsuite dir, WDYT? As suggested by Pedro in https://sourceware.org/ml/gdb-patches/2018-12/msg00022.html, I am busy measuring how much the patch [RFA] Add FORCE_LOCAL_GDB_QUIT_WAIT testsuite parameter. slows down the regression test, if always activated. For this, I am using the extract times script Pedro did. So, IMO, such a script is very useful. I am also post-processing its output with the below 'avg' script: awk '{ sum = sum + $1;  n = n + 1}   END { printf("sum %d N %d avg %f\n",sum,n,sum/n) }' "$@" e.g. doing extract-times ... | avg Note that regarding the slowdown by the FORCE_LOCAL_GDB_QUIT_WAIT: it seems that a significant nr of tests are somewhat faster when activating this FORCE QUIT WAIT, but that is all based on a second precision, e.g. 30 tests or so take now 0 seconds rather than 1 second, or 1 second instead of 2 seconds. So, if easy to do, it would be nice to have a precision better than a second, to have a better idea of small improvement or degradation. For the patch 'slow down/speed up' : in total, the patch is still significantly slowing down the testsuite, as a bunch of tests are taking about one minute more due to timeouts doing the quit. I am trying to have a better logic in FORCE QUIT WAIT to solve that : it is not impossible that at the end, doing a clean QUIT+WAIT might slightly speed up the testsuite (measured doing make check RUNTESTFLAGS="GDB=$PWD/gdb FORCE_LOCAL_GDB_QUIT_WAIT=1" FORCE_PARALLEL="1" -j1 ). Thanks Philippe