From patchwork Wed Oct 30 20:22:20 2013 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Johannes Berg X-Patchwork-Id: 287344 Return-Path: X-Original-To: patchwork-incoming@ozlabs.org Delivered-To: patchwork-incoming@ozlabs.org Received: from maxx.maxx.shmoo.com (maxx.shmoo.com [205.134.188.171]) (using TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits)) (Client CN "maxx.shmoo.com", Issuer "CA Cert Signing Authority" (not verified)) by ozlabs.org (Postfix) with ESMTPS id A89C62C0383 for ; Thu, 31 Oct 2013 07:22:41 +1100 (EST) Received: from localhost (localhost [127.0.0.1]) by maxx.maxx.shmoo.com (Postfix) with ESMTP id A993F9C0FB; Wed, 30 Oct 2013 16:22:37 -0400 (EDT) X-Virus-Scanned: amavisd-new at maxx.shmoo.com Received: from maxx.maxx.shmoo.com ([127.0.0.1]) by localhost (maxx.shmoo.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id EbrXu5ibUuvo; Wed, 30 Oct 2013 16:22:37 -0400 (EDT) Received: from maxx.shmoo.com (localhost [127.0.0.1]) by maxx.maxx.shmoo.com (Postfix) with ESMTP id 2EC3C9C10E; Wed, 30 Oct 2013 16:22:33 -0400 (EDT) X-Original-To: mailman-post+hostap@maxx.shmoo.com Delivered-To: mailman-post+hostap@maxx.shmoo.com Received: from localhost (localhost [127.0.0.1]) by maxx.maxx.shmoo.com (Postfix) with ESMTP id 53DC89C10E for ; Wed, 30 Oct 2013 16:22:32 -0400 (EDT) X-Virus-Scanned: amavisd-new at maxx.shmoo.com Received: from maxx.maxx.shmoo.com ([127.0.0.1]) by localhost (maxx.shmoo.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id ia5IaZZzXxZi for ; Wed, 30 Oct 2013 16:22:28 -0400 (EDT) Received: from sipsolutions.net (s3.sipsolutions.net [144.76.43.152]) (using TLSv1 with cipher DHE-RSA-AES128-SHA (128/128 bits)) (Client did not present a certificate) by maxx.maxx.shmoo.com (Postfix) with ESMTPS id E096F9C0FB for ; Wed, 30 Oct 2013 16:22:27 -0400 (EDT) Received: by sipsolutions.net with esmtpsa (TLS1.2:DHE_RSA_AES_256_CBC_SHA256:256) (Exim 4.80) (envelope-from ) id 1VbcHZ-00087l-M9; Wed, 30 Oct 2013 21:22:26 +0100 From: Johannes Berg To: hostap@lists.shmoo.com Subject: [PATCH] hwsim tests: allow run-tests.py to start tracing Date: Wed, 30 Oct 2013 21:22:20 +0100 Message-Id: <1383164540-20700-1-git-send-email-johannes@sipsolutions.net> X-Mailer: git-send-email 1.8.4.rc3 Cc: Johannes Berg X-BeenThere: hostap@lists.shmoo.com X-Mailman-Version: 2.1.11 Precedence: list List-Id: HostAP Project List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , MIME-Version: 1.0 Sender: hostap-bounces@lists.shmoo.com Errors-To: hostap-bounces@lists.shmoo.com From: Johannes Berg In order to get tracing per test, allow run-tests.py to start and stop tracing per test case. This is implemented using a python 'with' context so it starts/stops automatically at the right spots. Instead of starting global tracing, also use it from run-all.sh and put the trace files into the log dir. Note that this only works right if you use a separate log dir for all test runs as the trace files aren't timestamped. Signed-off-by: Johannes Berg --- tests/hwsim/run-all.sh | 11 +--- tests/hwsim/run-tests.py | 145 ++++++++++++++++++++++++++++------------------- 2 files changed, 89 insertions(+), 67 deletions(-) diff --git a/tests/hwsim/run-all.sh b/tests/hwsim/run-all.sh index ecc70a1..bef49f9 100755 --- a/tests/hwsim/run-all.sh +++ b/tests/hwsim/run-all.sh @@ -44,9 +44,11 @@ fi if [ "x$1" = "xtrace" ] ; then TRACE=trace SUFFIX=$SUFFIX-trace + TRACE_ARGS="-T $LOGDIR" shift else unset TRACE + unset TRACE_ARGS fi if ! ./start.sh $CONCURRENT $VALGRIND $TRACE; then @@ -55,14 +57,7 @@ if ! ./start.sh $CONCURRENT $VALGRIND $TRACE; then fi DATE=`ls -1tr $LOGDIR | tail -1 | cut -f1 -d-` rm $LOGDIR/last-debug 2>/dev/null -RUNTESTS="./run-tests.py -l $LOGDIR/$DATE-run $DB -e $LOGDIR/$DATE-failed -r $LOGDIR/results.txt $CONCURRENT_TESTS $@" - -if [ "$TRACE" != "" ] ; then - sudo trace-cmd record -o $LOGDIR/$DATE-trace.dat -e mac80211 -e cfg80211 su $USER -c $RUNTESTS || errors=1 -else - $RUNTESTS || errors=1 -fi - +./run-tests.py $TRACE_ARGS -l $LOGDIR/$DATE-run $DB -e $LOGDIR/$DATE-failed -r $LOGDIR/results.txt $CONCURRENT_TESTS $@ || errors=1 cat $LOGDIR/$DATE-run >> $LOGDIR/last-debug ./stop-wifi.sh diff --git a/tests/hwsim/run-tests.py b/tests/hwsim/run-tests.py index 568e736..a540ec6 100755 --- a/tests/hwsim/run-tests.py +++ b/tests/hwsim/run-tests.py @@ -12,6 +12,7 @@ import sys import time from datetime import datetime import argparse +import subprocess import logging logger = logging.getLogger(__name__) @@ -47,6 +48,29 @@ def report(conn, build, commit, run, test, result, diff): print "sqlite: " + str(e) print "sql: %r" % (params, ) +class Tracer(object): + def __init__(self, tracedir, testname): + self._tracedir = tracedir + self._testname = testname + def __enter__(self): + if not self._tracedir: + return + output = os.path.join(self._tracedir, '%s.dat' % (self._testname, )) + self._trace_cmd = subprocess.Popen(['trace-cmd', 'record', '-o', output, '-e', 'mac80211', '-e', 'cfg80211', 'sh', '-c', 'echo STARTED ; read l'], + stdin=subprocess.PIPE, + stdout=subprocess.PIPE, + stderr=open('/dev/null', 'w'), + cwd=self._tracedir) + l = self._trace_cmd.stdout.read(7) + while not 'STARTED' in l: + l += self._trace_cmd.stdout.read(1) + print l + def __exit__(self, type, value, traceback): + if not self._tracedir: + return + self._trace_cmd.stdin.write('DONE\n') + self._trace_cmd.wait() + def main(): tests = [] test_modules = [] @@ -86,6 +110,8 @@ def main(): parser.add_argument('-b', metavar='', dest='build', help='build ID') parser.add_argument('-L', action='store_true', dest='update_tests_db', help='List tests (and update descriptions in DB)') + parser.add_argument('-T', metavar='', dest='tracedir', + help='tracing directory - will get a trace file per test') parser.add_argument('-f', dest='testmodules', metavar='', help='execute only tests from these test modules', type=str, choices=[[]] + test_modules, nargs='+') @@ -165,70 +191,71 @@ def main(): if args.testmodules: if not t.__module__ in args.testmodules: continue - reset_devs(dev, apdev) - logger.info("START " + t.__name__) - if log_to_file: - print "START " + t.__name__ - sys.stdout.flush() - if t.__doc__: - logger.info("Test: " + t.__doc__) - start = datetime.now() - for d in dev: - try: - d.request("NOTE TEST-START " + t.__name__) - except Exception, e: - logger.info("Failed to issue TEST-START before " + t.__name__ + " for " + d.ifname) - logger.info(e) - print "FAIL " + t.__name__ + " - could not start test" - if conn: - conn.close() - conn = None - sys.exit(1) - try: - if t.func_code.co_argcount > 1: - res = t(dev, apdev) - else: - res = t(dev) - end = datetime.now() - diff = end - start - if res == "skip": - skipped.append(t.__name__) - result = "SKIP" - else: - passed.append(t.__name__) - result = "PASS" - report(conn, args.build, args.commit, run, t.__name__, result, diff) - result = result + " " + t.__name__ + " " - result = result + str(diff.total_seconds()) + " " + str(end) - logger.info(result) - if log_to_file or print_res: - print result - sys.stdout.flush() - if results_file: - f = open(results_file, 'a') - f.write(result + "\n") - f.close() - except Exception, e: - end = datetime.now() - diff = end - start - logger.info(e) - failed.append(t.__name__) - report(conn, args.build, args.commit, run, t.__name__, "FAIL", diff) - result = "FAIL " + t.__name__ + " " + str(diff.total_seconds()) + " " + str(end) - logger.info(result) + with Tracer(args.tracedir, t.__name__): + reset_devs(dev, apdev) + logger.info("START " + t.__name__) if log_to_file: - print result + print "START " + t.__name__ sys.stdout.flush() - if results_file: - f = open(results_file, 'a') - f.write(result + "\n") - f.close() - for d in dev: + if t.__doc__: + logger.info("Test: " + t.__doc__) + start = datetime.now() + for d in dev: + try: + d.request("NOTE TEST-START " + t.__name__) + except Exception, e: + logger.info("Failed to issue TEST-START before " + t.__name__ + " for " + d.ifname) + logger.info(e) + print "FAIL " + t.__name__ + " - could not start test" + if conn: + conn.close() + conn = None + sys.exit(1) try: - d.request("NOTE TEST-STOP " + t.__name__) + if t.func_code.co_argcount > 1: + res = t(dev, apdev) + else: + res = t(dev) + end = datetime.now() + diff = end - start + if res == "skip": + skipped.append(t.__name__) + result = "SKIP" + else: + passed.append(t.__name__) + result = "PASS" + report(conn, args.build, args.commit, run, t.__name__, result, diff) + result = result + " " + t.__name__ + " " + result = result + str(diff.total_seconds()) + " " + str(end) + logger.info(result) + if log_to_file or print_res: + print result + sys.stdout.flush() + if results_file: + f = open(results_file, 'a') + f.write(result + "\n") + f.close() except Exception, e: - logger.info("Failed to issue TEST-STOP after " + t.__name__ + " for " + d.ifname) + end = datetime.now() + diff = end - start logger.info(e) + failed.append(t.__name__) + report(conn, args.build, args.commit, run, t.__name__, "FAIL", diff) + result = "FAIL " + t.__name__ + " " + str(diff.total_seconds()) + " " + str(end) + logger.info(result) + if log_to_file: + print result + sys.stdout.flush() + if results_file: + f = open(results_file, 'a') + f.write(result + "\n") + f.close() + for d in dev: + try: + d.request("NOTE TEST-STOP " + t.__name__) + except Exception, e: + logger.info("Failed to issue TEST-STOP after " + t.__name__ + " for " + d.ifname) + logger.info(e) if not args.tests: reset_devs(dev, apdev)