From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 59310 invoked by alias); 23 Nov 2018 14:48:49 -0000 Mailing-List: contact gdb-patches-help@sourceware.org; run by ezmlm Precedence: bulk List-Id: List-Subscribe: List-Archive: List-Post: List-Help: , Sender: gdb-patches-owner@sourceware.org Received: (qmail 59109 invoked by uid 89); 23 Nov 2018 14:48:26 -0000 Authentication-Results: sourceware.org; auth=none X-Spam-SWARE-Status: No, score=-25.9 required=5.0 tests=BAYES_00,GIT_PATCH_0,GIT_PATCH_1,GIT_PATCH_2,GIT_PATCH_3,KAM_LAZY_DOMAIN_SECURITY,KAM_SHORT,SPF_HELO_PASS autolearn=ham version=3.3.2 spammy= X-HELO: mx1.redhat.com Received: from mx1.redhat.com (HELO mx1.redhat.com) (209.132.183.28) by sourceware.org (qpsmtpd/0.93/v0.84-503-g423c35a) with ESMTP; Fri, 23 Nov 2018 14:48:23 +0000 Received: from smtp.corp.redhat.com (int-mx07.intmail.prod.int.phx2.redhat.com [10.5.11.22]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mx1.redhat.com (Postfix) with ESMTPS id 85B6885546; Fri, 23 Nov 2018 14:48:15 +0000 (UTC) Received: from localhost (unused-10-15-17-196.yyz.redhat.com [10.15.17.196]) by smtp.corp.redhat.com (Postfix) with ESMTP id 4B1A21001F54; Fri, 23 Nov 2018 14:48:15 +0000 (UTC) From: Sergio Durigan Junior To: Alan Hayward Cc: GDB Patches , nd Subject: Re: [PATCH] Implement timestamp'ed output on "make check" References: <20181122221240.15354-1-sergiodj@redhat.com> <4606227D-972D-4314-B7A1-E518BA67458B@arm.com> Date: Fri, 23 Nov 2018 14:48:00 -0000 In-Reply-To: <4606227D-972D-4314-B7A1-E518BA67458B@arm.com> (Alan Hayward's message of "Fri, 23 Nov 2018 14:42:46 +0000") Message-ID: <87in0n6ea9.fsf@redhat.com> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/26.1 (gnu/linux) MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-IsSubscribed: yes X-SW-Source: 2018-11/txt/msg00386.txt.bz2 On Friday, November 23 2018, Alan Hayward wrote: >> On 22 Nov 2018, at 22:12, Sergio Durigan Junior wr= ote: >>=20 >> 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). >>=20 >> 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! >>=20 >> 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. >>=20 >> 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"). >>=20 >> Here's an example of how the output looks like: >>=20 >> ... >> [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-archi= tectures-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-buf= fer-overflow.exp ... >> [Nov 22 17:07:56] Running binutils-gdb/gdb/testsuite/gdb.base/gcore-rel= ro.exp ... >> [Nov 22 17:07:56] Running binutils-gdb/gdb/testsuite/gdb.base/watchpoin= t-delete.exp ... >> [Nov 22 17:07:56] Running binutils-gdb/gdb/testsuite/gdb.base/breakpoin= t-in-ro-region.exp ... >> [Nov 22 17:07:56] Running binutils-gdb/gdb/testsuite/gdb.base/vla-sidee= ffect.exp ... >> [Nov 22 17:07:57] Running binutils-gdb/gdb/testsuite/gdb.base/unload.ex= p ... >> ... >>=20 >> (What, gdb.base/quit-live.exp is taking 26 seconds to complete?!) >>=20 >> I've also tested this with FORCE_PARALLEL=3D1 -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=3D1 -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" (t= imeout) > [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] =3D=3D=3D gdb Summary =3D=3D=3D > [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] =3D=3D=3D gdb Summary =3D=3D=3D > [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 (timeo= ut) > [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] =3D=3D=3D gdb Summary =3D=3D=3D > [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] =3D=3D=3D gdb Summary =3D=3D=3D > [Nov 23 14:24:13] [33745] > > Look how spaced apart the 32485 entries are. I think it needs a pid in th= e output. Good point. I guess my -j8 test wasn't enough to trigger this problem. I'll adjust the patch to include the PID. >>=20 >> 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. >>=20 >> gdb/testsuite/ChangeLog: >> 2018-11-22 Sergio Durigan Junior >>=20 >> * 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 >>=20 >> 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=3D"1" check >>=20 >> +# Check whether we need to print the timestamp for each line of >> +# status. >> +TIMESTAMP =3D $(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 =3D \ >> @@ -192,7 +196,7 @@ check-gdb.%: >> $(MAKE) check TESTS=3D"gdb.$*/*.exp" >>=20 >> check-single: >> - $(DO_RUNTEST) $(RUNTESTFLAGS) $(expanded_tests_or_none) >> + $(DO_RUNTEST) $(RUNTESTFLAGS) $(expanded_tests_or_none) $(TIMESTAMP) >>=20 >> 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=3Dracy_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) >>=20 >> check/%.exp: >> -mkdir -p outputs/$* >> - @$(DO_RUNTEST) GDB_PARALLEL=3Dyes --outdir=3Doutputs/$* $*.exp $(RUNTE= STFLAGS) >> + @$(DO_RUNTEST) GDB_PARALLEL=3Dyes --outdir=3Doutputs/$* $*.exp $(RUNTE= STFLAGS) $(TIMESTAMP) >>=20 >> do-check-parallel-racy: $(TEST_TARGETS) >> @: >> @@ -282,7 +286,7 @@ check-racy/%.exp: >> -mkdir -p racy_outputs/$(RACY_OUTPUT_N)/$* >> $(DO_RUNTEST) GDB_PARALLEL=3Dyes \ >> --outdir=3Dracy_outputs/$(RACY_OUTPUT_N)/$* $*.exp \ >> - $(RUNTESTFLAGS) >> + $(RUNTESTFLAGS) $(TIMESTAMP) >>=20 >> 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=3Dgdb.perf/outputs/$* lib/build-piece.exp WORKE= R=3D$* GDB_PARALLEL=3Dgdb.perf $(RUNTESTFLAGS) GDB_PERFTEST_MODE=3Dcompile = GDB_PERFTEST_SUBMODE=3Dbuild-pieces >> + $(DO_RUNTEST) --outdir=3Dgdb.perf/outputs/$* lib/build-piece.exp WORKE= R=3D$* GDB_PARALLEL=3Dgdb.perf $(RUNTESTFLAGS) GDB_PERFTEST_MODE=3Dcompile = GDB_PERFTEST_SUBMODE=3Dbuild-pieces $(TIMESTAMP) >>=20 >> # 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=3Dgdb.perf --outdir gdb.perf/workers GDB_PAR= ALLEL=3Dgdb.perf $(RUNTESTFLAGS) GDB_PERFTEST_MODE=3Dcompile GDB_PERFTEST_S= UBMODE=3Dgen-workers >> + $(DO_RUNTEST) --directory=3Dgdb.perf --outdir gdb.perf/workers GDB_PAR= ALLEL=3Dgdb.perf $(RUNTESTFLAGS) GDB_PERFTEST_MODE=3Dcompile GDB_PERFTEST_S= UBMODE=3Dgen-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=3Dgdb.perf --outdir gdb.perf GDB_PARALLEL=3D= gdb.perf $(RUNTESTFLAGS) GDB_PERFTEST_MODE=3Dcompile GDB_PERFTEST_SUBMODE= =3Dfinal >> + $(DO_RUNTEST) --directory=3Dgdb.perf --outdir gdb.perf GDB_PARALLEL=3D= gdb.perf $(RUNTESTFLAGS) GDB_PERFTEST_MODE=3Dcompile GDB_PERFTEST_SUBMODE= =3Dfinal $(TIMESTAMP) >>=20 >> # The default is to both compile and run the tests. >> GDB_PERFTEST_MODE =3D both >>=20 >> check-perf: all $(abs_builddir)/site.exp >> @if test ! -d gdb.perf; then mkdir gdb.perf; fi >> - $(DO_RUNTEST) --directory=3Dgdb.perf --outdir gdb.perf GDB_PERFTEST_MO= DE=3D$(GDB_PERFTEST_MODE) $(RUNTESTFLAGS) >> + $(DO_RUNTEST) --directory=3Dgdb.perf --outdir gdb.perf GDB_PERFTEST_MO= DE=3D$(GDB_PERFTEST_MODE) $(RUNTESTFLAGS) $(TIMESTAMP) >>=20 >> force:; >>=20 >> 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. >>=20 >> +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=3D1 >> + >> +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=3D1 TS_FORMAT=3D'[%b %H:%S]' >> + >> Race detection >> ************** >>=20 >> 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 =E2=80=9Cp= ython=E2=80=9D. 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. >> + >> +# 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 . >> + >> +# This is a simple program that can be used to print timestamps on >> +# standard output. The inspiration for it was ts(1) >> +# (). 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 =3D sys.argv[1] >> +else: >> + fmt =3D '[%b %d %H:%M:%S]' >> + >> +for line in fileinput.input ('-'): >> + print ("{} {}".format (datetime.datetime.now ().strftime (fmt), >> + line), >> + end =3D '', flush =3D True) >> --=20 >> 2.17.2 >>=20 --=20 Sergio GPG key ID: 237A 54B1 0287 28BF 00EF 31F4 D0EB 7628 65FC 5E36 Please send encrypted e-mail if possible http://sergiodj.net/