[PATCH] Implement timestamp'ed output on "make check"
Sergio Durigan Junior
sergiodj@redhat.com
Fri Nov 23 14:48:00 GMT 2018
On Friday, November 23 2018, Alan Hayward wrote:
>> 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.
Thanks!
>>
>> 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.
Good point. I guess my -j8 test wasn't enough to trigger this
problem. I'll adjust the patch to include the PID.
>>
>> 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”.
That's something I wondered myself. I wrote the script with Python 3 in
mind, but I guess I can make it compatible with Python 2 as well since
it's pretty simple.
I'll send a v2 soon. Thanks for the review.
>> +
>> +# 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
>>
--
Sergio
GPG key ID: 237A 54B1 0287 28BF 00EF 31F4 D0EB 7628 65FC 5E36
Please send encrypted e-mail if possible
http://sergiodj.net/
More information about the Gdb-patches
mailing list