From patchwork Fri Nov 23 15:02:56 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Sergio Durigan Junior X-Patchwork-Id: 30270 Received: (qmail 25524 invoked by alias); 23 Nov 2018 15:03:09 -0000 Mailing-List: contact gdb-patches-help@sourceware.org; run by ezmlm Precedence: bulk List-Id: List-Unsubscribe: List-Subscribe: List-Archive: List-Post: List-Help: , Sender: gdb-patches-owner@sourceware.org Delivered-To: mailing list gdb-patches@sourceware.org Received: (qmail 25510 invoked by uid 89); 23 Nov 2018 15:03:07 -0000 Authentication-Results: sourceware.org; auth=none X-Spam-SWARE-Status: No, score=-26.9 required=5.0 tests=BAYES_00, GIT_PATCH_0, GIT_PATCH_1, GIT_PATCH_2, GIT_PATCH_3, 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 15:03:04 +0000 Received: from smtp.corp.redhat.com (int-mx01.intmail.prod.int.phx2.redhat.com [10.5.11.11]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mx1.redhat.com (Postfix) with ESMTPS id 841048830F; Fri, 23 Nov 2018 15:03:02 +0000 (UTC) Received: from psique.yyz.redhat.com (unused-10-15-17-196.yyz.redhat.com [10.15.17.196]) by smtp.corp.redhat.com (Postfix) with ESMTP id E1AC283EAC; Fri, 23 Nov 2018 15:02:58 +0000 (UTC) From: Sergio Durigan Junior To: GDB Patches Cc: Alan Hayward , nd , Sergio Durigan Junior Subject: [PATCH v2] Implement timestamp'ed output on "make check" Date: Fri, 23 Nov 2018 10:02:56 -0500 Message-Id: <20181123150256.22584-1-sergiodj@redhat.com> In-Reply-To: <20181122221240.15354-1-sergiodj@redhat.com> References: <20181122221240.15354-1-sergiodj@redhat.com> X-IsSubscribed: yes 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 * 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 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="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:; 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. +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 ************** diff --git a/gdb/testsuite/print-ts.py b/gdb/testsuite/print-ts.py new file mode 100755 index 0000000000..4763d78c0e --- /dev/null +++ b/gdb/testsuite/print-ts.py @@ -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 . + +# 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 +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 ()