debug: output some more useful info into the post-mortem data
[riscv-tests.git] / debug / testlib.py
index fae2132415d03514339f80ba71f645dfce7a1046..09baf1bec6bb522fb7d85631f2112c61dd1270de 100644 (file)
@@ -9,9 +9,13 @@ import sys
 import tempfile
 import time
 import traceback
+import pipes
 
 import pexpect
 
+print_log_names = False
+real_stdout = sys.stdout
+
 # Note that gdb comes with its own testsuite. I was unable to figure out how to
 # run that testsuite against the spike simulator.
 
@@ -52,10 +56,13 @@ def compile(args, xlen=32): # pylint: disable=redefined-builtin
         raise Exception("Compile failed!")
 
 class Spike(object):
-    def __init__(self, target, halted=False, timeout=None, with_jtag_gdb=True):
+    def __init__(self, target, halted=False, timeout=None, with_jtag_gdb=True,
+            isa=None, progbufsize=None):
         """Launch spike. Return tuple of its process and the port it's running
         on."""
         self.process = None
+        self.isa = isa
+        self.progbufsize = progbufsize
 
         if target.harts:
             harts = target.harts
@@ -70,6 +77,8 @@ class Spike(object):
         self.logfile = tempfile.NamedTemporaryFile(prefix="spike-",
                 suffix=".log")
         self.logname = self.logfile.name
+        if print_log_names:
+            real_stdout.write("Temporary spike log: %s\n" % self.logname)
         self.logfile.write("+ %s\n" % " ".join(cmd))
         self.logfile.flush()
         self.process = subprocess.Popen(cmd, stdin=subprocess.PIPE,
@@ -103,10 +112,17 @@ class Spike(object):
         assert len(set(t.xlen for t in harts)) == 1, \
                 "All spike harts must have the same XLEN"
 
-        if harts[0].xlen == 32:
-            cmd += ["--isa", "RV32G"]
+        if self.isa:
+            isa = self.isa
         else:
-            cmd += ["--isa", "RV64G"]
+            isa = "RV%dG" % harts[0].xlen
+
+        cmd += ["--isa", isa]
+        cmd += ["--debug-auth"]
+
+        if not self.progbufsize is None:
+            cmd += ["--progsize", str(self.progbufsize)]
+            cmd += ["--debug-sba", "32"]
 
         assert len(set(t.ram for t in harts)) == 1, \
                 "All spike harts must have the same RAM layout"
@@ -137,9 +153,10 @@ class Spike(object):
         return self.process.wait(*args, **kwargs)
 
 class VcsSim(object):
-    logname = "simv.log"
+    logfile = tempfile.NamedTemporaryFile(prefix='simv', suffix='.log')
+    logname = logfile.name
 
-    def __init__(self, sim_cmd=None, debug=False):
+    def __init__(self, sim_cmd=None, debug=False, timeout=300):
         if sim_cmd:
             cmd = shlex.split(sim_cmd)
         else:
@@ -148,14 +165,19 @@ class VcsSim(object):
         if debug:
             cmd[0] = cmd[0] + "-debug"
             cmd += ["+vcdplusfile=output/gdbserver.vpd"]
+
         logfile = open(self.logname, "w")
+        if print_log_names:
+            real_stdout.write("Temporary VCS log: %s\n" % self.logname)
         logfile.write("+ %s\n" % " ".join(cmd))
         logfile.flush()
+
         listenfile = open(self.logname, "r")
         listenfile.seek(0, 2)
         self.process = subprocess.Popen(cmd, stdin=subprocess.PIPE,
                 stdout=logfile, stderr=logfile)
         done = False
+        start = time.time()
         while not done:
             # Fail if VCS exits early
             exit_code = self.process.poll()
@@ -172,6 +194,10 @@ class VcsSim(object):
                 self.port = int(match.group(1))
                 os.environ['JTAG_VPI_PORT'] = str(self.port)
 
+            if (time.time() - start) > timeout:
+                raise Exception("Timed out waiting for VCS to listen for JTAG "
+                        "vpi")
+
     def __del__(self):
         try:
             self.process.kill()
@@ -182,7 +208,6 @@ class VcsSim(object):
 class Openocd(object):
     logfile = tempfile.NamedTemporaryFile(prefix='openocd', suffix='.log')
     logname = logfile.name
-    print "OpenOCD Temporary Log File: %s" % logname
 
     def __init__(self, server_cmd=None, config=None, debug=False, timeout=60):
         self.timeout = timeout
@@ -221,7 +246,13 @@ class Openocd(object):
             cmd.append("-d")
 
         logfile = open(Openocd.logname, "w")
-        logfile.write("+ %s\n" % " ".join(cmd))
+        if print_log_names:
+            real_stdout.write("Temporary OpenOCD log: %s\n" % Openocd.logname)
+        env_entries = ("REMOTE_BITBANG_HOST", "REMOTE_BITBANG_PORT")
+        env_entries = [key for key in env_entries if key in os.environ]
+        logfile.write("+ %s%s\n" % (
+            "".join("%s=%s " % (key, os.environ[key]) for key in env_entries),
+            " ".join(map(pipes.quote, cmd))))
         logfile.flush()
 
         self.gdb_ports = []
@@ -304,6 +335,12 @@ class CannotAccess(Exception):
         Exception.__init__(self)
         self.address = address
 
+class CouldNotFetch(Exception):
+    def __init__(self, regname, explanation):
+        Exception.__init__(self)
+        self.regname = regname
+        self.explanation = explanation
+
 Thread = collections.namedtuple('Thread', ('id', 'description', 'target_id',
     'name', 'frame'))
 
@@ -311,13 +348,20 @@ class Gdb(object):
     """A single gdb class which can interact with one or more gdb instances."""
 
     # pylint: disable=too-many-public-methods
+    # pylint: disable=too-many-instance-attributes
 
     def __init__(self, ports,
             cmd=os.path.expandvars("$RISCV/bin/riscv64-unknown-elf-gdb"),
-            binary=None):
+            timeout=60, binary=None):
         assert ports
 
+        self.ports = ports
+        self.cmd = cmd
+        self.timeout = timeout
+        self.binary = binary
+
         self.stack = []
+        self.harts = {}
 
         self.logfiles = []
         self.children = []
@@ -325,14 +369,16 @@ class Gdb(object):
             logfile = tempfile.NamedTemporaryFile(prefix="gdb@%d-" % port,
                     suffix=".log")
             self.logfiles.append(logfile)
+            if print_log_names:
+                real_stdout.write("Temporary gdb log: %s\n" % logfile.name)
             child = pexpect.spawn(cmd)
             child.logfile = logfile
             child.logfile.write("+ %s\n" % cmd)
             self.children.append(child)
         self.active_child = self.children[0]
 
-        self.harts = {}
-        for port, child in zip(ports, self.children):
+    def connect(self):
+        for port, child in zip(self.ports, self.children):
             self.select_child(child)
             self.wait()
             self.command("set confirm off")
@@ -340,9 +386,10 @@ class Gdb(object):
             self.command("set height 0")
             # Force consistency.
             self.command("set print entry-values no")
+            self.command("set remotetimeout %d" % self.timeout)
             self.command("target extended-remote localhost:%d" % port)
-            if binary:
-                self.command("file %s" % binary)
+            if self.binary:
+                self.command("file %s" % self.binary)
             threads = self.threads()
             for t in threads:
                 hartid = None
@@ -355,12 +402,18 @@ class Gdb(object):
                         hartid = max(self.harts) + 1
                     else:
                         hartid = 0
-                self.harts[hartid] = (child, t)
+                # solo: True iff this is the only thread on this child
+                self.harts[hartid] = {'child': child,
+                        'thread': t,
+                        'solo': len(threads) == 1}
 
     def __del__(self):
         for child in self.children:
             del child
 
+    def one_hart_per_gdb(self):
+        return all(h['solo'] for h in self.harts.itervalues())
+
     def lognames(self):
         return [logfile.name for logfile in self.logfiles]
 
@@ -368,10 +421,11 @@ class Gdb(object):
         self.active_child = child
 
     def select_hart(self, hart):
-        child, thread = self.harts[hart.id]
-        self.select_child(child)
-        output = self.command("thread %s" % thread.id)
-        assert "Unknown" not in output
+        h = self.harts[hart.id]
+        self.select_child(h['child'])
+        if not h['solo']:
+            output = self.command("thread %s" % h['thread'].id, ops=5)
+            assert "Unknown" not in output
 
     def push_state(self):
         self.stack.append({
@@ -386,8 +440,11 @@ class Gdb(object):
         """Wait for prompt."""
         self.active_child.expect(r"\(gdb\)")
 
-    def command(self, command, timeout=6000):
-        """timeout is in seconds"""
+    def command(self, command, ops=1):
+        """ops is the estimated number of operations gdb will have to perform
+        to perform this command. It is used to compute a timeout based on
+        self.timeout."""
+        timeout = ops * self.timeout
         self.active_child.sendline(command)
         self.active_child.expect("\n", timeout=timeout)
         self.active_child.expect(r"\(gdb\)", timeout=timeout)
@@ -400,7 +457,7 @@ class Gdb(object):
                 self.select_child(child)
                 self.command(command)
 
-    def c(self, wait=True, timeout=-1, async=False):
+    def c(self, wait=True, async=False):
         """
         Dumb c command.
         In RTOS mode, gdb will resume all harts.
@@ -411,13 +468,14 @@ class Gdb(object):
             async = "&"
         else:
             async = ""
+        ops = 10
         if wait:
-            output = self.command("c%s" % async, timeout=timeout)
+            output = self.command("c%s" % async, ops=ops)
             assert "Continuing" in output
             return output
         else:
             self.active_child.sendline("c%s" % async)
-            self.active_child.expect("Continuing")
+            self.active_child.expect("Continuing", timeout=ops * self.timeout)
 
     def c_all(self):
         """
@@ -472,6 +530,9 @@ class Gdb(object):
         m = re.search("Cannot access memory at address (0x[0-9a-f]+)", output)
         if m:
             raise CannotAccess(int(m.group(1), 0))
+        m = re.search(r"Could not fetch register \"(\w+)\"; (.*)$", output)
+        if m:
+            raise CouldNotFetch(m.group(1), m.group(2))
         rhs = output.split('=')[-1]
         return self.parse_string(rhs)
 
@@ -481,28 +542,30 @@ class Gdb(object):
         return value
 
     def stepi(self):
-        output = self.command("stepi", timeout=60)
+        output = self.command("stepi", ops=10)
         return output
 
     def load(self):
-        output = self.command("load", timeout=6000)
+        output = self.command("load", ops=1000)
         assert "failed" not in  output
         assert "Transfer rate" in output
+        output = self.command("compare-sections", ops=1000)
+        assert "MIS" not in output
 
     def b(self, location):
-        output = self.command("b %s" % location)
+        output = self.command("b %s" % location, ops=5)
         assert "not defined" not in output
         assert "Breakpoint" in output
         return output
 
     def hbreak(self, location):
-        output = self.command("hbreak %s" % location)
+        output = self.command("hbreak %s" % location, ops=5)
         assert "not defined" not in output
         assert "Hardware assisted breakpoint" in output
         return output
 
     def threads(self):
-        output = self.command("info threads")
+        output = self.command("info threads", ops=100)
         threads = []
         for line in output.splitlines():
             m = re.match(
@@ -533,8 +596,12 @@ class PrivateState(object):
         self.gdb.pop_state()
 
 def run_all_tests(module, target, parsed):
-    if not os.path.exists(parsed.logs):
+    try:
         os.makedirs(parsed.logs)
+    except OSError:
+        # There's a race where multiple instances of the test program might
+        # decide to create the logs directory at the same time.
+        pass
 
     overall_start = time.time()
 
@@ -581,14 +648,17 @@ def run_tests(parsed, target, todo):
         log_fd.write("Test: %s\n" % name)
         log_fd.write("Target: %s\n" % type(target).__name__)
         start = time.time()
+        global real_stdout  # pylint: disable=global-statement
         real_stdout = sys.stdout
         sys.stdout = log_fd
         try:
-            result = instance.run(real_stdout)
+            result = instance.run()
             log_fd.write("Result: %s\n" % result)
+            log_fd.write("Logfile: %s\n" % log_name)
         finally:
             sys.stdout = real_stdout
             log_fd.write("Time elapsed: %.2fs\n" % (time.time() - start))
+            log_fd.flush()
         print "[%s] %s in %.2fs" % (name, result, time.time() - start)
         if result not in good_results and parsed.print_failures:
             sys.stdout.write(open(log_name).read())
@@ -618,6 +688,9 @@ def add_test_run_options(parser):
             help="Exit as soon as any test fails.")
     parser.add_argument("--print-failures", action="store_true",
             help="When a test fails, print the log file to stdout.")
+    parser.add_argument("--print-log-names", "--pln", action="store_true",
+            help="Print names of temporary log files as soon as they are "
+            "created.")
     parser.add_argument("test", nargs='*',
             help="Run only tests that are named here.")
     parser.add_argument("--gdb",
@@ -694,7 +767,7 @@ class BaseTest(object):
     def postMortem(self):
         pass
 
-    def run(self, real_stdout):
+    def run(self):
         """
         If compile_args is set, compile a program and set self.binary.
 
@@ -713,8 +786,6 @@ class BaseTest(object):
 
         try:
             self.classSetup()
-            real_stdout.write("[%s] Temporary logs: %s\n" % (
-                type(self).__name__, ", ".join(self.logs)))
             self.setup()
             result = self.test()    # pylint: disable=no-member
         except TestNotApplicable:
@@ -757,16 +828,17 @@ class GdbTest(BaseTest):
         BaseTest.classSetup(self)
 
         if gdb_cmd:
-            self.gdb = Gdb(self.server.gdb_ports, gdb_cmd, binary=self.binary)
+            self.gdb = Gdb(self.server.gdb_ports, gdb_cmd,
+                    timeout=self.target.timeout_sec, binary=self.binary)
         else:
-            self.gdb = Gdb(self.server.gdb_ports, binary=self.binary)
+            self.gdb = Gdb(self.server.gdb_ports,
+                    timeout=self.target.timeout_sec, binary=self.binary)
 
         self.logs += self.gdb.lognames()
+        self.gdb.connect()
 
-        if self.target:
-            self.gdb.global_command("set arch riscv:rv%d" % self.hart.xlen)
-            self.gdb.global_command("set remotetimeout %d" %
-                    self.target.timeout_sec)
+        self.gdb.global_command("set remotetimeout %d" %
+            self.target.timeout_sec)
 
         for cmd in self.target.gdb_setup:
             self.gdb.command(cmd)
@@ -780,7 +852,10 @@ class GdbTest(BaseTest):
         if not self.gdb:
             return
         self.gdb.interrupt()
-        self.gdb.command("info registers all", timeout=10)
+        self.gdb.command("disassemble", ops=20)
+        self.gdb.command("info registers all", ops=100)
+        self.gdb.command("flush regs")
+        self.gdb.command("info threads", ops=100)
 
     def classTeardown(self):
         del self.gdb
@@ -795,6 +870,7 @@ class GdbSingleHartTest(GdbTest):
             if hart != self.hart:
                 self.gdb.select_hart(hart)
                 self.gdb.p("$pc=loop_forever")
+
         self.gdb.select_hart(self.hart)
 
 class ExamineTarget(GdbTest):
@@ -805,16 +881,23 @@ class ExamineTarget(GdbTest):
             hart.misa = self.gdb.p("$misa")
 
             txt = "RV"
-            if (hart.misa >> 30) == 1:
-                txt += "32"
-            elif (hart.misa >> 62) == 2:
-                txt += "64"
-            elif (hart.misa >> 126) == 3:
-                txt += "128"
+            misa_xlen = 0
+            if ((hart.misa & 0xFFFFFFFF) >> 30) == 1:
+                misa_xlen = 32
+            elif ((hart.misa & 0xFFFFFFFFFFFFFFFF) >> 62) == 2:
+                misa_xlen = 64
+            elif ((hart.misa & 0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF) >> 126) == 3:
+                misa_xlen = 128
             else:
                 raise TestFailed("Couldn't determine XLEN from $misa (0x%x)" %
                         self.hart.misa)
 
+            if misa_xlen != hart.xlen:
+                raise TestFailed("MISA reported XLEN of %d but we were "\
+                        "expecting XLEN of %d\n" % (misa_xlen, hart.xlen))
+
+            txt += ("%d" % misa_xlen)
+
             for i in range(26):
                 if hart.misa & (1<<i):
                     txt += chr(i + ord('A'))