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

[Simon Marchi]

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