Skip to content

Commit 544061e

Browse files
smoorssmoors
authored
Merge pull request #3716 from Flamefire/timing
Add per-step timing information
2 parents a80f589 + 7d53ee3 commit 544061e

File tree

5 files changed

+44
-36
lines changed

5 files changed

+44
-36
lines changed

‎easybuild/framework/easyblock.py‎

Lines changed: 10 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -3532,7 +3532,16 @@ def run_all_steps(self, run_test_cases):
35323532
else:
35333533
print_msg("%s..." % descr, log=self.log, silent=self.silent)
35343534
self.current_step = step_name
3535-
self.run_step(step_name, step_methods)
3535+
start_time = datetime.now()
3536+
try:
3537+
self.run_step(step_name, step_methods)
3538+
finally:
3539+
if not self.dry_run:
3540+
step_duration = datetime.now() - start_time
3541+
if step_duration.total_seconds() >= 1:
3542+
print_msg("... (took %s)", time2str(step_duration), log=self.log, silent=self.silent)
3543+
elif self.logdebug or build_option('trace'):
3544+
print_msg("... (took < 1 sec)", log=self.log, silent=self.silent)
35363545

35373546
except StopException:
35383547
pass

‎easybuild/tools/utilities.py‎

Lines changed: 12 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -300,22 +300,19 @@ def time2str(delta):
300300
if not isinstance(delta, datetime.timedelta):
301301
raise EasyBuildError("Incorrect value type provided to time2str, should be datetime.timedelta: %s", type(delta))
302302

303-
delta_secs = delta.days * 3600 * 24 + delta.seconds + delta.microseconds / 10**6
304-
305-
if delta_secs < 60:
306-
res = '%d sec' % int(delta_secs)
307-
elif delta_secs < 3600:
308-
mins = int(delta_secs / 60)
309-
secs = int(delta_secs - (mins * 60))
310-
res = '%d min %d sec' % (mins, secs)
311-
else:
312-
hours = int(delta_secs / 3600)
313-
mins = int((delta_secs - hours * 3600) / 60)
314-
secs = int(delta_secs - (hours * 3600) - (mins * 60))
315-
hours_str = 'hours' if hours > 1 else 'hour'
316-
res = '%d %s %d min %d sec' % (hours, hours_str, mins, secs)
303+
delta_secs = delta.total_seconds()
317304

318-
return res
305+
hours, remainder = divmod(delta_secs, 3600)
306+
mins, secs = divmod(remainder, 60)
307+
308+
res = []
309+
if hours:
310+
res.append('%d %s' % (hours, 'hour' if hours == 1 else 'hours'))
311+
if mins or hours:
312+
res.append('%d %s' % (mins, 'min' if mins == 1 else 'mins'))
313+
res.append('%d %s' % (secs, 'sec' if secs == 1 else 'secs'))
314+
315+
return ' '.join(res)
319316

320317

321318
def natural_keys(key):

‎test/framework/options.py‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1895,7 +1895,7 @@ def test_from_pr_x(self):
18951895
re.compile(r"^\*\*\* DRY RUN using 'EB_FFTW' easyblock", re.M),
18961896
re.compile(r"^== building and installing FFTW/3.3.8-gompi-2018b\.\.\.", re.M),
18971897
re.compile(r"^building... \[DRY RUN\]", re.M),
1898-
re.compile(r"^== COMPLETED: Installation ended successfully \(took .* sec\)", re.M),
1898+
re.compile(r"^== COMPLETED: Installation ended successfully \(took .* secs?\)", re.M),
18991899
]
19001900

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

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

48104810
def test_fetch(self):
@@ -4829,7 +4829,7 @@ def test_fetch(self):
48294829

48304830
patterns = [
48314831
r"^== fetching files\.\.\.$",
4832-
r"^== COMPLETED: Installation STOPPED successfully \(took .* sec\)$",
4832+
r"^== COMPLETED: Installation STOPPED successfully \(took .* secs?\)$",
48334833
]
48344834
for pattern in patterns:
48354835
regex = re.compile(pattern, re.M)

‎test/framework/toy_build.py‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -112,7 +112,7 @@ def check_toy(self, installpath, outtxt, version='0.0', versionprefix='', versio
112112
full_version = ''.join([versionprefix, version, versionsuffix])
113113

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

118118
# if the module exists, it should be fine

‎test/framework/utilities_test.py‎

Lines changed: 17 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -57,21 +57,23 @@ def test_time2str(self):
5757
start = datetime(2019, 7, 30, 5, 14, 23)
5858

5959
test_cases = [
60-
(start, "0 sec"),
61-
(datetime(2019, 7, 30, 5, 14, 37), "14 sec"),
62-
(datetime(2019, 7, 30, 5, 15, 22), "59 sec"),
63-
(datetime(2019, 7, 30, 5, 15, 23), "1 min 0 sec"),
64-
(datetime(2019, 7, 30, 5, 16, 22), "1 min 59 sec"),
65-
(datetime(2019, 7, 30, 5, 37, 26), "23 min 3 sec"),
66-
(datetime(2019, 7, 30, 6, 14, 22), "59 min 59 sec"),
67-
(datetime(2019, 7, 30, 6, 14, 23), "1 hour 0 min 0 sec"),
68-
(datetime(2019, 7, 30, 6, 49, 14), "1 hour 34 min 51 sec"),
69-
(datetime(2019, 7, 30, 7, 14, 23), "2 hours 0 min 0 sec"),
70-
(datetime(2019, 7, 30, 8, 35, 59), "3 hours 21 min 36 sec"),
71-
(datetime(2019, 7, 30, 16, 29, 24), "11 hours 15 min 1 sec"),
72-
(datetime(2019, 7, 31, 5, 14, 22), "23 hours 59 min 59 sec"),
73-
(datetime(2019, 7, 31, 5, 14, 23), "24 hours 0 min 0 sec"),
74-
(datetime(2019, 8, 5, 20, 39, 44), "159 hours 25 min 21 sec"),
60+
(start, "0 secs"),
61+
(datetime(2019, 7, 30, 5, 14, 37), "14 secs"),
62+
(datetime(2019, 7, 30, 5, 15, 22), "59 secs"),
63+
(datetime(2019, 7, 30, 5, 15, 23), "1 min 0 secs"),
64+
(datetime(2019, 7, 30, 5, 16, 22), "1 min 59 secs"),
65+
(datetime(2019, 7, 30, 5, 16, 24), "2 mins 1 sec"),
66+
(datetime(2019, 7, 30, 5, 37, 26), "23 mins 3 secs"),
67+
(datetime(2019, 7, 30, 6, 14, 22), "59 mins 59 secs"),
68+
(datetime(2019, 7, 30, 6, 14, 23), "1 hour 0 mins 0 secs"),
69+
(datetime(2019, 7, 30, 6, 49, 14), "1 hour 34 mins 51 secs"),
70+
(datetime(2019, 7, 30, 7, 14, 23), "2 hours 0 mins 0 secs"),
71+
(datetime(2019, 7, 30, 8, 35, 59), "3 hours 21 mins 36 secs"),
72+
(datetime(2019, 7, 30, 16, 29, 24), "11 hours 15 mins 1 sec"),
73+
(datetime(2019, 7, 31, 5, 14, 22), "23 hours 59 mins 59 secs"),
74+
(datetime(2019, 7, 31, 5, 14, 23), "24 hours 0 mins 0 secs"),
75+
(datetime(2019, 7, 31, 5, 15, 24), "24 hours 1 min 1 sec"),
76+
(datetime(2019, 8, 5, 20, 39, 44), "159 hours 25 mins 21 secs"),
7577
]
7678
for end, expected in test_cases:
7779
self.assertEqual(time2str(end - start), expected)

0 commit comments

Comments
 (0)