From 9679d339ad2d4c495d734bad3a0fb7be6c4215eb Mon Sep 17 00:00:00 2001 From: Stephen Warren Date: Fri, 27 Oct 2017 11:04:08 -0600 Subject: [PATCH] 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 --- test/py/multiplexed_log.css | 4 ++++ test/py/multiplexed_log.py | 37 ++++++++++++++++++++++++++++++++++ test/py/u_boot_console_base.py | 3 +++ 3 files changed, 44 insertions(+) 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('
Section: ' + blk_path + '
\n') self.f.write('
\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('
' + 'End section: ' + blk_path + '
\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): -- 2.25.1