def test_run_and_log(self):
def mock_run(test):
self.assertEquals(test, 'b1')
return PerformanceTestResult(
'3,b1,5,101,1,1,1,1,888'.split(','),
quantiles=True, delta=True, memory=True)
driver = BenchmarkDriver(tests=['b1'], args=Stub(output_dir=None))
driver.run_independent_samples = mock_run # patching
with captured_output() as (out, _):
log = driver.run_and_log()
header = '#,TEST,SAMPLES,MIN(μs),Q1(μs),MEDIAN(μs),Q3(μs),MAX(μs),' +\
'MAX_RSS(B)\n'
csv_log = '3,b1,5,101,102,103,104,105,888\n'
self.assertEquals(log, None)
self.assertEquals(
out.getvalue(),
header +
csv_log +
'\n' +
'Total performance tests executed: 1\n')
with captured_output() as (out, _):
log = driver.run_and_log(csv_console=False)
self.assertEquals(log, header + csv_log)
self.assertEquals(
out.getvalue(),
' # TEST SAMPLES MIN(μs) Q1(μs)' +
' MEDIAN(μs) Q3(μs) MAX(μs) MAX_RSS(B)\n' +
' 3 b1 5 101 102' +
' 103 104 105 888\n' +
'\n' +
'Total performance tests executed: 1\n')
def test_log_results(self):
"""Create log directory if it doesn't exist and write the log file."""
def assert_log_written(out, log_file, content):
self.assertEquals(out.getvalue(),
'Logging results to: ' + log_file + '\n')
with open(log_file, 'rU') as f:
text = f.read()
self.assertEquals(text, "formatted output")
try:
import tempfile # setUp
temp_dir = tempfile.mkdtemp()
log_dir = os.path.join(temp_dir, 'sub-dir/')
driver = BenchmarkDriver(Stub(), tests=[''])
self.assertFalse(os.path.exists(log_dir))
content = "formatted output"
log_file = os.path.join(log_dir, '1.log')
with captured_output() as (out, _):
driver.log_results(content, log_file=log_file)
assert_log_written(out, log_file, content)
self.assertTrue(os.path.exists(log_dir))
log_file = os.path.join(log_dir, '2.log')
with captured_output() as (out, _):
driver.log_results(content, log_file=log_file)
assert_log_written(out, log_file, content)
finally:
import shutil # tearDown
shutil.rmtree(temp_dir)
def test_benchmark_has_no_significant_setup_overhead(self):
with captured_output() as (out, _):
doctor = BenchmarkDoctor(self.args, BenchmarkDriverMock([]))
doctor.analyze({
'name': 'NoOverhead', # not 'significant' enough
# Based on DropFirstArray a10/e10: overhead 3.7% (6 μs)
'NoOverhead O i1a': _PTR(min=162),
'NoOverhead O i2a': _PTR(min=159)})
doctor.analyze({
'name': 'SO', # Setup Overhead
# Based on SuffixArrayLazy a10/e10: overhead 5.8% (4 μs)
'SO O i1a': _PTR(min=69), 'SO O i1b': _PTR(min=70),
'SO O i2a': _PTR(min=67), 'SO O i2b': _PTR(min=68)})
doctor.analyze({'name': 'Zero', 'Zero O i1a': _PTR(min=0),
'Zero O i2a': _PTR(min=0)})
output = out.getvalue()
self.assertIn('runtime: ', output)
self.assertNotIn('NoOverhead', output)
self.assertNotIn('ZeroRuntime', output)
self.assert_contains(
["'SO' has setup overhead of 4 μs (5.8%)."],
self.logs['error'])
self.assert_contains(
["Move initialization of benchmark data to the `setUpFunction` "
"registered in `BenchmarkInfo`."], self.logs['info'])
def test_benchmark_name_matches_naming_conventions(self):
driver = BenchmarkDriverMock(tests=[
'BenchmarkName', 'CapitalWordsConvention', 'ABBRName',
'TooManyCamelCaseHumps',
'Existential.Array.method.1x.Val4',
'Flatten.Array.Array.Str.for-in.reserved',
'Flatten.Array.String?.as!.NSArray',
'wrongCase', 'Wrong_convention', 'Illegal._$%[]<>{}@^()'])
with captured_output() as (out, _):
doctor = BenchmarkDoctor(self.args, driver)
doctor.check()
output = out.getvalue()
self.assertIn('naming: ', output)
self.assertNotIn('BenchmarkName', output)
self.assertNotIn('CapitalWordsConvention', output)
self.assertNotIn('ABBRName', output)
self.assertNotIn('Existential.Array.method.1x.Val4', output)
self.assertNotIn('Flatten.Array.Array.Str.for-in.reserved', output)
self.assertNotIn('Flatten.Array.String?.as!.NSArray', output)
err_msg = " name doesn't conform to benchmark naming convention."
self.assert_contains(
["'wrongCase'" + err_msg, "'Wrong_convention'" + err_msg,
"'Illegal._$%[]<>{}@^()'" + err_msg], self.logs['error'])
self.assert_contains(
["'TooManyCamelCaseHumps' name is composed of 5 words."],
self.logs['warning'])
self.assert_contains(
['See http://bit.ly/BenchmarkNaming'], self.logs['info'])
self.assert_contains(
["Split 'TooManyCamelCaseHumps' name into dot-separated groups "
"and variants. See http://bit.ly/BenchmarkNaming"],
self.logs['info'])
def test_supports_verbose_output(self):
driver = BenchmarkDriverMock(tests=['B1', 'B2'])
driver.verbose = True
self.args.verbose = True
with captured_output() as (out, _):
BenchmarkDoctor(self.args, driver)
self.assert_contains(['Checking tests: B1, B2'], out.getvalue())
def test_uses_optional_markdown_report_formatter(self):
self.args.markdown = True
with captured_output() as (_, _):
doc = BenchmarkDoctor(self.args, BenchmarkDriverMock(tests=['B1']))
self.assertTrue(doc)
console_handler = logging.getLogger('BenchmarkDoctor').handlers[1]
self.assertTrue(isinstance(console_handler, MarkdownReportHandler))
def test_measure_10_independent_1s_benchmark_series(self):
"""Measurement strategy takes 5 i2 and 5 i1 series.
Num-samples for Benchmark Driver are calibrated to be powers of two,
take measurements for approximately 1s
based on short initial runtime sampling. Capped at 200 samples.
"""
driver = BenchmarkDriverMock(tests=['B1'], responses=([
# calibration run, returns a stand-in for PerformanceTestResult
(_run('B1', num_samples=3, num_iters=1,
verbose=True), _PTR(min=300))] +
# 5x i1 series, with 300 μs runtime its possible to take 4098
# samples/s, but it should be capped at 2k
([(_run('B1', num_samples=200, num_iters=1,
verbose=True, measure_memory=True), _PTR(min=300))] * 5) +
# 5x i2 series
([(_run('B1', num_samples=200, num_iters=2,
verbose=True, measure_memory=True), _PTR(min=300))] * 5)
))
doctor = BenchmarkDoctor(self.args, driver)
with captured_output() as (out, _):
measurements = doctor.measure('B1')
driver.assert_called_all_expected()
self.assert_contains(
['name',
'B1 O i1a', 'B1 O i1b', 'B1 O i1c', 'B1 O i1d', 'B1 O i1e',
'B1 O i2a', 'B1 O i2b', 'B1 O i2c', 'B1 O i2d', 'B1 O i2e'],
measurements.keys())
self.assertEquals(measurements['name'], 'B1')
self.assert_contains(
['Calibrating num-samples for B1:',
'Runtime 300 μs yields 4096 adjusted samples per second.',
'Measuring B1, 5 x i1 (200 samples), 5 x i2 (200 samples)'],
self.logs['debug'])
def test_benchmark_runtime_range(self):
"""Optimized benchmark should have runtime between 20 μs and 1000 μs.
Even on calm machine, benchmark with runtime of 2500 μs has 1:4 chance
of being interrupted in the middle of measurement due to elapsed 10 ms
quantum used by macos scheduler. Linux scheduler's quantum is 6ms.
Driver yielding the process before the 10ms quantum elapses helped
a lot, but benchmarks with runtimes under 1ms usually exhibit a strong
mode which is best for accurate performance charaterization.
To minimize the number of involuntary context switches that corrupt our
measurements, we should strive to stay in the microbenchmark range.
Warn about longer runtime. Runtimes over 10ms are an error.
"""
def measurements(name, runtime):
return {'name': name,
name + ' O i1a': _PTR(min=runtime + 2),
name + ' O i2a': _PTR(min=runtime)}
with captured_output() as (out, _):
doctor = BenchmarkDoctor(self.args, BenchmarkDriverMock([]))
doctor.analyze(measurements('Sylph', 0))
doctor.analyze(measurements('Unicorn', 3))
doctor.analyze(measurements('Cheetah', 200))
doctor.analyze(measurements('Hare', 1001))
doctor.analyze(measurements('Tortoise', 500000))
doctor.analyze({'name': 'OverheadTurtle',
'OverheadTurtle O i1a': _PTR(min=800000),
'OverheadTurtle O i2a': _PTR(min=700000)})
output = out.getvalue()
self.assertIn('runtime: ', output)
self.assertNotIn('Cheetah', output)
self.assert_contains(["'Sylph' execution took 0 μs."],
self.logs['error'])
self.assert_contains(
["Ensure the workload of 'Sylph' has a properly measurable size"
" (runtime > 20 μs) and is not eliminated by the compiler (use "
"`blackHole` function if necessary)."],
self.logs['info'])
self.assert_contains(["'Unicorn' execution took 3 μs."],
self.logs['warning'])
self.assert_contains(
["Increase the workload of 'Unicorn' to be more than 20 μs."],
self.logs['info'])
self.assert_contains(["'Hare' execution took at least 1001 μs."],
self.logs['warning'])
self.assert_contains(
["Decrease the workload of 'Hare' by a factor of 2 (10), "
"to be less than 1000 μs."], self.logs['info'])
self.assert_contains(
["'Tortoise' execution took at least 500000 μs."],
self.logs['error'])
self.assert_contains(
["Decrease the workload of 'Tortoise' by a factor of 512 (1000), "
"to be less than 1000 μs."], self.logs['info'])
self.assert_contains(
["'OverheadTurtle' execution took at least 600000 μs"
" (excluding the setup overhead)."],
self.logs['error'])
def test_required_input_arguments(self):
with captured_output() as (_, err):
self.assertRaises(SystemExit, parse_args, [])
self.assertIn('usage: compare_perf_tests.py', err.getvalue())
args = parse_args(self.required)
self.assertEquals(args.old_file, 'old.log')
self.assertEquals(args.new_file, 'new.log')
def test_run_benchmarks_and_filters_are_exclusive(self):
with captured_output() as (_, err):
self.assertRaises(SystemExit,
parse_args, 'run -f Filter1 Benchmark1'.split())
self.assert_contains(
['error',
'argument BENCHMARK: not allowed with argument -f/--filter'],
err.getvalue())
def test_check_flags_are_mutually_exclusive(self):
with captured_output() as (out, err):
self.assertRaises(SystemExit,
parse_args, ['check', '-md', '-v'])
self.assert_contains(
['error:', 'argument -v/--verbose: ' +
'not allowed with argument -md/--markdown'],
err.getvalue())
def test_iterations(self):
self.assertEquals(parse_args(['run']).iterations, 1)
self.assertEquals(parse_args(['run', '-i', '3']).iterations, 3)
with captured_output() as (out, err):
self.assertRaises(SystemExit,
parse_args, ['run', '-i', '-3'])
self.assert_contains(
['error:',
"argument -i/--iterations: invalid positive_int value: '-3'"],
err.getvalue())
def test_benchmark_has_constant_memory_use(self):
"""Benchmark's memory footprint must not vary with num-iters."""
with captured_output() as (out, _):
doctor = BenchmarkDoctor(self.args, BenchmarkDriverMock([]))
doctor.analyze({
# The threshold of 15 pages was estimated from previous
# measurements. The normal range should be probably aproximated
# by a function instead of a simple constant.
# TODO: re-evaluate normal range from whole SBS
'name': 'ConstantMemory',
'ConstantMemory O i1a': _PTR(mem_pages=1460),
'ConstantMemory O i2a': _PTR(mem_pages=(1460 + 15))})
doctor.analyze({
'name': 'VariableMemory', # ObserverForwardStruct
'VariableMemory O i1a': _PTR(mem_pages=1460),
'VariableMemory O i1b': _PTR(mem_pages=1472),
# i2 series start at 290 pages higher
'VariableMemory O i2a': _PTR(mem_pages=1750),
'VariableMemory O i2b': _PTR(mem_pages=1752)})
measurements = dict([
('HighVariance O i{0}{1}'.format(num_iters, suffix),
_PTR(mem_pages=num_pages))
for num_iters, pages in [
(1, [6200, 5943, 4818, 5612, 5469]),
(2, [6244, 5832, 4674, 5176, 5490])]
for num_pages, suffix in zip(pages, list('abcde'))])
measurements['name'] = 'HighVariance' # Array2D
doctor.analyze(measurements)
output = out.getvalue()
self.assertIn('memory: ', output)
self.assertNotIn('ConstantMemory', output)
self.assert_contains(
["'VariableMemory' varies the memory footprint of the base "
"workload depending on the `num-iters`."],
self.logs['error'])
self.assert_contains(
["'VariableMemory' "
"mem_pages [i1, i2]: min=[1460, 1750] 𝚫=290 R=[12, 2]"],
self.logs['info'])
self.assert_contains(
["'HighVariance' has very wide range of memory used between "
"independent, repeated measurements."],
self.logs['warning'])
self.assert_contains(
["'HighVariance' "
"mem_pages [i1, i2]: min=[4818, 4674] 𝚫=144 R=[1382, 1570]"],
self.logs['info'])
def test_format_argument(self):
self.assertEquals(parse_args(self.required).format, 'markdown')
self.assertEquals(
parse_args(self.required + ['--format', 'markdown']).format,
'markdown')
self.assertEquals(
parse_args(self.required + ['--format', 'git']).format, 'git')
self.assertEquals(
parse_args(self.required + ['--format', 'html']).format, 'html')
with captured_output() as (_, err):
self.assertRaises(SystemExit, parse_args,
self.required + ['--format', 'bogus'])
self.assertIn(
"error: argument --format: invalid choice: 'bogus' "
"(choose from 'markdown', 'git', 'html')", err.getvalue())
def test_optimization_argument(self):
self.assertEqual(parse_args(["run"]).optimization, "O")
self.assertEqual(parse_args(["run", "-o", "O"]).optimization, "O")
self.assertEqual(parse_args(["run", "-o", "Onone"]).optimization, "Onone")
self.assertEqual(parse_args(["run", "-o", "Osize"]).optimization, "Osize")
with captured_output() as (_, err):
self.assertRaises(SystemExit, parse_args, ["run", "-o", "bogus"])
self.assert_contains(
[
"error:",
"argument -o/--optimization: invalid choice: 'bogus'",
"(choose from 'O', 'Onone', 'Osize')",
],
err.getvalue(),
)
def test_format_argument(self):
self.assertEquals(parse_args(self.required).format, 'markdown')
self.assertEquals(
parse_args(self.required + ['--format', 'markdown']).format,
'markdown')
self.assertEquals(
parse_args(self.required + ['--format', 'git']).format, 'git')
self.assertEquals(
parse_args(self.required + ['--format', 'html']).format, 'html')
with captured_output() as (_, err):
self.assertRaises(SystemExit, parse_args,
self.required + ['--format', 'bogus'])
self.assertIn("error: argument --format: invalid choice: 'bogus' "
"(choose from 'markdown', 'git', 'html')",
err.getvalue())
def test_benchmark_name_matches_naming_conventions(self):
driver = BenchmarkDriverMock(tests=[
"BenchmarkName",
"CapitalWordsConvention",
"ABBRName",
"TooManyCamelCaseHumps",
"Existential.Array.method.1x.Val4",
"Flatten.Array.Array.Str.for-in.reserved",
"Flatten.Array.String?.as!.NSArray",
"wrongCase",
"Wrong_convention",
"Illegal._$%[]<>{}@^()",
])
with captured_output() as (out, _):
doctor = BenchmarkDoctor(self.args, driver)
doctor.check()
output = out.getvalue()
self.assertIn("naming: ", output)
self.assertNotIn("BenchmarkName", output)
self.assertNotIn("CapitalWordsConvention", output)
self.assertNotIn("ABBRName", output)
self.assertNotIn("Existential.Array.method.1x.Val4", output)
self.assertNotIn("Flatten.Array.Array.Str.for-in.reserved", output)
self.assertNotIn("Flatten.Array.String?.as!.NSArray", output)
err_msg = " name doesn't conform to benchmark naming convention."
self.assert_contains(
[
"'wrongCase'" + err_msg,
"'Wrong_convention'" + err_msg,
"'Illegal._$%[]<>{}@^()'" + err_msg,
],
self.logs["error"],
)
self.assert_contains(
["'TooManyCamelCaseHumps' name is composed of 5 words."],
self.logs["warning"],
)
self.assert_contains(["See http://bit.ly/BenchmarkNaming"],
self.logs["info"])
self.assert_contains(
[
"Split 'TooManyCamelCaseHumps' name into dot-separated groups "
"and variants. See http://bit.ly/BenchmarkNaming"
],
self.logs["info"],
)
def test_benchmark_name_is_at_most_40_chars_long(self):
driver = BenchmarkDriverMock(tests=[
'BenchmarkName',
'ThisTestNameIsTooLongAndCausesOverflowsInReports'])
with captured_output() as (out, _):
doctor = BenchmarkDoctor(self.args, driver)
doctor.check()
output = out.getvalue()
self.assertIn('naming: ', output)
self.assertNotIn('BenchmarkName', output)
self.assert_contains(
["'ThisTestNameIsTooLongAndCausesOverflowsInReports' name is "
"48 characters long."], self.logs['error'])
self.assert_contains(
["Benchmark name should not be longer than 40 characters."],
self.logs['info'])
def test_print_and_log(num_evals, expected_prints, expected_logs):
with captured_output() as (out, err):
init_num_iterations = obj.num_iterations()
for iter in range(num_evals):
# Funtion evaluations should be printed and logged.
obj.f(x0)
# Derivatives should not count towards printing or logging.
obj.grad(x0)
obj.hessian(x0)
obj.hessian_vector_product(x0, x0)
lines = out.getvalue().splitlines()
self.assertEqual(init_num_iterations + num_evals,
obj.num_iterations())
self.assertEqual(len(lines), expected_prints)
self.assertEqual(len(obj.optimization_log), expected_logs)
def test_optimization_argument(self):
self.assertEqual(parse_args(['run']).optimization, 'O')
self.assertEqual(
parse_args(['run', '-o', 'O']).optimization, 'O')
self.assertEqual(
parse_args(['run', '-o', 'Onone']).optimization, 'Onone')
self.assertEqual(
parse_args(['run', '-o', 'Osize']).optimization, 'Osize')
with captured_output() as (_, err):
self.assertRaises(SystemExit,
parse_args, ['run', '-o', 'bogus'])
self.assert_contains(
['error:',
"argument -o/--optimization: invalid choice: 'bogus'",
"(choose from 'O', 'Onone', 'Osize')"],
err.getvalue())
def test_optimization_argument(self):
self.assertEquals(parse_args(['run']).optimization, 'O')
self.assertEquals(
parse_args(['run', '-o', 'O']).optimization, 'O')
self.assertEquals(
parse_args(['run', '-o', 'Onone']).optimization, 'Onone')
self.assertEquals(
parse_args(['run', '-o', 'Osize']).optimization, 'Osize')
with captured_output() as (_, err):
self.assertRaises(SystemExit,
parse_args, ['run', '-o', 'bogus'])
self.assert_contains(
['error:',
"argument -o/--optimization: invalid choice: 'bogus'",
"(choose from 'O', 'Onone', 'Osize')"],
err.getvalue())
def test_benchmark_runtime_range(self):
"""Optimized benchmark should run in less then 2500 μs.
With runtimes less than 2500 μs there is better than 1:4 chance of
being interrupted in the middle of measurement due to elapsed 10 ms
quantum used by macos scheduler.
Warn about longer runtime. Runtimes over half a second are an error.
"""
def measurements(name, runtime):
return {
'name': name,
name + ' O i1a': _PTR(min=runtime + 2),
name + ' O i2a': _PTR(min=runtime)
}
with captured_output() as (out, _):
doctor = BenchmarkDoctor(self.args, BenchmarkDriverMock([]))
doctor.analyze(measurements('Cheetah', 200))
doctor.analyze(measurements('Hare', 2501))
doctor.analyze(measurements('Tortoise', 500000))
doctor.analyze({
'name': 'OverheadTurtle',
'OverheadTurtle O i1a': _PTR(min=800000),
'OverheadTurtle O i2a': _PTR(min=700000)
})
output = out.getvalue()
self.assertIn('runtime: ', output)
self.assertNotIn('Cheetah', output)
self.assert_contains(["'Hare' execution took at least 2501 μs."],
self.logs['warning'])
self.assert_contains([
"Decrease the workload of 'Hare' by a factor of 2, "
"to be less than 2500 μs."
], self.logs['info'])
self.assert_contains(["'Tortoise' execution took at least 500000 μs."],
self.logs['error'])
self.assert_contains([
"Decrease the workload of 'Tortoise' by a factor of 256, "
"to be less than 2500 μs."
], self.logs['info'])
self.assert_contains([
"'OverheadTurtle' execution took at least 600000 μs"
" (excluding the setup overhead)."
], self.logs['error'])
def test_benchmark_name_is_at_most_40_chars_long(self):
driver = BenchmarkDriverMock(tests=[
'BenchmarkName',
'ThisTestNameIsTooLongAndCausesOverflowsInReports'])
with captured_output() as (out, _):
doctor = BenchmarkDoctor(self.args, driver)
doctor.check()
output = out.getvalue()
self.assertIn('naming: ', output)
self.assertNotIn('BenchmarkName', output)
self.assert_contains(
["'ThisTestNameIsTooLongAndCausesOverflowsInReports' name is "
"48 characters long."], self.logs['error'])
self.assert_contains(
["Benchmark name should not be longer than 40 characters."],
self.logs['info'])
def test_delta_threshold_argument(self):
# default value
args = parse_args(self.required)
self.assertEqual(args.delta_threshold, 0.05)
# float parsing
args = parse_args(self.required + ['--delta-threshold', '0.1'])
self.assertEqual(args.delta_threshold, 0.1)
args = parse_args(self.required + ['--delta-threshold', '1'])
self.assertEqual(args.delta_threshold, 1.0)
args = parse_args(self.required + ['--delta-threshold', '.2'])
self.assertEqual(args.delta_threshold, 0.2)
with captured_output() as (_, err):
self.assertRaises(SystemExit, parse_args,
self.required + ['--delta-threshold', '2,2'])
self.assertIn(
" error: argument --delta-threshold: invalid float "
"value: '2,2'", err.getvalue())
def test_run_bechmarks(self):
def mock_run(test):
self.assertEquals(test, 'b1')
return PerformanceTestResult(
'3,b1,1,123,123,123,0,123,888'.split(','))
driver = Stub(tests=['b1'])
driver.run_independent_samples = mock_run
run_benchmarks = Benchmark_Driver.run_benchmarks
with captured_output() as (out, _):
run_benchmarks(driver)
self.assertEquals('\n'.join("""
#,TEST,SAMPLES,MIN(μs),MAX(μs),MEAN(μs),SD(μs),MEDIAN(μs),MAX_RSS(B)
3,b1,1,123,123,123,0,123,888
Totals,1
""".splitlines()[1:]), out.getvalue()) # removes 1st \n from multiline string
def test_format_argument(self):
self.assertEqual(parse_args(self.required).format, "markdown")
self.assertEqual(
parse_args(self.required + ["--format", "markdown"]).format,
"markdown")
self.assertEqual(
parse_args(self.required + ["--format", "git"]).format, "git")
self.assertEqual(
parse_args(self.required + ["--format", "html"]).format, "html")
with captured_output() as (_, err):
self.assertRaises(SystemExit, parse_args,
self.required + ["--format", "bogus"])
self.assertIn(
"error: argument --format: invalid choice: 'bogus' "
"(choose from 'markdown', 'git', 'html')",
err.getvalue(),
)
def test_delta_threshold_argument(self):
# default value
args = parse_args(self.required)
self.assertEquals(args.delta_threshold, 0.05)
# float parsing
args = parse_args(self.required + ['--delta-threshold', '0.1'])
self.assertEquals(args.delta_threshold, 0.1)
args = parse_args(self.required + ['--delta-threshold', '1'])
self.assertEquals(args.delta_threshold, 1.0)
args = parse_args(self.required + ['--delta-threshold', '.2'])
self.assertEquals(args.delta_threshold, 0.2)
with captured_output() as (_, err):
self.assertRaises(SystemExit, parse_args,
self.required + ['--delta-threshold', '2,2'])
self.assertIn(" error: argument --delta-threshold: invalid float "
"value: '2,2'",
err.getvalue())
def test_benchmark_has_no_significant_setup_overhead(self):
with captured_output() as (out, _):
doctor = BenchmarkDoctor(self.args, BenchmarkDriverMock([]))
doctor.analyze({
"name": "NoOverhead", # not 'significant' enough
# Based on DropFirstArray a10/e10: overhead 3.7% (6 μs)
"NoOverhead O i1a": _PTR(min=162),
"NoOverhead O i2a": _PTR(min=159),
})
doctor.analyze({
"name": "SO", # Setup Overhead
# Based on SuffixArrayLazy a10/e10: overhead 5.8% (4 μs)
"SO O i1a": _PTR(min=69),
"SO O i1b": _PTR(min=70),
"SO O i2a": _PTR(min=67),
"SO O i2b": _PTR(min=68),
})
doctor.analyze({
"name": "Zero",
"Zero O i1a": _PTR(min=0),
"Zero O i2a": _PTR(min=0)
})
doctor.analyze({
"name": "LOA", # Limit of Accuracy
# Impossible to detect overhead:
# Even 1μs change in 20μs runtime is 5%.
"LOA O i1a": _PTR(min=21),
"LOA O i2a": _PTR(min=20),
})
output = out.getvalue()
self.assertIn("runtime: ", output)
self.assertNotIn("NoOverhead", output)
self.assertNotIn("ZeroRuntime", output)
self.assertNotIn("LOA", output)
self.assert_contains(["'SO' has setup overhead of 4 μs (5.8%)."],
self.logs["error"])
self.assert_contains(
[
"Move initialization of benchmark data to the `setUpFunction` "
"registered in `BenchmarkInfo`."
],
self.logs["info"],
)
def test_benchmark_name_matches_capital_words_conventions(self):
driver = BenchmarkDriverMock(tests=[
'BenchmarkName', 'CapitalWordsConvention', 'ABBRName',
'wrongCase', 'Wrong_convention'])
with captured_output() as (out, _):
doctor = BenchmarkDoctor(self.args, driver)
doctor.check()
output = out.getvalue()
self.assertIn('naming: ', output)
self.assertNotIn('BenchmarkName', output)
self.assertNotIn('CapitalWordsConvention', output)
self.assertNotIn('ABBRName', output)
self.assert_contains(
["'wrongCase' name doesn't conform to UpperCamelCase convention.",
"'Wrong_convention' name doesn't conform to UpperCamelCase "
"convention."], self.logs['error'])
self.assert_contains(
['See http://bit.ly/UpperCamelCase'], self.logs['info'])
def test_measure_10_independent_1s_benchmark_series(self):
"""Measurement strategy takes 5 i2 and 5 i1 series.
Num-samples for Benchmark Driver are calibrated to be powers of two,
take measurements for approximately 1s
based on short initial runtime sampling. Capped at 200 samples.
"""
driver = BenchmarkDriverMock(
tests=['B1'],
responses=
([
# calibration run, returns a stand-in for PerformanceTestResult
(_run('B1', num_samples=3, num_iters=1,
verbose=True), _PTR(min=300))
] +
# 5x i1 series, with 300 μs runtime its possible to take 4098
# samples/s, but it should be capped at 2k
([(_run('B1',
num_samples=200,
num_iters=1,
verbose=True,
measure_memory=True), _PTR(min=300))] * 5) +
# 5x i2 series
([(_run('B1',
num_samples=200,
num_iters=2,
verbose=True,
measure_memory=True), _PTR(min=300))] * 5)))
doctor = BenchmarkDoctor(self.args, driver)
with captured_output() as (out, _):
measurements = doctor.measure('B1')
driver.assert_called_all_expected()
self.assert_contains([
'name', 'B1 O i1a', 'B1 O i1b', 'B1 O i1c', 'B1 O i1d', 'B1 O i1e',
'B1 O i2a', 'B1 O i2b', 'B1 O i2c', 'B1 O i2d', 'B1 O i2e'
], measurements.keys())
self.assertEquals(measurements['name'], 'B1')
self.assert_contains([
'Calibrating num-samples for B1:',
'Runtime 300 μs yields 4096 adjusted samples per second.',
'Measuring B1, 5 x i1 (200 samples), 5 x i2 (200 samples)'
], self.logs['debug'])
def test_run_bechmarks(self):
def mock_run(test):
self.assertEquals(test, 'b1')
return PerformanceTestResult(
'3,b1,1,123,123,123,0,123,888'.split(','))
driver = Stub(tests=['b1'])
driver.run_independent_samples = mock_run
run_benchmarks = Benchmark_Driver.run_benchmarks
with captured_output() as (out, _):
run_benchmarks(driver)
self.assertEquals('\n'.join("""
#,TEST,SAMPLES,MIN(μs),MAX(μs),MEAN(μs),SD(μs),MEDIAN(μs),MAX_RSS(B)
3,b1,1,123,123,123,0,123,888
Totals,1
""".splitlines()[1:]), out.getvalue()) # removes 1st \n from multiline string
def test_benchmark_has_constant_memory_use(self):
"""Benchmark's memory footprint must not vary with num-iters."""
with captured_output() as (out, _):
doctor = BenchmarkDoctor(self.args, BenchmarkDriverMock([]))
doctor.analyze({
# The threshold of 15 pages was estimated from previous
# measurements. The normal range should be probably aproximated
# by a function instead of a simple constant.
# TODO: re-evaluate normal range from whole SBS
'name': 'ConstantMemory',
'ConstantMemory O i1a': _PTR(mem_pages=1460),
'ConstantMemory O i2a': _PTR(mem_pages=(1460 + 15))
})
doctor.analyze({
'name': 'VariableMemory', # ObserverForwardStruct
'VariableMemory O i1a': _PTR(mem_pages=1460),
'VariableMemory O i1b': _PTR(mem_pages=1472),
# i2 series start at 290 pages higher
'VariableMemory O i2a': _PTR(mem_pages=1750),
'VariableMemory O i2b': _PTR(mem_pages=1752)
})
measurements = dict([
('HighVariance O i{0}{1}'.format(num_iters, suffix),
_PTR(mem_pages=num_pages))
for num_iters, pages in [(1, [6200, 5943, 4818, 5612, 5469]
), (2,
[6244, 5832, 4674, 5176, 5490])]
for num_pages, suffix in zip(pages, list('abcde'))
])
measurements['name'] = 'HighVariance' # Array2D
doctor.analyze(measurements)
output = out.getvalue()
self.assertIn('memory: ', output)
self.assertNotIn('ConstantMemory', output)
self.assert_contains([
"'VariableMemory' varies the memory footprint of the base "
"workload depending on the `num-iters`."
], self.logs['error'])
self.assert_contains([
"'HighVariance' has very wide range of memory used between "
"independent, repeated measurements."
], self.logs['warning'])
def test_benchmark_name_matches_capital_words_conventions(self):
driver = BenchmarkDriverMock(tests=[
'BenchmarkName', 'CapitalWordsConvention', 'ABBRName',
'wrongCase', 'Wrong_convention'])
with captured_output() as (out, _):
doctor = BenchmarkDoctor(self.args, driver)
doctor.check()
output = out.getvalue()
self.assertIn('naming: ', output)
self.assertNotIn('BenchmarkName', output)
self.assertNotIn('CapitalWordsConvention', output)
self.assertNotIn('ABBRName', output)
self.assert_contains(
["'wrongCase' name doesn't conform to UpperCamelCase convention.",
"'Wrong_convention' name doesn't conform to UpperCamelCase "
"convention."], self.logs['error'])
self.assert_contains(
['See http://bit.ly/UpperCamelCase'], self.logs['info'])
def test_display_full(self):
""" test _display_compact function """
# create a FtpFileDownloader for the test
ftp = FtpFileDownloader(server_url='localhost',
username='******',
password='******',
port=2121,
concurrent_connections=4,
min_blocks_per_segment=1,
max_blocks_per_segment=2,
initial_blocksize=1048576,
kill_speed=0,
clean=True)
# create a blockmap for the test
blockmap = create_blockmap(self._results_dir, 1024 * 1024 * 32)
blockmap.init_blockmap()
blockmap.change_block_range_status(1024 * 1024 * 2, 2,
Blockmap.DOWNLOADED)
blockmap.change_block_range_status(1024 * 1024 * 24, 2,
Blockmap.PENDING)
blockmap.change_block_range_status(1024 * 1024 * 30, 2,
Blockmap.SAVING)
# check the display_compact
with captured_output() as (out, err):
superftp._display_full(ftp, blockmap, '\remote\test', (24, 80))
s = err.getvalue()
self.assertEqual(s, '')
s = out.getvalue()
truth = (
'\x1b[1;0H\x1b[37mETA:infinite 3.2% 0.000MB/sec \remote\test\x1b[K\x1b[2;0H\x1b[K\x1b[3;0H'
+
'\x1b[37m[0.000][0.000][0.000][0.000]\x1b[K\n[0.000][0.000][0.000][0.000]\x1b[K\n[0.000][0.000]'
+
'[0.000][0.000]\x1b[K\n[0.000][0.000][0.000][0.000]\x1b[K\n\x1b[7;0H\x1b[K\x1b[8;0H\x1b[37m..\x1b'
+
'[92m**\x1b[37m....................\x1b[93m001234__789ABCDEF23456789ABCDEF\x1b[37m.......\x1b[K\r\n'
+
'\x1b[K\r\n\x1b[K\r\n\x1b[K\r\n\x1b[K\r\n\x1b[K\r\n\x1b[K\r\n\x1b[K\r\n\x1b[K\r\n\x1b[K\r\n\x1b[K\r'
+ '\n\x1b[K\r\n\x1b[K\r\n\x1b[K\r\n\x1b[K\r\n\x1b[J')
self.assertEqual(s, truth)
def test_benchmark_has_no_significant_setup_overhead(self):
with captured_output() as (out, _):
doctor = BenchmarkDoctor(self.args, BenchmarkDriverMock([]))
doctor.analyze({
'name': 'NoOverhead', # not 'significant' enough
# Based on DropFirstArray a10/e10: overhead 3.7% (6 μs)
'NoOverhead O i1a': _PTR(min=162),
'NoOverhead O i2a': _PTR(min=159)
})
doctor.analyze({
'name': 'SO', # Setup Overhead
# Based on SuffixArrayLazy a10/e10: overhead 5.8% (4 μs)
'SO O i1a': _PTR(min=69),
'SO O i1b': _PTR(min=70),
'SO O i2a': _PTR(min=67),
'SO O i2b': _PTR(min=68)
})
doctor.analyze({
'name': 'Zero',
'Zero O i1a': _PTR(min=0),
'Zero O i2a': _PTR(min=0)
})
doctor.analyze({
'name': 'LOA', # Limit of Accuracy
# Impossible to detect overhead:
# Even 1μs change in 20μs runtime is 5%.
'LOA O i1a': _PTR(min=21),
'LOA O i2a': _PTR(min=20)
})
output = out.getvalue()
self.assertIn('runtime: ', output)
self.assertNotIn('NoOverhead', output)
self.assertNotIn('ZeroRuntime', output)
self.assertNotIn('LOA', output)
self.assert_contains(["'SO' has setup overhead of 4 μs (5.8%)."],
self.logs['error'])
self.assert_contains([
"Move initialization of benchmark data to the `setUpFunction` "
"registered in `BenchmarkInfo`."
], self.logs['info'])
def test_benchmark_runtime_range(self):
"""Optimized benchmark should run in less then 2500 μs.
With runtimes less than 2500 μs there is better than 1:4 chance of
being interrupted in the middle of measurement due to elapsed 10 ms
quantum used by macos scheduler.
Warn about longer runtime. Runtimes over half a second are an error.
"""
def measurements(name, runtime):
return {'name': name,
name + ' O i1a': _PTR(min=runtime + 2),
name + ' O i2a': _PTR(min=runtime)}
with captured_output() as (out, _):
doctor = BenchmarkDoctor(self.args, BenchmarkDriverMock([]))
doctor.analyze(measurements('Cheetah', 200))
doctor.analyze(measurements('Hare', 2501))
doctor.analyze(measurements('Tortoise', 500000))
doctor.analyze({'name': 'OverheadTurtle',
'OverheadTurtle O i1a': _PTR(min=800000),
'OverheadTurtle O i2a': _PTR(min=700000)})
output = out.getvalue()
self.assertIn('runtime: ', output)
self.assertNotIn('Cheetah', output)
self.assert_contains(["'Hare' execution took at least 2501 μs."],
self.logs['warning'])
self.assert_contains(
["Decrease the workload of 'Hare' by a factor of 2, "
"to be less than 2500 μs."], self.logs['info'])
self.assert_contains(
["'Tortoise' execution took at least 500000 μs."],
self.logs['error'])
self.assert_contains(
["Decrease the workload of 'Tortoise' by a factor of 256, "
"to be less than 2500 μs."], self.logs['info'])
self.assert_contains(
["'OverheadTurtle' execution took at least 600000 μs"
" (excluding the setup overhead)."],
self.logs['error'])
def test_benchmark_setup_takes_reasonable_time(self):
"""Setup < 200 ms (20% extra on top of the typical 1 s measurement)"""
with captured_output() as (out, _):
doctor = BenchmarkDoctor(self.args, BenchmarkDriverMock([]))
doctor.analyze({
'name': 'NormalSetup',
'NormalSetup O i1a': _PTR(setup=199999),
'NormalSetup O i2a': _PTR(setup=200001)})
doctor.analyze({
'name': 'LongSetup',
'LongSetup O i1a': _PTR(setup=200001),
'LongSetup O i2a': _PTR(setup=200002)})
output = out.getvalue()
self.assertIn('runtime: ', output)
self.assertNotIn('NormalSetup', output)
self.assert_contains(
["'LongSetup' setup took at least 200001 μs."],
self.logs['error'])
self.assert_contains(
["The `setUpFunction` should take no more than 200 ms."],
self.logs['info'])
def test_benchmark_setup_takes_reasonable_time(self):
"""Setup < 200 ms (20% extra on top of the typical 1 s measurement)"""
with captured_output() as (out, _):
doctor = BenchmarkDoctor(self.args, BenchmarkDriverMock([]))
doctor.analyze({
'name': 'NormalSetup',
'NormalSetup O i1a': _PTR(setup=199999),
'NormalSetup O i2a': _PTR(setup=200001)})
doctor.analyze({
'name': 'LongSetup',
'LongSetup O i1a': _PTR(setup=200001),
'LongSetup O i2a': _PTR(setup=200002)})
output = out.getvalue()
self.assertIn('runtime: ', output)
self.assertNotIn('NormalSetup', output)
self.assert_contains(
["'LongSetup' setup took at least 200001 μs."],
self.logs['error'])
self.assert_contains(
["The `setUpFunction` should take no more than 200 ms."],
self.logs['info'])
def execute_main_with_format(self, report_format, test_output=False):
report_file = self.test_dir + 'report.log'
args = ['compare_perf_tests.py',
'--old-file', self.old_log,
'--new-file', self.new_log,
'--format', report_format]
sys.argv = (args if not test_output else
args + ['--output', report_file])
with captured_output() as (out, _):
main()
report_out = out.getvalue()
if test_output:
with open(report_file, 'r') as f:
report = f.read()
# because print adds newline, add one here, too:
report_file = str(report + '\n')
else:
report_file = None
return report_out, report_file
def execute_main_with_format(self, report_format, test_output=False):
report_file = self.test_dir + 'report.log'
args = [
'compare_perf_tests.py', '--old-file', self.old_log, '--new-file',
self.new_log, '--format', report_format
]
sys.argv = (args if not test_output else args +
['--output', report_file])
with captured_output() as (out, _):
main()
report_out = out.getvalue()
if test_output:
with open(report_file, 'r') as f:
report = f.read()
# because print adds newline, add one here, too:
report_file = str(report + '\n')
else:
report_file = None
return report_out, report_file
def test_supports_verbose_output(self):
driver = BenchmarkDriverMock(tests=['B1', 'B2'])
driver.verbose = True
with captured_output() as (out, _):
BenchmarkDoctor(Stub(verbose=True), driver)
self.assert_contains(['Checking tests: B1, B2'], out.getvalue())
def test_uses_logging(self):
driver = BenchmarkDriverMock(tests=['B1', 'B2'])
with captured_output() as (out, _):
BenchmarkDoctor(self.args, driver)
self.assert_contains(['Checking tests: B1, B2'], self.logs['debug'])
self.assertEquals(out.getvalue(), '')
def test_command_help_lists_commands(self):
with captured_output() as (out, _):
self.assertRaises(SystemExit, parse_args, ['-h'])
self.assert_contains(['COMMAND', 'run', 'compare', 'check'],
out.getvalue())
def test_requires_command_argument(self):
with captured_output() as (_, err):
self.assertRaises(SystemExit, parse_args, [])
self.assert_contains(['usage:', 'COMMAND', 'too few arguments'],
err.getvalue())
def test_uses_logging(self):
driver = BenchmarkDriverMock(tests=['B1', 'B2'])
with captured_output() as (out, _):
BenchmarkDoctor(self.args, driver)
self.assert_contains(['Checking tests: B1, B2'], self.logs['debug'])
self.assertEquals(out.getvalue(), '')
def test_command_help_lists_commands(self):
with captured_output() as (out, _):
self.assertRaises(SystemExit, parse_args, ['-h'])
self.assert_contains(['COMMAND', 'run', 'compare', 'check'],
out.getvalue())
def test_requires_command_argument(self):
with captured_output() as (_, err):
self.assertRaises(SystemExit, parse_args, [])
self.assert_contains(['usage:', 'COMMAND', 'too few arguments'],
err.getvalue())
def test_benchmark_has_constant_memory_use(self):
"""Benchmark's memory footprint must not vary with num-iters."""
with captured_output() as (out, _):
doctor = BenchmarkDoctor(self.args, BenchmarkDriverMock([]))
doctor.analyze({
# The threshold of 15 pages was estimated from previous
# measurements. The normal range should be probably aproximated
# by a function instead of a simple constant.
# TODO: re-evaluate normal range from whole SBS
"name": "ConstantMemory",
"ConstantMemory O i1a": _PTR(mem_pages=1460),
"ConstantMemory O i2a": _PTR(mem_pages=(1460 + 15)),
})
doctor.analyze({
"name": "VariableMemory", # ObserverForwardStruct
"VariableMemory O i1a": _PTR(mem_pages=1460),
"VariableMemory O i1b": _PTR(mem_pages=1472),
# i2 series start at 290 pages higher
"VariableMemory O i2a": _PTR(mem_pages=1750),
"VariableMemory O i2b": _PTR(mem_pages=1752),
})
measurements = dict([(
"HighVariance O i{0}{1}".format(num_iters, suffix),
_PTR(mem_pages=num_pages),
) for num_iters, pages in [
(1, [6200, 5943, 4818, 5612, 5469]),
(2, [6244, 5832, 4674, 5176, 5490]),
] for num_pages, suffix in zip(pages, list("abcde"))])
measurements["name"] = "HighVariance" # Array2D
doctor.analyze(measurements)
output = out.getvalue()
self.assertIn("memory: ", output)
self.assertNotIn("ConstantMemory", output)
self.assert_contains(
[
"'VariableMemory' varies the memory footprint of the base "
"workload depending on the `num-iters`."
],
self.logs["error"],
)
self.assert_contains(
[
"'VariableMemory' "
"mem_pages [i1, i2]: min=[1460, 1750] 𝚫=290 R=[12, 2]"
],
self.logs["info"],
)
self.assert_contains(
[
"'HighVariance' has very wide range of memory used between "
"independent, repeated measurements."
],
self.logs["warning"],
)
self.assert_contains(
[
"'HighVariance' "
"mem_pages [i1, i2]: min=[4818, 4674] 𝚫=144 R=[1382, 1570]"
],
self.logs["info"],
)
def test_uses_logging(self):
driver = BenchmarkDriverMock(tests=["B1", "B2"])
with captured_output() as (out, _):
BenchmarkDoctor(self.args, driver)
self.assert_contains(["Checking tests: B1, B2"], self.logs["debug"])
self.assertEqual(out.getvalue(), "")
def test_benchmark_runtime_range(self):
"""Optimized benchmark should have runtime between 20 μs and 1000 μs.
Even on calm machine, benchmark with runtime of 2500 μs has 1:4 chance
of being interrupted in the middle of measurement due to elapsed 10 ms
quantum used by macos scheduler. Linux scheduler's quantum is 6ms.
Driver yielding the process before the 10ms quantum elapses helped
a lot, but benchmarks with runtimes under 1ms usually exhibit a strong
mode which is best for accurate performance charaterization.
To minimize the number of involuntary context switches that corrupt our
measurements, we should strive to stay in the microbenchmark range.
Warn about longer runtime. Runtimes over 10ms are an error.
"""
def measurements(name, runtime):
return {
"name": name,
name + " O i1a": _PTR(min=runtime + 2),
name + " O i2a": _PTR(min=runtime),
}
with captured_output() as (out, _):
doctor = BenchmarkDoctor(self.args, BenchmarkDriverMock([]))
doctor.analyze(measurements("Sylph", 0))
doctor.analyze(measurements("Unicorn", 3))
doctor.analyze(measurements("Cheetah", 200))
doctor.analyze(measurements("Hare", 1001))
doctor.analyze(measurements("Tortoise", 500000))
doctor.analyze({
"name": "OverheadTurtle",
"OverheadTurtle O i1a": _PTR(min=800000),
"OverheadTurtle O i2a": _PTR(min=700000),
})
output = out.getvalue()
self.assertIn("runtime: ", output)
self.assertNotIn("Cheetah", output)
self.assert_contains(["'Sylph' execution took 0 μs."],
self.logs["error"])
self.assert_contains(
[
"Ensure the workload of 'Sylph' has a properly measurable size"
" (runtime > 20 μs) and is not eliminated by the compiler (use "
"`blackHole` function if necessary)."
],
self.logs["info"],
)
self.assert_contains(["'Unicorn' execution took 3 μs."],
self.logs["warning"])
self.assert_contains(
["Increase the workload of 'Unicorn' to be more than 20 μs."],
self.logs["info"],
)
self.assert_contains(["'Hare' execution took at least 1001 μs."],
self.logs["warning"])
self.assert_contains(
[
"Decrease the workload of 'Hare' by a factor of 2 (10), "
"to be less than 1000 μs."
],
self.logs["info"],
)
self.assert_contains(["'Tortoise' execution took at least 500000 μs."],
self.logs["error"])
self.assert_contains(
[
"Decrease the workload of 'Tortoise' by a factor of 512 (1000), "
"to be less than 1000 μs."
],
self.logs["info"],
)
self.assert_contains(
[
"'OverheadTurtle' execution took at least 600000 μs"
" (excluding the setup overhead)."
],
self.logs["error"],
)
def test_command_help_lists_commands(self):
with captured_output() as (out, _):
self.assertRaises(SystemExit, parse_args, ["-h"])
self.assert_contains(["COMMAND", "run", "compare", "check"],
out.getvalue())