Skip to content

Add per-step timing information #3716

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
smoors merged 6 commits into from
Jun 9, 2021
Merged

Add per-step timing information #3716

Show file tree
Hide file tree
Changes from 5 commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
e0eed8c
Add per-step timing information
Flamefire May 31, 2021
20cbc0c
Use correct singluar/plural forms in time2str
Flamefire May 31, 2021
0e4847c
Honor silent, log and dry-run options for step-timing
Flamefire Jun 1, 2021
a9e882e
Fix tests for plural of sec/secs
Flamefire Jun 1, 2021
30d29ba
Also print step timing when step failed
Flamefire Jun 1, 2021
7d53ee3
Use divmod instead of manual divide and subtract
Flamefire Jun 9, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
11 changes: 10 additions & 1 deletion easybuild/framework/easyblock.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3528,7 +3528,16 @@ def run_all_steps(self, run_test_cases):
else:
print_msg("%s..." % descr, log=self.log, silent=self.silent)
self.current_step = step_name
self.run_step(step_name, step_methods)
start_time = datetime.now()
try:
self.run_step(step_name, step_methods)
finally:
if not self.dry_run:
step_duration = datetime.now() - start_time
if step_duration.total_seconds() >= 1:
print_msg("... (took %s)", time2str(step_duration), log=self.log, silent=self.silent)
elif self.logdebug or build_option('trace'):
print_msg("... (took < 1 sec)", log=self.log, silent=self.silent)

except StopException:
pass
Expand Down
29 changes: 14 additions & 15 deletions easybuild/tools/utilities.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -300,22 +300,21 @@ def time2str(delta):
if not isinstance(delta, datetime.timedelta):
raise EasyBuildError("Incorrect value type provided to time2str, should be datetime.timedelta: %s", type(delta))

delta_secs = delta.days * 3600 * 24 + delta.seconds + delta.microseconds / 10**6

if delta_secs < 60:
res = '%d sec' % int(delta_secs)
elif delta_secs < 3600:
mins = int(delta_secs / 60)
secs = int(delta_secs - (mins * 60))
res = '%d min %d sec' % (mins, secs)
else:
hours = int(delta_secs / 3600)
mins = int((delta_secs - hours * 3600) / 60)
secs = int(delta_secs - (hours * 3600) - (mins * 60))
hours_str = 'hours' if hours > 1 else 'hour'
res = '%d %s %d min %d sec' % (hours, hours_str, mins, secs)
delta_secs = delta.total_seconds()

return res
hours = int(delta_secs / 3600)
delta_secs -= hours * 3600
mins = int(delta_secs / 60)
secs = int(delta_secs - mins * 60)

res = []
if hours:
res.append('%d %s' % (hours, 'hour' if hours == 1 else 'hours'))
if mins or hours:
res.append('%d %s' % (mins, 'min' if mins == 1 else 'mins'))
res.append('%d %s' % (secs, 'sec' if secs == 1 else 'secs'))

return ' '.join(res)


def natural_keys(key):
Expand Down
8 changes: 4 additions & 4 deletions test/framework/options.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1895,7 +1895,7 @@ def test_from_pr_x(self):
re.compile(r"^\*\*\* DRY RUN using 'EB_FFTW' easyblock", re.M),
re.compile(r"^== building and installing FFTW/3.3.8-gompi-2018b\.\.\.", re.M),
re.compile(r"^building... \[DRY RUN\]", re.M),
re.compile(r"^== COMPLETED: Installation ended successfully \(took .* sec\)", re.M),
re.compile(r"^== COMPLETED: Installation ended successfully \(took .* secs?\)", re.M),
]

for msg_regex in msg_regexs:
Expand Down Expand Up @@ -3820,7 +3820,7 @@ def test_extended_dry_run(self):
msg_regexs = [
re.compile(r"the actual build \& install procedure that will be performed may diverge", re.M),
re.compile(r"^\*\*\* DRY RUN using 'EB_toy' easyblock", re.M),
re.compile(r"^== COMPLETED: Installation ended successfully \(took .* sec\)", re.M),
re.compile(r"^== COMPLETED: Installation ended successfully \(took .* secs?\)", re.M),
re.compile(r"^\(no ignored errors during dry run\)", re.M),
]
ignoring_error_regex = re.compile(r"WARNING: ignoring error", re.M)
Expand Down Expand Up @@ -4804,7 +4804,7 @@ def test_stop(self):
args = ['toy-0.0.eb', '--force', '--stop=configure']
txt, _ = self._run_mock_eb(args, do_build=True, raise_error=True, testing=False, strip=True)

regex = re.compile(r"COMPLETED: Installation STOPPED successfully \(took .* sec\)", re.M)
regex = re.compile(r"COMPLETED: Installation STOPPED successfully \(took .* secs?\)", re.M)
self.assertTrue(regex.search(txt), "Pattern '%s' found in: %s" % (regex.pattern, txt))

def test_fetch(self):
Expand All @@ -4829,7 +4829,7 @@ def test_fetch(self):

patterns = [
r"^== fetching files\.\.\.$",
r"^== COMPLETED: Installation STOPPED successfully \(took .* sec\)$",
r"^== COMPLETED: Installation STOPPED successfully \(took .* secs?\)$",
]
for pattern in patterns:
regex = re.compile(pattern, re.M)
Expand Down
2 changes: 1 addition & 1 deletion test/framework/toy_build.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -111,7 +111,7 @@ def check_toy(self, installpath, outtxt, version='0.0', versionprefix='', versio
full_version = ''.join([versionprefix, version, versionsuffix])

# check for success
success = re.compile(r"COMPLETED: Installation ended successfully \(took .* sec\)")
success = re.compile(r"COMPLETED: Installation ended successfully \(took .* secs?\)")
self.assertTrue(success.search(outtxt), "COMPLETED message found in '%s" % outtxt)

# if the module exists, it should be fine
Expand Down
32 changes: 17 additions & 15 deletions test/framework/utilities_test.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -57,21 +57,23 @@ def test_time2str(self):
start = datetime(2019, 7, 30, 5, 14, 23)

test_cases = [
(start, "0 sec"),
(datetime(2019, 7, 30, 5, 14, 37), "14 sec"),
(datetime(2019, 7, 30, 5, 15, 22), "59 sec"),
(datetime(2019, 7, 30, 5, 15, 23), "1 min 0 sec"),
(datetime(2019, 7, 30, 5, 16, 22), "1 min 59 sec"),
(datetime(2019, 7, 30, 5, 37, 26), "23 min 3 sec"),
(datetime(2019, 7, 30, 6, 14, 22), "59 min 59 sec"),
(datetime(2019, 7, 30, 6, 14, 23), "1 hour 0 min 0 sec"),
(datetime(2019, 7, 30, 6, 49, 14), "1 hour 34 min 51 sec"),
(datetime(2019, 7, 30, 7, 14, 23), "2 hours 0 min 0 sec"),
(datetime(2019, 7, 30, 8, 35, 59), "3 hours 21 min 36 sec"),
(datetime(2019, 7, 30, 16, 29, 24), "11 hours 15 min 1 sec"),
(datetime(2019, 7, 31, 5, 14, 22), "23 hours 59 min 59 sec"),
(datetime(2019, 7, 31, 5, 14, 23), "24 hours 0 min 0 sec"),
(datetime(2019, 8, 5, 20, 39, 44), "159 hours 25 min 21 sec"),
(start, "0 secs"),
(datetime(2019, 7, 30, 5, 14, 37), "14 secs"),
(datetime(2019, 7, 30, 5, 15, 22), "59 secs"),
(datetime(2019, 7, 30, 5, 15, 23), "1 min 0 secs"),
(datetime(2019, 7, 30, 5, 16, 22), "1 min 59 secs"),
(datetime(2019, 7, 30, 5, 16, 24), "2 mins 1 sec"),
(datetime(2019, 7, 30, 5, 37, 26), "23 mins 3 secs"),
(datetime(2019, 7, 30, 6, 14, 22), "59 mins 59 secs"),
(datetime(2019, 7, 30, 6, 14, 23), "1 hour 0 mins 0 secs"),
(datetime(2019, 7, 30, 6, 49, 14), "1 hour 34 mins 51 secs"),
(datetime(2019, 7, 30, 7, 14, 23), "2 hours 0 mins 0 secs"),
(datetime(2019, 7, 30, 8, 35, 59), "3 hours 21 mins 36 secs"),
(datetime(2019, 7, 30, 16, 29, 24), "11 hours 15 mins 1 sec"),
(datetime(2019, 7, 31, 5, 14, 22), "23 hours 59 mins 59 secs"),
(datetime(2019, 7, 31, 5, 14, 23), "24 hours 0 mins 0 secs"),
(datetime(2019, 7, 31, 5, 15, 24), "24 hours 1 min 1 sec"),
(datetime(2019, 8, 5, 20, 39, 44), "159 hours 25 mins 21 secs"),
]
for end, expected in test_cases:
self.assertEqual(time2str(end - start), expected)
Expand Down