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

Simon Marchi
2018-11-23T18:23:33Z

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