Re: [PATCH] Implement timestamp'ed output on "make check"

[Philippe Waroquiers <philippe.waroquiers@skynet.be>]

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 <https://gdb-build.sergiodj.net/results/>,
> > > > > 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