[v2] Implement timestamp'ed output on "make check"
Commit Message
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 <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 | 48 +++++++++++++++++++++++++++++++++++++++
3 files changed, 80 insertions(+), 8 deletions(-)
create mode 100755 gdb/testsuite/print-ts.py
Comments
On 2018-11-23 10:02 a.m., Sergio Durigan Junior wrote:
> 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.
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%20GDB-Python-Coding-Standards#preview
On Friday, November 23 2018, Simon Marchi wrote:
> On 2018-11-23 10:02 a.m., Sergio Durigan Junior wrote:
>> 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.
>
> I think this is a good idea. I tried it and it works very well.
Thanks for the review, Simon.
> 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,
On 2018-11-25 11:24, Sergio Durigan Junior wrote:
>> 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
On Sunday, November 25 2018, Simon Marchi wrote:
> On 2018-11-25 11:24, Sergio Durigan Junior wrote:
>>> 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.
On 2018-11-25 18:23, Sergio Durigan Junior wrote:
> 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.
> 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
:)
> Anyway, I've pushed the commit now:
>
> f63c03b470036353c8c6c657e15f5ebd62ab67dd
>
> Thanks again for the review.
Thanks,
Simon
On Sunday, November 25 2018, Simon Marchi wrote:
> On 2018-11-25 18:23, Sergio Durigan Junior wrote:
>> 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.
>> 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,
On 2018-11-26 11:29, Sergio Durigan Junior wrote:
>>> 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.
> 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.
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.
> 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
On Sunday, November 25 2018, I wrote:
> Anyway, I've pushed the commit now:
>
> 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,
@@ -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:;
@@ -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
**************
new file mode 100755
@@ -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 ()