Discussion:
[PATCH] Implement timestamp'ed output on "make check"
Sergio Durigan Junior
2018-11-22 22:12:40 UTC
Permalink
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] 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).

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 <***@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
+
+# 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
Alan Hayward
2018-11-23 14:42:46 UTC
Permalink
Post by Sergio Durigan Junior
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.
Post by Sergio Durigan Junior
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").
...
[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.
Post by Sergio Durigan Junior
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.
* 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
$(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 = \
$(MAKE) check TESTS="gdb.$*/*.exp"
- $(DO_RUNTEST) $(RUNTESTFLAGS) $(expanded_tests_or_none)
+ $(DO_RUNTEST) $(RUNTESTFLAGS) $(expanded_tests_or_none) $(TIMESTAMP)
-rm -rf cache racy_outputs temp
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)
-mkdir -p outputs/$*
do-check-parallel-racy: $(TEST_TARGETS)
-mkdir -p racy_outputs/$(RACY_OUTPUT_N)/$*
$(DO_RUNTEST) GDB_PARALLEL=yes \
--outdir=racy_outputs/$(RACY_OUTPUT_N)/$* $*.exp \
- $(RUNTESTFLAGS)
+ $(RUNTESTFLAGS) $(TIMESTAMP)
@echo ""
# Utility rule invoked by step 2 of the build-perf rule.
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.
@@ -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
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
+
+ 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
+
+ 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”.
Post by Sergio Durigan Junior
+
+# 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.
+#
+#
+# #> 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
+
+ fmt = sys.argv[1]
+ fmt = '[%b %d %H:%M:%S]'
+
+ print ("{} {}".format (datetime.datetime.now ().strftime (fmt),
+ line),
+ end = '', flush = T
Sergio Durigan Junior
2018-11-23 14:48:14 UTC
Permalink
Post by Alan Hayward
Post by Sergio Durigan Junior
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!
Post by Alan Hayward
Post by Sergio Durigan Junior
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").
...
[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
[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.
Post by Alan Hayward
Post by Sergio Durigan Junior
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.
* 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
$(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 = \
$(MAKE) check TESTS="gdb.$*/*.exp"
- $(DO_RUNTEST) $(RUNTESTFLAGS) $(expanded_tests_or_none)
+ $(DO_RUNTEST) $(RUNTESTFLAGS) $(expanded_tests_or_none) $(TIMESTAMP)
-rm -rf cache racy_outputs temp
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)
-mkdir -p outputs/$*
do-check-parallel-racy: $(TEST_TARGETS)
-mkdir -p racy_outputs/$(RACY_OUTPUT_N)/$*
$(DO_RUNTEST) GDB_PARALLEL=yes \
--outdir=racy_outputs/$(RACY_OUTPUT_N)/$* $*.exp \
- $(RUNTESTFLAGS)
+ $(RUNTESTFLAGS) $(TIMESTAMP)
@echo ""
# Utility rule invoked by step 2 of the build-perf rule.
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.
@@ -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
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
+
+ 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
+
+ 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.
Post by Alan Hayward
Post by Sergio Durigan Junior
+
+# 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.
+#
+#
+# #> 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
+
+ fmt = sys.argv[1]
+ fmt = '[%b %d %H:%M:%S]'
+
+ 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/
Sergio Durigan Junior
2018-11-23 15:02:56 UTC
Permalink
Changes from v2:

- Make 'print-ts.py' compatible with Python 2.

- Print PID of script when outputting timestamp.


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-23 Sergio Durigan Junior <***@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 | 48 +++++++++++++++++++++++++++++++++++++++
3 files changed, 80 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..4763d78c0e
--- /dev/null
+++ b/gdb/testsuite/print-ts.py
@@ -0,0 +1,48 @@
+#!/usr/bin/env 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
+import os
+
+if len (sys.argv) > 1:
+ fmt = sys.argv[1]
+else:
+ fmt = '[%b %d %H:%M:%S]'
+
+mypid = os.getpid ()
+
+for line in fileinput.input ('-'):
+ sys.stdout.write ("{} [{}] {}".format (datetime.datetime.now ().strftime (fmt),
+ mypid, line))
+ sys.stdout.flush ()
--
2.17.2
Simon Marchi
2018-11-23 18:23:23 UTC
Permalink
Post by Sergio Durigan Junior
- Make 'print-ts.py' compatible with Python 2.
- Print PID of script when outputting timestamp.
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").
...
[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.
I think this is a good idea. I tried it and it works very well.

As for the coding style, according to the wiki [1], we should follow PEP8 (which
I think makes sense). Can you change your script to folow that?
"autopep8 -i print-ts.py" should do it.

The patch LGTM with that fixed.

[1] https://sourceware.org/gdb/wiki/Internals%20GD
Sergio Durigan Junior
2018-11-25 16:24:04 UTC
Permalink
Post by Simon Marchi
Post by Sergio Durigan Junior
- Make 'print-ts.py' compatible with Python 2.
- Print PID of script when outputting timestamp.
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").
...
[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.
I think this is a good idea. I tried it and it works very well.
Thanks for the review, Simon.
Post by Simon Marchi
As for the coding style, according to the wiki [1], we should follow PEP8 (which
I think makes sense). Can you change your script to folow that?
"autopep8 -i print-ts.py" should do it.
Hm, the command doesn't output anything to me, and $? = 0. Is there
anything in particular that you noticed?

Thanks,
--
Sergio
GPG key ID: 237A 54B1 0287 28BF 00EF 31F4 D0EB 7628 65FC 5E36
Please send encrypted e-mail if possible
http://sergiodj.net/
Simon Marchi
2018-11-25 19:56:32 UTC
Permalink
Post by Sergio Durigan Junior
Post by Simon Marchi
As for the coding style, according to the wiki [1], we should follow PEP8 (which
I think makes sense). Can you change your script to folow that?
"autopep8 -i print-ts.py" should do it.
Hm, the command doesn't output anything to me, and $? = 0. Is there
anything in particular that you noticed?
The command modifies the file in-place, so you should have unstaged
changes after running it. In particular, it should remove spaces before
parentheses.

Simon
Sergio Durigan Junior
2018-11-25 23:23:27 UTC
Permalink
Post by Simon Marchi
Post by Sergio Durigan Junior
Post by Simon Marchi
As for the coding style, according to the wiki [1], we should follow PEP8 (which
I think makes sense). Can you change your script to folow that?
"autopep8 -i print-ts.py" should do it.
Hm, the command doesn't output anything to me, and $? = 0. Is there
anything in particular that you noticed?
The command modifies the file in-place, so you should have unstaged
changes after running it. In particular, it should remove spaces
before parentheses.
Ah, OK. I'm not used to tools that don't ask me whether I'd like to
modify a file. And FWIW, I don't really like this part of PEP8 which
states that there should be no spaces before parentheses.

Anyway, I've pushed the commit now:

f63c03b470036353c8c6c657e15f5ebd62ab67dd

Thanks again for the review.
--
Sergio
GPG key ID: 237A 54B1 0287 28BF 00EF 31F4 D0EB 7628 65FC 5E36
Please send encrypted e-mail if possible
http://sergiodj.net/
Simon Marchi
2018-11-26 00:47:01 UTC
Permalink
Post by Sergio Durigan Junior
Ah, OK. I'm not used to tools that don't ask me whether I'd like to
modify a file.
The -i switch tells it to modify the file in-place, otherwise it outputs
on stdout.
Post by Sergio Durigan Junior
And FWIW, I don't really like this part of PEP8 which
states that there should be no spaces before parentheses.
If you hate it that much, feel free to propose a change to our standards
:)
Post by Sergio Durigan Junior
f63c03b470036353c8c6c657e15f5ebd62ab67dd
Thanks again for the review.
Thanks,

Simon
Sergio Durigan Junior
2018-11-26 16:29:04 UTC
Permalink
Post by Simon Marchi
Post by Sergio Durigan Junior
Ah, OK. I'm not used to tools that don't ask me whether I'd like to
modify a file.
The -i switch tells it to modify the file in-place, otherwise it
outputs on stdout.
I thought -i was for "information". My bad for not reading the
documentation.
Post by Simon Marchi
Post by Sergio Durigan Junior
And FWIW, I don't really like this part of PEP8 which
states that there should be no spaces before parentheses.
If you hate it that much, feel free to propose a change to our
standards :)
Sorry if it appeared that I was complaining about your email! Not my
intention at all, and I do appreciate your reviews.

As for proposing a change to the standards... that's a good idea! I've
played a little bit with "autopep8" here, and it seems to be a nice
little tool which offers the possibility of ignoring parts of the PEP8
spec when fixing the file. For example, for the specific case of
"whitespace before '('", if you do:

autopep8 --ignore E211 -i FILE

It will not fix the "issue", and will preserve the whitespaces there.
Neat.

Anyway, I just wanted to document that I found a way to disable this
specific extension. As much as I'd like us to change this specific
thing, I'll focus on other priorities right now.

Cheers,
--
Sergio
GPG key ID: 237A 54B1 0287 28BF 00EF 31F4 D0EB 7628 65FC 5E36
Please send encrypted e-mail if possible
http://sergiodj.net/
Simon Marchi
2018-11-26 17:22:40 UTC
Permalink
Post by Sergio Durigan Junior
Post by Simon Marchi
Post by Sergio Durigan Junior
And FWIW, I don't really like this part of PEP8 which
states that there should be no spaces before parentheses.
If you hate it that much, feel free to propose a change to our
standards :)
Sorry if it appeared that I was complaining about your email! Not my
intention at all, and I do appreciate your reviews.
No harm felt on this side, my response could be interpreted a bit
harshly too, sorry about that.
Post by Sergio Durigan Junior
As for proposing a change to the standards... that's a good idea!
I've
played a little bit with "autopep8" here, and it seems to be a nice
little tool which offers the possibility of ignoring parts of the PEP8
spec when fixing the file. For example, for the specific case of
autopep8 --ignore E211 -i FILE
It will not fix the "issue", and will preserve the whitespaces there.
Neat.
I think autopep8's goal is to enforce pep8 (hence the name), so you
might not be able to have it format the code in different ways (just
ignore the warnings, as you pointed out). But there might be other
Python formatting tools that are more configurable. If there's one that
works well, which we can instruct to add spaces before parentheses (to
match how we format C/C++ code), then I think it would be reasonable to
do that.

But otherwise, it just feels we are just swimming against the current,
since pep8 is recommended by the language implementation itself, and
most tools revolve around that.
Post by Sergio Durigan Junior
Anyway, I just wanted to document that I found a way to disable this
specific extension. As much as I'd like us to change this specific
thing, I'll focus on other priorities right now.
:)

Simon
Sergio Durigan Junior
2018-11-26 18:48:36 UTC
Permalink
Post by Sergio Durigan Junior
f63c03b470036353c8c6c657e15f5ebd62ab67dd
Thanks again for the review.
FWIW, I've just enabled the timestamp'ed output on the BuildBot. You
can see an example here:

https://gdb-build.sergiodj.net/builders/Fedora-x86_64-native-extended-gdbserver-m32/builds/11223/steps/test%20gdb/logs/stdio

Thanks,
--
Sergio
GPG key ID: 237A 54B1 0287 28BF 00EF 31F4 D0EB 7628 65FC 5E36
Please send encrypted e-mail if possible
http://sergiodj.net/
Pedro Franco de Carvalho
2018-12-05 19:38:51 UTC
Permalink
Post by Sergio Durigan Junior
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.
Hello Sergio,

I've looked into the ppc64le native-gdbserver/native-extended-gdbserver
buildbot workers, it seems that they started getting slower with this
patch:

f19c7ff839d7a32ebb48482ae7d318fb46ca823d
GDBSERVER: Listen on a unix domain (instead of TCP) socket if requested.

I believe this patch has been reverted, but the builders haven't reached
the reverted point yet. Would it make sense to make the workers resume
after the reverted patch? This would be at commit
80e24d09860dbeba7d435b4a4f0990f85dbc084e.

They did also get even slower after this patch:

fe1a5cad302b5535030cdf62895e79512713d738
[gdb/testsuite] Log wait status on process no longer exists error

But I think it only happens in combination with the patch above (see
https://sourceware.org/ml/gdb-patches/2018-12/msg00060.html for a more
detailed explanation).

Thanks!!

--
Pedro Franco de Carvalho
Sergio Durigan Junior
2018-12-05 19:48:38 UTC
Permalink
Post by Pedro Franco de Carvalho
Post by Sergio Durigan Junior
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.
Hello Sergio,
Hey Pedro,
Post by Pedro Franco de Carvalho
I've looked into the ppc64le native-gdbserver/native-extended-gdbserver
buildbot workers, it seems that they started getting slower with this
f19c7ff839d7a32ebb48482ae7d318fb46ca823d
GDBSERVER: Listen on a unix domain (instead of TCP) socket if requested.
From my recollection, ISTR that the gdbserver builders were *very* slow
even before this commit. I was even talking to Edjunior about disabling
the gdbserver builders, because they were just contributing to making
the queue larger for the native builder.
Post by Pedro Franco de Carvalho
I believe this patch has been reverted, but the builders haven't reached
the reverted point yet. Would it make sense to make the workers resume
after the reverted patch? This would be at commit
80e24d09860dbeba7d435b4a4f0990f85dbc084e.
fe1a5cad302b5535030cdf62895e79512713d738
[gdb/testsuite] Log wait status on process no longer exists error
But I think it only happens in combination with the patch above (see
https://sourceware.org/ml/gdb-patches/2018-12/msg00060.html for a more
detailed explanation).
Alright. I'll try to cancel the builds up until
80e24d09860dbeba7d435b4a4f0990f85dbc084e and see how things go.

Thanks for taking the time to investigate this!
--
Sergio
GPG key ID: 237A 54B1 0287 28BF 00EF 31F4 D0EB 7628 65FC 5E36
Please send encrypted e-mail if possible
http://sergiodj.net/
Pedro Franco de Carvalho
2018-12-05 20:07:20 UTC
Permalink
Post by Sergio Durigan Junior
From my recollection, ISTR that the gdbserver builders were *very* slow
even before this commit. I was even talking to Edjunior about disabling
the gdbserver builders, because they were just contributing to making
the queue larger for the native builder.
It seems they were taking about one hour before, at least on the LE
builders, although I think the BE ones were taking longer. Is one hour
more than expected for the gdbserver builders? If not, I'll see if I
can figure out what's taking long.
Post by Sergio Durigan Junior
Alright. I'll try to cancel the builds up until
80e24d09860dbeba7d435b4a4f0990f85dbc084e and see how things go.
Thanks for taking the time to investigate this!
Thank you!

--
Pedro Franco de Carvalho
Sergio Durigan Junior
2018-12-05 20:26:05 UTC
Permalink
Post by Pedro Franco de Carvalho
Post by Sergio Durigan Junior
From my recollection, ISTR that the gdbserver builders were *very* slow
even before this commit. I was even talking to Edjunior about disabling
the gdbserver builders, because they were just contributing to making
the queue larger for the native builder.
It seems they were taking about one hour before, at least on the LE
builders, although I think the BE ones were taking longer. Is one hour
more than expected for the gdbserver builders? If not, I'll see if I
can figure out what's taking long.
Hm, on the native builder (CentOS-ppc64le-m64), the builds were taking
about 30 minutes. However, on
CentOS-ppc64le-native-extended-gdbserver-m64 and
CentOS-ppc64le-native-gdbserver-m64, the builds were taking much
longer. For example:

https://gdb-build.sergiodj.net/builders/CentOS-ppc64le-native-gdbserver-m64/builds/1988
Elapsed 6 hrs, 30 mins, 12 secs

https://gdb-build.sergiodj.net/builders/CentOS-ppc64le-native-gdbserver-m64/builds/1997
Elapsed 20 hrs, 52 mins, 15 secs

Things get much worse with native-extended:

https://gdb-build.sergiodj.net/builders/CentOS-ppc64le-native-extended-gdbserver-m64/builds/1992
Elapsed 37 hrs, 4 mins, 29 secs

https://gdb-build.sergiodj.net/builders/CentOS-ppc64le-native-extended-gdbserver-m64/builds/1988
Elapsed 37 hrs, 6 mins, 19 secs

Unfortunately they haven't reached the commit which introduces the
timestamp feature, so we still don't know exactly where they're hanging.
Post by Pedro Franco de Carvalho
Post by Sergio Durigan Junior
Alright. I'll try to cancel the builds up until
80e24d09860dbeba7d435b4a4f0990f85dbc084e and see how things go.
Thanks for taking the time to investigate this!
Thank you!
No problem.

I've now cancelled the builds; let's see how things go.

Cheers,
--
Sergio
GPG key ID: 237A 54B1 0287 28BF 00EF 31F4 D0EB 7628 65FC 5E36
Please send encrypted e-mail if possible
http://sergiodj.net/
Pedro Alves
2018-12-06 15:29:55 UTC
Permalink
Post by Sergio Durigan Junior
Unfortunately they haven't reached the commit which introduces the
timestamp feature, so we still don't know exactly where they're hanging.
Actually we could know even without the timestamp feature -- all the
testsuite/*/gdb.log files have something like:

Test run by pedro on Tue Dec 4 18:15:17 2018

at the top, and ...

runtest completed at Tue Dec 4 18:15:18 2018

... at the bottom.

So a simple script could extract that info and present it
in a convenient way.

Thanks,
Pedro Alves
Pedro Alves
2018-12-06 15:53:48 UTC
Permalink
Post by Pedro Alves
Post by Sergio Durigan Junior
Unfortunately they haven't reached the commit which introduces the
timestamp feature, so we still don't know exactly where they're hanging.
Actually we could know even without the timestamp feature -- all the
Test run by pedro on Tue Dec 4 18:15:17 2018
at the top, and ...
runtest completed at Tue Dec 4 18:15:18 2018
... at the bottom.
So a simple script could extract that info and present it
in a convenient way.
Here's a quick bash POC.

Make sure to test in parallel mode (make check-parallel),
so that each testcase gets its own gdb.log file
and then run the script, like:

$ cd gdb
$ make -j8 check-parallel
$ extract-times testsuite/outputs/ | sort -n | tail -n 10
33 seconds for testsuite/outputs/gdb.base/whatis-ptype-typedefs/gdb.log
35 seconds for testsuite/outputs/gdb.base/quit-live/gdb.log
35 seconds for testsuite/outputs/gdb.base/structs/gdb.log
37 seconds for testsuite/outputs/gdb.base/gdb-sigterm/gdb.log
39 seconds for testsuite/outputs/gdb.threads/attach-many-short-lived-threads/gdb.log
43 seconds for testsuite/outputs/gdb.base/multi-forks/gdb.log
48 seconds for testsuite/outputs/gdb.linespec/cpls-ops/gdb.log
64 seconds for testsuite/outputs/gdb.linespec/cpcompletion/gdb.log
78 seconds for testsuite/outputs/gdb.base/break-interp/gdb.log
149 seconds for testsuite/outputs/gdb.base/sigstep/gdb.log

(that was run against an older test dir I had handy.)
Pedro Franco de Carvalho
2018-12-06 19:32:12 UTC
Permalink
Post by Pedro Alves
Here's a quick bash POC.
Thanks for the script! However, for the buildbots I don't have access
to the parallel outputs folder through the webpage (or I don't know
where to find them).

Still, the merged gdb.log file seems to already have the completion
times, e.g.:

testcase [...]gdb.trace/unavailable.exp completed in 28 seconds

--
Pedro Franco de Carvalho
Sergio Durigan Junior
2018-12-06 19:52:41 UTC
Permalink
Post by Pedro Franco de Carvalho
Post by Pedro Alves
Here's a quick bash POC.
Thanks for the script! However, for the buildbots I don't have access
to the parallel outputs folder through the webpage (or I don't know
where to find them).
Still, the merged gdb.log file seems to already have the completion
testcase [...]gdb.trace/unavailable.exp completed in 28 seconds
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/.

Thanks,
--
Sergio
GPG key ID: 237A 54B1 0287 28BF 00EF 31F4 D0EB 7628 65FC 5E36
Please send encrypted e-mail if possible
http://sergiodj.net/
Pedro Alves
2018-12-07 20:05:55 UTC
Permalink
Post by Sergio Durigan Junior
Post by Pedro Franco de Carvalho
Post by Pedro Alves
Here's a quick bash POC.
Thanks for the script! However, for the buildbots I don't have access
to the parallel outputs folder through the webpage (or I don't know
where to find them).
Still, the merged gdb.log file seems to already have the completion
testcase [...]gdb.trace/unavailable.exp completed in 28 seconds
Indeed!
Post by Sergio Durigan Junior
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.

Thanks,
Pedro Alves
Sergio Durigan Junior
2018-12-07 22:09:15 UTC
Permalink
Post by Pedro Alves
Post by Sergio Durigan Junior
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, but I also think it makes sense to have
the special "timestamp'd" mode, because sometimes (when a build takes
more than 120 hours, for example, which was happening until recently
with the ppc64le builders) it's useful to have the information on the
screen without having to wait, I think.

Cheers,
--
Sergio
GPG key ID: 237A 54B1 0287 28BF 00EF 31F4 D0EB 7628 65FC 5E36
Please send encrypted e-mail if possible
http://sergiodj.net/
Pedro Alves
2018-12-08 12:58:40 UTC
Permalink
Post by Sergio Durigan Junior
Post by Pedro Alves
Post by Sergio Durigan Junior
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

Thanks,
Pedro Alves

Pedro Franco de Carvalho
2018-12-06 19:41:08 UTC
Permalink
Post by Sergio Durigan Junior
I've now cancelled the builds; let's see how things go.
Thanks! The LE builder seem to be going faster now (a bit more than one
hour).

They still fail sometimes with a timeout for make. From the logs of the
ones that didn't fail it seems that gdb.threads/trace-condition.exp and
gdb.threads/tspeed.exp are the ones taking long, and could be causing
this, but I haven't looked into them yet.

--
Pedro Franco de Carvalho
Loading...