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

Philippe Waroquiers
2018-12-09T08:57:26Z

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