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>
This commit is contained in:
Stephen Warren 2017-10-27 11:04:08 -06:00 committed by Tom Rini
parent 1543bf794f
commit 9679d339ad
3 changed files with 44 additions and 0 deletions

View File

@ -62,6 +62,10 @@ pre {
color: #8080ff
}
.timestamp {
color: #8080ff
}
.status-pass {
color: #00ff00
}

View File

@ -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.

View File

@ -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):