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

[Alan Hayward <Alan dot Hayward at arm dot com>]

> On 22 Nov 2018, at 22:12, Sergio Durigan Junior <sergiodj@redhat.com> wrote:
> 
> It is unfortunately not uncommon to have tests hanging on some of the
> BuildBot workers.  For example, the ppc64be/ppc64le+gdbserver builders
> are especially in a bad state when it comes to testing GDB/gdbserver,
> and we can have builds that take an absurd amount of time to
> finish (almost 1 week for one single build, for example).
> 
> It may be hard to diagnose these failures, because sometimes we don't
> have access to the faulty systems, and other times we're just too busy
> to wait and check which test is actually hanging.  During one of our
> conversations about the topic, someone proposed that it would be a
> good idea to have a timestamp put together with stdout output, so that
> we can come back later and examine which tests are taking too long to
> complete.

Having encountered the same issue, I really like this patch.

> 
> Here's my proposal to do this.  The very first thing I tried to do was
> to use "ts(1)" to achieve this feature, and it obviously worked, but
> the problem is that I'm afraid "ts(1)" may not be widely available on
> every system we support.  Therefore, I decided to implement a *very*
> simple version of "ts(1)", in Python 3, which basically does the same
> thing: iterate over the stdin lines, and prepend a timestamp onto
> them.
> 
> As for testsuite/Makefile.in, the user can now specify two new
> variables to enable timestamp'ed output: TS (which enables the
> output), and TS_FORMAT (optional, used to specify another timestamp
> format according to "strftime").
> 
> Here's an example of how the output looks like:
> 
>  ...
>  [Nov 22 17:07:19] Running binutils-gdb/gdb/testsuite/gdb.base/call-strs.exp ...
>  [Nov 22 17:07:19] Running binutils-gdb/gdb/testsuite/gdb.base/step-over-no-symbols.exp ...
>  [Nov 22 17:07:20] Running binutils-gdb/gdb/testsuite/gdb.base/all-architectures-6.exp ...
>  [Nov 22 17:07:20] Running binutils-gdb/gdb/testsuite/gdb.base/hashline3.exp ...
>  [Nov 22 17:07:20] Running binutils-gdb/gdb/testsuite/gdb.base/max-value-size.exp ...
>  [Nov 22 17:07:20] Running binutils-gdb/gdb/testsuite/gdb.base/quit-live.exp ...
>  [Nov 22 17:07:46] Running binutils-gdb/gdb/testsuite/gdb.base/paginate-bg-execution.exp ...
>  [Nov 22 17:07:56] Running binutils-gdb/gdb/testsuite/gdb.base/gcore-buffer-overflow.exp ...
>  [Nov 22 17:07:56] Running binutils-gdb/gdb/testsuite/gdb.base/gcore-relro.exp ...
>  [Nov 22 17:07:56] Running binutils-gdb/gdb/testsuite/gdb.base/watchpoint-delete.exp ...
>  [Nov 22 17:07:56] Running binutils-gdb/gdb/testsuite/gdb.base/breakpoint-in-ro-region.exp ...
>  [Nov 22 17:07:56] Running binutils-gdb/gdb/testsuite/gdb.base/vla-sideeffect.exp ...
>  [Nov 22 17:07:57] Running binutils-gdb/gdb/testsuite/gdb.base/unload.exp ...
>  ...
> 
> (What, gdb.base/quit-live.exp is taking 26 seconds to complete?!)
> 
> I've also tested this with FORCE_PARALLEL=1 -j8, and the output still
> looks clean (i.e., not intertwined).

I tried adding a pid to the output (with os.getpid()) and ran with FORCE_PARALLEL=1 -j55

Sample output:

[Nov 23 14:23:31] [32975] /work/alahay01/gdb-HEAD/build-aarch64/gdb/testsuite/../../gdb/gdb version  8.2.50.20181123-git -nw -nx -data-directory /work/alahay01/gdb-HEAD/build-aarch64/gdb/testsuite/../data-directory
[Nov 23 14:23:31] [32975]
[Nov 23 14:23:34] [32485] FAIL: gdb.threads/create-fail.exp: iteration 4: run till end (timeout)
[Nov 23 14:23:39] [28592] FAIL: gdb.threads/process-dies-while-detaching.exp: single-process: detach: killed outside: continue to breakpoint: _exit (timeout)
[Nov 23 14:23:44] [32485] FAIL: gdb.threads/create-fail.exp: iteration 5: run till end (timeout)
[Nov 23 14:23:49] [28592] FAIL: gdb.threads/process-dies-while-detaching.exp: single-process: detach: killed outside: get integer valueof "mypid" (timeout)
[Nov 23 14:23:55] [32485] FAIL: gdb.threads/create-fail.exp: iteration 6: run till end (timeout)
[Nov 23 14:23:55] [39624]
[Nov 23 14:23:55] [39624] 		=== gdb Summary ===
[Nov 23 14:23:55] [39624]
[Nov 23 14:23:55] [39624] # of expected passes		769
[Nov 23 14:23:55] [39624] /work/alahay01/gdb-HEAD/build-aarch64/gdb/testsuite/../../gdb/gdb version  8.2.50.20181123-git -nw -nx -data-directory /work/alahay01/gdb-HEAD/build-aarch64/gdb/testsuite/../data-directory
[Nov 23 14:23:55] [39624]
[Nov 23 14:23:58] [34046]
[Nov 23 14:23:58] [34046] 		=== gdb Summary ===
[Nov 23 14:23:58] [34046]
[Nov 23 14:23:58] [34046] # of expected passes		6
[Nov 23 14:23:58] [34046] /work/alahay01/gdb-HEAD/build-aarch64/gdb/testsuite/../../gdb/gdb version  8.2.50.20181123-git -nw -nx -data-directory /work/alahay01/gdb-HEAD/build-aarch64/gdb/testsuite/../data-directory
[Nov 23 14:23:58] [34046]
[Nov 23 14:24:01] [28592] FAIL: gdb.threads/process-dies-while-detaching.exp: single-process: continue: detach: continue to breakpoint: _exit (timeout)
[Nov 23 14:24:05] [32485] FAIL: gdb.threads/create-fail.exp: iteration 7: run till end (timeout)
[Nov 23 14:24:11] [28592] FAIL: gdb.threads/process-dies-while-detaching.exp: single-process: continue: detach: continue (timeout)
[Nov 23 14:24:13] [31641]
[Nov 23 14:24:13] [31641] 		=== gdb Summary ===
[Nov 23 14:24:13] [31641]
[Nov 23 14:24:13] [31641] # of expected passes		33
[Nov 23 14:24:13] [31641] # of unexpected failures	4
[Nov 23 14:24:13] [33745]
[Nov 23 14:24:13] [33745] 		=== gdb Summary ===
[Nov 23 14:24:13] [33745]

Look how spaced apart the 32485 entries are. I think it needs a pid in the output.


> 
> Output to stderr is not timestamp'ed, but I don't think that will be a
> problem for us.  If it is, we can revisit the solution and extend it.
> 
> gdb/testsuite/ChangeLog:
> 2018-11-22  Sergio Durigan Junior  <sergiodj@redhat.com>
> 
> 	* Makefile.in (TIMESTAMP): New variable.
> 	(check-single): Add $(TIMESTAMP) to the end of $(DO_RUNTEST)
> 	command.
> 	(check-single-racy): Likewise.
> 	(check/%.exp): Likewise.
> 	(check-racy/%.exp): Likewise.
> 	(workers/%.worker): Likewise.
> 	(build-perf): Likewise.
> 	(check-perf): Likewise.
> 	* README: Describe new "TS" and "TS_FORMAT" variables.
> 	* print-ts.py: New file.
> ---
> gdb/testsuite/Makefile.in | 20 ++++++++++-------
> gdb/testsuite/README      | 20 +++++++++++++++++
> gdb/testsuite/print-ts.py | 45 +++++++++++++++++++++++++++++++++++++++
> 3 files changed, 77 insertions(+), 8 deletions(-)
> create mode 100755 gdb/testsuite/print-ts.py
> 
> diff --git a/gdb/testsuite/Makefile.in b/gdb/testsuite/Makefile.in
> index ece7e252c5..b526f579be 100644
> --- a/gdb/testsuite/Makefile.in
> +++ b/gdb/testsuite/Makefile.in
> @@ -158,6 +158,10 @@ check: all $(abs_builddir)/site.exp
> check-read1:
> 	$(MAKE) READ1="1" check
> 
> +# Check whether we need to print the timestamp for each line of
> +# status.
> +TIMESTAMP = $(if $(TS),| $(srcdir)/print-ts.py $(if $(TS_FORMAT),$(TS_FORMAT),),)
> +
> # All the hair to invoke dejagnu.  A given invocation can just append
> # $(RUNTESTFLAGS)
> DO_RUNTEST = \
> @@ -192,7 +196,7 @@ check-gdb.%:
> 	$(MAKE) check TESTS="gdb.$*/*.exp"
> 
> check-single:
> -	$(DO_RUNTEST) $(RUNTESTFLAGS) $(expanded_tests_or_none)
> +	$(DO_RUNTEST) $(RUNTESTFLAGS) $(expanded_tests_or_none) $(TIMESTAMP)
> 
> check-single-racy:
> 	-rm -rf cache racy_outputs temp
> @@ -208,7 +212,7 @@ check-single-racy:
> 	for n in `seq $$racyiter` ; do \
> 	  mkdir -p racy_outputs/$$n; \
> 	  $(DO_RUNTEST) --outdir=racy_outputs/$$n $(RUNTESTFLAGS) \
> -	    $(expanded_tests_or_none); \
> +	    $(expanded_tests_or_none) $(TIMESTAMP); \
> 	done; \
> 	$(srcdir)/analyze-racy-logs.py \
> 	  `ls racy_outputs/*/gdb.sum` > racy.sum; \
> @@ -273,7 +277,7 @@ do-check-parallel: $(TEST_TARGETS)
> 
> check/%.exp:
> 	-mkdir -p outputs/$*
> -	@$(DO_RUNTEST) GDB_PARALLEL=yes --outdir=outputs/$* $*.exp $(RUNTESTFLAGS)
> +	@$(DO_RUNTEST) GDB_PARALLEL=yes --outdir=outputs/$* $*.exp $(RUNTESTFLAGS) $(TIMESTAMP)
> 
> do-check-parallel-racy: $(TEST_TARGETS)
> 	@:
> @@ -282,7 +286,7 @@ check-racy/%.exp:
> 	-mkdir -p racy_outputs/$(RACY_OUTPUT_N)/$*
> 	$(DO_RUNTEST) GDB_PARALLEL=yes \
> 	  --outdir=racy_outputs/$(RACY_OUTPUT_N)/$* $*.exp \
> -	  $(RUNTESTFLAGS)
> +	  $(RUNTESTFLAGS) $(TIMESTAMP)
> 
> check/no-matching-tests-found:
> 	@echo ""
> @@ -292,7 +296,7 @@ check/no-matching-tests-found:
> # Utility rule invoked by step 2 of the build-perf rule.
> workers/%.worker:
> 	mkdir -p gdb.perf/outputs/$*
> -	$(DO_RUNTEST) --outdir=gdb.perf/outputs/$* lib/build-piece.exp WORKER=$* GDB_PARALLEL=gdb.perf $(RUNTESTFLAGS) GDB_PERFTEST_MODE=compile GDB_PERFTEST_SUBMODE=build-pieces
> +	$(DO_RUNTEST) --outdir=gdb.perf/outputs/$* lib/build-piece.exp WORKER=$* GDB_PARALLEL=gdb.perf $(RUNTESTFLAGS) GDB_PERFTEST_MODE=compile GDB_PERFTEST_SUBMODE=build-pieces $(TIMESTAMP)
> 
> # Utility rule to build tests that support it in parallel.
> # The build is broken into 3 steps distinguished by GDB_PERFTEST_SUBMODE:
> @@ -312,18 +316,18 @@ build-perf: $(abs_builddir)/site.exp
> 	rm -rf gdb.perf/workers
> 	mkdir -p gdb.perf/workers
> 	@: Step 1: Generate the build .worker files.
> -	$(DO_RUNTEST) --directory=gdb.perf --outdir gdb.perf/workers GDB_PARALLEL=gdb.perf $(RUNTESTFLAGS) GDB_PERFTEST_MODE=compile GDB_PERFTEST_SUBMODE=gen-workers
> +	$(DO_RUNTEST) --directory=gdb.perf --outdir gdb.perf/workers GDB_PARALLEL=gdb.perf $(RUNTESTFLAGS) GDB_PERFTEST_MODE=compile GDB_PERFTEST_SUBMODE=gen-workers $(TIMESTAMP)
> 	@: Step 2: Compile the pieces.  Here is the build parallelism.
> 	$(MAKE) $$(cd gdb.perf && echo workers/*/*.worker)
> 	@: Step 3: Do the final link.
> -	$(DO_RUNTEST) --directory=gdb.perf --outdir gdb.perf GDB_PARALLEL=gdb.perf $(RUNTESTFLAGS) GDB_PERFTEST_MODE=compile GDB_PERFTEST_SUBMODE=final
> +	$(DO_RUNTEST) --directory=gdb.perf --outdir gdb.perf GDB_PARALLEL=gdb.perf $(RUNTESTFLAGS) GDB_PERFTEST_MODE=compile GDB_PERFTEST_SUBMODE=final $(TIMESTAMP)
> 
> # The default is to both compile and run the tests.
> GDB_PERFTEST_MODE = both
> 
> check-perf: all $(abs_builddir)/site.exp
> 	@if test ! -d gdb.perf; then mkdir gdb.perf; fi
> -	$(DO_RUNTEST) --directory=gdb.perf --outdir gdb.perf GDB_PERFTEST_MODE=$(GDB_PERFTEST_MODE) $(RUNTESTFLAGS)
> +	$(DO_RUNTEST) --directory=gdb.perf --outdir gdb.perf GDB_PERFTEST_MODE=$(GDB_PERFTEST_MODE) $(RUNTESTFLAGS) $(TIMESTAMP)
> 
> force:;
> 
> diff --git a/gdb/testsuite/README b/gdb/testsuite/README
> index 55abfb3254..723d8ba5eb 100644
> --- a/gdb/testsuite/README
> +++ b/gdb/testsuite/README
> @@ -273,6 +273,26 @@ can do:
> Note that only a hostname/address can be provided, without a port
> number.
> 
> +TS
> +
> +This variable turns on the timestamp printing for each line of "make
> +check".  Note that the timestamp will be printed on stdout output
> +only.  In other words, there will be no timestamp output on either
> +gdb.sum and gdb.log files.  If you would like to enable timestamp
> +printing, you can do:
> +
> +	make check TS=1
> +
> +TS_FORMAT
> +
> +You can provide a custom format for timestamp printing with this
> +variable.  The format must be a string compatible with "strftime".
> +This variable is only useful when the TS variable is also provided.
> +If you would like to change the output format of the timestamp, you
> +can do:
> +
> +	make check TS=1 TS_FORMAT='[%b %H:%S]'
> +
> Race detection
> **************
> 
> diff --git a/gdb/testsuite/print-ts.py b/gdb/testsuite/print-ts.py
> new file mode 100755
> index 0000000000..58127f5716
> --- /dev/null
> +++ b/gdb/testsuite/print-ts.py
> @@ -0,0 +1,45 @@
> +#!/usr/bin/env python3

Is it correct to force to python3? Everything else in gdb uses “python”.

> +
> +# Copyright (C) 2018 Free Software Foundation, Inc.
> +#
> +# This file is part of GDB.
> +#
> +# This program is free software; you can redistribute it and/or modify
> +# it under the terms of the GNU General Public License as published by
> +# the Free Software Foundation; either version 3 of the License, or
> +# (at your option) any later version.
> +#
> +# This program is distributed in the hope that it will be useful,
> +# but WITHOUT ANY WARRANTY; without even the implied warranty of
> +# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
> +# GNU General Public License for more details.
> +#
> +# You should have received a copy of the GNU General Public License
> +# along with this program.  If not, see <http://www.gnu.org/licenses/>.
> +
> +# This is a simple program that can be used to print timestamps on
> +# standard output.  The inspiration for it was ts(1)
> +# (<https://joeyh.name/code/moreutils/>).  We have our own version
> +# because unfortunately ts(1) is or may not be available on all
> +# systems that GDB supports.
> +#
> +# The usage is simple:
> +#
> +#   #> some_command | print-ts.py [FORMAT]
> +#
> +# FORMAT must be a string compatible with "strftime".  If nothing is
> +# provided, we choose a reasonable format.
> +
> +import fileinput
> +import datetime
> +import sys
> +
> +if len (sys.argv) > 1:
> +    fmt = sys.argv[1]
> +else:
> +    fmt = '[%b %d %H:%M:%S]'
> +
> +for line in fileinput.input ('-'):
> +    print ("{} {}".format (datetime.datetime.now ().strftime (fmt),
> +                           line),
> +           end = '', flush = True)
> -- 
> 2.17.2
>