ext: Add timing indications to every TestCase

The log_call helper is now accepting a time parameter (dictionary). If
the param is not None, the function will fill the timing indications
(user and system time) for the TestCase.

There are some TestCases whose user time is not of our interest; for
example we don't really care about the cpu time of a stdout diff
(MatchStdout tests). In those cases the resulting cpu time in the
generated JUnit file (results.xml) will be 0.

JIRA: https://gem5.atlassian.net/browse/GEM5-548

Change-Id: I53c1b59f8ad93900aeac06197e39189c00a9053c
Signed-off-by: Giacomo Travaglini <giacomo.travaglini@arm.com>
Reviewed-on: https://gem5-review.googlesource.com/c/public/gem5/+/32653
Tested-by: kokoro <noreply+kokoro@google.com>
diff --git a/ext/testlib/helper.py b/ext/testlib/helper.py
index 01ca539..1cb13f0 100644
--- a/ext/testlib/helper.py
+++ b/ext/testlib/helper.py
@@ -132,7 +132,7 @@
 TimedWaitPID.install()
 
 #TODO Tear out duplicate logic from the sandbox IOManager
-def log_call(logger, command, *popenargs, **kwargs):
+def log_call(logger, command, time, *popenargs, **kwargs):
     '''
     Calls the given process and automatically logs the command and output.
 
@@ -186,6 +186,12 @@
     retval = p.wait()
     stdout_thread.join()
     stderr_thread.join()
+
+    if time is not None and TimedWaitPID.has_time_for_pid(p.pid):
+        resource_usage = TimedWaitPID.get_time_for_pid(p.pid)
+        time['user_time'] = resource_usage.user_time
+        time['system_time'] = resource_usage.system_time
+
     # Return the return exit code of the process.
     if retval != 0:
         raise subprocess.CalledProcessError(retval, cmdstr)
@@ -482,7 +488,8 @@
     (_, tfname) = tempfile.mkstemp(dir=os.path.dirname(out_file), text=True)
     with open(tfname, 'r+') as tempfile_:
         try:
-            log_call(logger, ['diff', out_file, ref_file], stdout=tempfile_)
+            log_call(logger, ['diff', out_file, ref_file],
+                time=None, stdout=tempfile_)
         except OSError:
             # Likely signals that diff does not exist on this system. fallback
             # to difflib
diff --git a/ext/testlib/result.py b/ext/testlib/result.py
index 2d2c506..5c60342 100644
--- a/ext/testlib/result.py
+++ b/ext/testlib/result.py
@@ -1,3 +1,15 @@
+# Copyright (c) 2020 ARM Limited
+# All rights reserved
+#
+# The license below extends only to copyright in the software and shall
+# not be construed as granting a license to any other intellectual
+# property including but not limited to intellectual property relating
+# to a hardware implementation of the functionality of the software
+# licensed hereunder.  You may use the software subject to the license
+# terms below provided that you ensure that this notice is replicated
+# unmodified and in its entirety in all distributions of the software,
+# modified or unmodified, in source code or in binary form.
+#
 # Copyright (c) 2017 Mark D. Hill and David A. Wood
 # All rights reserved.
 #
@@ -60,6 +72,10 @@
     def unsuccessful(self):
         return self._metadata.result.value != state.Result.Passed
 
+    @property
+    def time(self):
+        return self._metadata.time
+
 
 class InternalTestResult(_CommonMetadataMixin):
     def __init__(self, obj, suite, directory):
@@ -258,6 +274,7 @@
              # TODO JUnit expects class of test.. add as test metadata.
             XMLAttribute('classname', str(test_result.uid)),
             XMLAttribute('status', str(test_result.result)),
+            XMLAttribute('time', str(test_result.time["user_time"])),
         ]
 
         # TODO JUnit expects a message for the reason a test was
diff --git a/ext/testlib/runner.py b/ext/testlib/runner.py
index ee658c9..16ff952 100644
--- a/ext/testlib/runner.py
+++ b/ext/testlib/runner.py
@@ -79,6 +79,8 @@
         self.suite = suite
         self.log = log.test_log
         self.log.test = test
+        self.time = {
+            "user_time" : 0, "system_time" : 0}
 
     @helper.cacheresult
     def _fixtures(self):
@@ -152,6 +154,8 @@
         else:
             self.testable.result = Result(Result.Passed)
 
+        self.testable.time = test_params.time
+
 
 class SuiteRunner(RunnerPattern):
     def test(self):
diff --git a/ext/testlib/wrappers.py b/ext/testlib/wrappers.py
index e919702..b2b887b 100644
--- a/ext/testlib/wrappers.py
+++ b/ext/testlib/wrappers.py
@@ -1,4 +1,4 @@
-# Copyright (c) 2019 ARM Limited
+# Copyright (c) 2019-2020 ARM Limited
 # All rights reserved
 #
 # The license below extends only to copyright in the software and shall
@@ -124,6 +124,14 @@
     def runner(self):
         return self.obj.runner
 
+    @property
+    def time(self):
+        return self.metadata.time
+
+    @time.setter
+    def time(self, value):
+        self.metadata.time = value
+
     # TODO Change log to provide status_update, result_update for all types.
     def log_status(self, status):
         import testlib.log as log
diff --git a/tests/gem5/fixture.py b/tests/gem5/fixture.py
index bb911dd..e141d02 100644
--- a/tests/gem5/fixture.py
+++ b/tests/gem5/fixture.py
@@ -170,7 +170,7 @@
         command.extend(self.targets)
         if self.options:
             command.extend(self.options)
-        log_call(log.test_log, command, stderr=sys.stderr)
+        log_call(log.test_log, command, time=None, stderr=sys.stderr)
 
 class Gem5Fixture(SConsFixture):
     def __new__(cls, isa, variant, protocol=None):
@@ -208,7 +208,7 @@
         targets = set(self.required_by)
         command = ['make', '-C', self.directory]
         command.extend([target.target for target in targets])
-        log_call(log.test_log, command, stderr=sys.stderr)
+        log_call(log.test_log, command, time=None, stderr=sys.stderr)
 
 
 class MakeTarget(Fixture):
diff --git a/tests/gem5/suite.py b/tests/gem5/suite.py
index cba3d43..3b0f1f8 100644
--- a/tests/gem5/suite.py
+++ b/tests/gem5/suite.py
@@ -176,6 +176,7 @@
         command.append(config)
         # Config_args should set up the program args.
         command.extend(config_args)
-        log_call(params.log, command, stdout=sys.stdout, stderr=sys.stderr)
+        log_call(params.log, command, time=params.time,
+            stdout=sys.stdout, stderr=sys.stderr)
 
     return test_run_gem5