Implement timestamp'ed output on "make check"

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.

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] [1234] Running binutils-gdb/gdb/testsuite/gdb.base/call-strs.exp ...
  [Nov 22 17:07:19] [1234] Running binutils-gdb/gdb/testsuite/gdb.base/step-over-no-symbols.exp ...
  [Nov 22 17:07:20] [1234] Running binutils-gdb/gdb/testsuite/gdb.base/all-architectures-6.exp ...
  [Nov 22 17:07:20] [1234] Running binutils-gdb/gdb/testsuite/gdb.base/hashline3.exp ...
  [Nov 22 17:07:20] [1234] Running binutils-gdb/gdb/testsuite/gdb.base/max-value-size.exp ...
  [Nov 22 17:07:20] [1234] Running binutils-gdb/gdb/testsuite/gdb.base/quit-live.exp ...
  [Nov 22 17:07:46] [1234] Running binutils-gdb/gdb/testsuite/gdb.base/paginate-bg-execution.exp ...
  [Nov 22 17:07:56] [1234] Running binutils-gdb/gdb/testsuite/gdb.base/gcore-buffer-overflow.exp ...
  [Nov 22 17:07:56] [1234] Running binutils-gdb/gdb/testsuite/gdb.base/gcore-relro.exp ...
  [Nov 22 17:07:56] [1234] Running binutils-gdb/gdb/testsuite/gdb.base/watchpoint-delete.exp ...
  [Nov 22 17:07:56] [1234] Running binutils-gdb/gdb/testsuite/gdb.base/breakpoint-in-ro-region.exp ...
  [Nov 22 17:07:56] [1234] Running binutils-gdb/gdb/testsuite/gdb.base/vla-sideeffect.exp ...
  [Nov 22 17:07:57] [1234] Running binutils-gdb/gdb/testsuite/gdb.base/unload.exp ...
  ...

(What, gdb.base/quit-live.exp is taking 26 seconds to complete?!)

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-25  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.

1 files changed, 12 insertions, 8 deletions

diff --git a/gdb/testsuite/Makefile.in b/gdb/testsuite/Makefile.in
index ece7e252c51..b526f579bec 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:;