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

[Sergio Durigan Junior <sergiodj@redhat.com>]

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,

-- 
Sergio
GPG key ID: 237A 54B1 0287 28BF 00EF  31F4 D0EB 7628 65FC 5E36
Please send encrypted e-mail if possible
http://sergiodj.net/