From: Stephen Warren swarren@nvidia.com
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 --- 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 f135b10a24c9..9b7c44fe4de0 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 5bc1bc49d4de..8ca515319ce9 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 eedf73f85831..4bccd72050b7 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):