test/py: add timestamps to log

It can be useful to record how long tests take; this can help debug slow
running test systems or track changes in performance over time. Enhance
the test system to record timestamps while running test:
- Whenever a new log file section is started.
- After U-Boot is started and communication has been established.
- After each host or U-Boot command is executed.

Signed-off-by: Stephen Warren <swarren@nvidia.com>

3 files changed, 44 insertions, 0 deletions

diff --git a/test/py/multiplexed_log.css b/test/py/multiplexed_log.css
index f135b10a24..9b7c44fe4d 100644
--- a/test/py/multiplexed_log.css
+++ b/test/py/multiplexed_log.css
@@ -62,6 +62,10 @@ pre {
     color: #8080ff
 }
 
+.timestamp {
+    color: #8080ff
+}
+
 .status-pass {
     color: #00ff00
 }
diff --git a/test/py/multiplexed_log.py b/test/py/multiplexed_log.py
index 5bc1bc49d4..8ca515319c 100644
--- a/test/py/multiplexed_log.py
+++ b/test/py/multiplexed_log.py
@@ -7,6 +7,7 @@
 # each represented in a well-delineated/-structured fashion.
 
 import cgi
+import datetime
 import os.path
 import shutil
 import subprocess
@@ -164,6 +165,7 @@ class RunAndLog(object):
         self.logfile.write(self, output)
         if self.chained_file:
             self.chained_file.write(output)
+        self.logfile.timestamp()
 
         # Store the output so it can be accessed if we raise an exception.
         self.output = output
@@ -219,6 +221,9 @@ class Logfile(object):
         self.blocks = []
         self.cur_evt = 1
         self.anchor = 0
+        self.timestamp_start = self._get_time()
+        self.timestamp_prev = self.timestamp_start
+        self.timestamp_blocks = []
 
         shutil.copy(mod_dir + '/multiplexed_log.css', os.path.dirname(fn))
         self.f.write('''\
@@ -388,6 +393,7 @@ $(document).ready(function () {
 
         self._terminate_stream()
         self.blocks.append(marker)
+        self.timestamp_blocks.append(self._get_time())
         if not anchor:
             self.anchor += 1
             anchor = str(self.anchor)
@@ -396,6 +402,7 @@ $(document).ready(function () {
         self.f.write('<div class="section-header block-header">Section: ' +
                      blk_path + '</div>\n')
         self.f.write('<div class="section-content block-content">\n')
+        self.timestamp()
 
         return anchor
 
@@ -416,6 +423,11 @@ $(document).ready(function () {
             raise Exception('Block nesting mismatch: "%s" "%s"' %
                             (marker, '/'.join(self.blocks)))
         self._terminate_stream()
+        timestamp_now = self._get_time()
+        timestamp_section_start = self.timestamp_blocks.pop()
+        delta_section = timestamp_now - timestamp_section_start
+        self._note("timestamp",
+            "TIME: SINCE-SECTION: " + str(delta_section))
         blk_path = '/'.join(self.blocks)
         self.f.write('<div class="section-trailer block-trailer">' +
                      'End section: ' + blk_path + '</div>\n')
@@ -492,6 +504,31 @@ $(document).ready(function () {
 
         self._note("action", msg)
 
+    def _get_time(self):
+        return datetime.datetime.now()
+
+    def timestamp(self):
+        """Write a timestamp to the log file.
+
+        Args:
+            None
+
+        Returns:
+            Nothing.
+        """
+
+        timestamp_now = self._get_time()
+        delta_prev = timestamp_now - self.timestamp_prev
+        delta_start = timestamp_now - self.timestamp_start
+        self.timestamp_prev = timestamp_now
+
+        self._note("timestamp",
+            "TIME: NOW: " + timestamp_now.strftime("%Y/%m/%d %H:%M:%S.%f"))
+        self._note("timestamp",
+            "TIME: SINCE-PREV: " + str(delta_prev))
+        self._note("timestamp",
+            "TIME: SINCE-START: " + str(delta_start))
+
     def status_pass(self, msg, anchor=None):
         """Write a note to the log file describing test(s) which passed.
 
diff --git a/test/py/u_boot_console_base.py b/test/py/u_boot_console_base.py
index eedf73f858..4bccd72050 100644
--- a/test/py/u_boot_console_base.py
+++ b/test/py/u_boot_console_base.py
@@ -215,6 +215,8 @@ class ConsoleBase(object):
             self.log.error(str(ex))
             self.cleanup_spawn()
             raise
+        finally:
+            self.log.timestamp()
 
     def run_command_list(self, cmds):
         """Run a list of commands.
@@ -370,6 +372,7 @@ class ConsoleBase(object):
             self.cleanup_spawn()
             raise
         finally:
+            self.log.timestamp()
             self.log.end_section('Starting U-Boot')
 
     def cleanup_spawn(self):