Skip to content

Commit ebccc05

Browse files
authored
Display core time and wallclock times when test suite finishes, to be able to easily observe/benchmark test suite speedup optimizations. (#24396)
E.g. ![image](https://github.com/user-attachments/assets/ecc3dd77-ae94-4e95-b455-28d37ca91e32) I need to see the test times on core, not in wallclock time in order to be able to optimize test runtimes. A bit clunky, maybe there is a cleaner way to implement this same feature.
1 parent d0e06d8 commit ebccc05

File tree

2 files changed

+18
-6
lines changed

2 files changed

+18
-6
lines changed

test/parallel_testsuite.py

Lines changed: 10 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -90,6 +90,7 @@ def combine_results(self, result, buffered_results):
9090
# Sort the results back into alphabetical order. Running the tests in
9191
# parallel causes mis-orderings, this makes the results more readable.
9292
results = sorted(buffered_results, key=lambda res: str(res.test))
93+
result.core_time = 0
9394
for r in results:
9495
r.updateResult(result)
9596
return result
@@ -102,18 +103,21 @@ class BufferedParallelTestResult:
102103
"""
103104
def __init__(self):
104105
self.buffered_result = None
106+
self.test_duration = 0
105107

106108
@property
107109
def test(self):
108110
return self.buffered_result.test
109111

110-
def addDuration(self, test, elapsed):
111-
pass
112+
def calculateDuration(self):
113+
self.test_duration = time.perf_counter() - self.start_time
114+
return self.test_duration
112115

113116
def updateResult(self, result):
114117
result.startTest(self.test)
115118
self.buffered_result.updateResult(result)
116119
result.stopTest(self.test)
120+
result.core_time += self.test_duration
117121

118122
def startTest(self, test):
119123
self.start_time = time.perf_counter()
@@ -122,21 +126,21 @@ def stopTest(self, test):
122126
# TODO(sbc): figure out a way to display this duration information again when
123127
# these results get passed back to the TextTestRunner/TextTestResult.
124128
if hasattr(time, 'perf_counter'):
125-
self.buffered_result.duration = time.perf_counter() - self.start_time
129+
self.buffered_result.duration = self.test_duration
126130

127131
def addSuccess(self, test):
128132
if hasattr(time, 'perf_counter'):
129-
print(test, '... ok (%.2fs)' % (time.perf_counter() - self.start_time), file=sys.stderr)
133+
print(test, '... ok (%.2fs)' % (self.calculateDuration()), file=sys.stderr)
130134
self.buffered_result = BufferedTestSuccess(test)
131135

132136
def addExpectedFailure(self, test, err):
133137
if hasattr(time, 'perf_counter'):
134-
print(test, '... expected failure (%.2fs)' % (time.perf_counter() - self.start_time), file=sys.stderr)
138+
print(test, '... expected failure (%.2fs)' % (self.calculateDuration()), file=sys.stderr)
135139
self.buffered_result = BufferedTestExpectedFailure(test, err)
136140

137141
def addUnexpectedSuccess(self, test):
138142
if hasattr(time, 'perf_counter'):
139-
print(test, '... unexpected success (%.2fs)' % (time.perf_counter() - self.start_time), file=sys.stderr)
143+
print(test, '... unexpected success (%.2fs)' % (self.calculateDuration()), file=sys.stderr)
140144
self.buffered_result = BufferedTestUnexpectedSuccess(test)
141145

142146
def addSkip(self, test, reason):

test/runner.py

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -29,6 +29,7 @@
2929
import random
3030
import sys
3131
import unittest
32+
import time
3233

3334
# Setup
3435

@@ -348,13 +349,20 @@ def run_tests(options, suites):
348349
else:
349350
testRunner = unittest.TextTestRunner(verbosity=2, failfast=options.failfast)
350351

352+
total_core_time = 0
353+
run_start_time = time.perf_counter()
351354
for mod_name, suite in suites:
352355
print('Running %s: (%s tests)' % (mod_name, suite.countTestCases()))
353356
res = testRunner.run(suite)
354357
msg = ('%s: %s run, %s errors, %s failures, %s skipped' %
355358
(mod_name, res.testsRun, len(res.errors), len(res.failures), len(res.skipped)))
356359
num_failures += len(res.errors) + len(res.failures) + len(res.unexpectedSuccesses)
357360
resultMessages.append(msg)
361+
if hasattr(res, 'core_time'):
362+
total_core_time += res.core_time
363+
total_run_time = time.perf_counter() - run_start_time
364+
if total_core_time > 0:
365+
print('Total core time: %.3fs. Wallclock time: %.3fs. Parallelization: %.2fx.' % (total_core_time, total_run_time, total_core_time / total_run_time))
358366

359367
if len(resultMessages) > 1:
360368
print('====================')

0 commit comments

Comments
 (0)