From 7efd6e763b0380758360734f00eed045d468bd97 Mon Sep 17 00:00:00 2001 From: Tobias Pfeiffer Date: Thu, 10 May 2018 14:01:02 +0200 Subject: [PATCH 1/9] Basics to get nanosecond measurements going * native time measurer for determining n_times * added nano second unit, unit tests pass there PICK ME UP: * Integration tests failing * running fast_functions seems to break as well --- lib/benchee/benchmark/measure/native_time.ex | 18 ++++ lib/benchee/benchmark/measure/time.ex | 16 +++- lib/benchee/benchmark/runner.ex | 2 +- lib/benchee/conversion/duration.ex | 90 +++++++++++--------- test/benchee/conversion/duration_test.exs | 48 +++++------ 5 files changed, 108 insertions(+), 66 deletions(-) create mode 100644 lib/benchee/benchmark/measure/native_time.ex diff --git a/lib/benchee/benchmark/measure/native_time.ex b/lib/benchee/benchmark/measure/native_time.ex new file mode 100644 index 00000000..0d3ec8f4 --- /dev/null +++ b/lib/benchee/benchmark/measure/native_time.ex @@ -0,0 +1,18 @@ +defmodule Benchee.Benchmark.Measure.NativeTime do + @moduledoc """ + Measure the time elapsed while executing a given function. + + Uses only the time unit native to the platform. Used for determining how many times a function + should be repeated in `Benchee.Benchmark.Runner.determine_n_times/3` (private method though). + """ + + @behaviour Benchee.Benchmark.Measure + + def measure(function) do + start = :erlang.monotonic_time() + result = function.() + finish = :erlang.monotonic_time() + + {finish - start, result} + end +end diff --git a/lib/benchee/benchmark/measure/time.ex b/lib/benchee/benchmark/measure/time.ex index 2623caf8..e17838c9 100644 --- a/lib/benchee/benchmark/measure/time.ex +++ b/lib/benchee/benchmark/measure/time.ex @@ -1,11 +1,23 @@ defmodule Benchee.Benchmark.Measure.Time do @moduledoc """ - Measure the time consumed by a executing function. + Measure the time elapsed while executing a given function. + + In contrast to `:timer.tc/1` it always returns the result in nano seconds instead of micro + seconds. This helps us avoid losing precision as both Linux and MacOSX seem to be able to + measure in nano seconds. `:timer.tc/n` + [forfeits this precision]( + https://github.com/erlang/otp/blob/master/lib/stdlib/src/timer.erl#L164-L169). """ @behaviour Benchee.Benchmark.Measure def measure(function) do - :timer.tc(function) + start = :erlang.monotonic_time() + result = function.() + finish = :erlang.monotonic_time() + + duration_nano_seconds = :erlang.convert_time_unit(finish - start, :native, :nanosecond) + + {duration_nano_seconds, result} end end diff --git a/lib/benchee/benchmark/runner.ex b/lib/benchee/benchmark/runner.ex index 3b1c0ef8..fb1d74fd 100644 --- a/lib/benchee/benchmark/runner.ex +++ b/lib/benchee/benchmark/runner.ex @@ -187,7 +187,7 @@ defmodule Benchee.Benchmark.Runner do }, fast_warning ) do - run_time = measure_iteration(scenario, scenario_context, Measure.Time) + run_time = measure_iteration(scenario, scenario_context, Measure.NativeTime) if run_time >= @minimum_execution_time do {num_iterations, adjust_for_iterations(run_time, num_iterations)} diff --git a/lib/benchee/conversion/duration.ex b/lib/benchee/conversion/duration.ex index 23c6274f..c029f178 100644 --- a/lib/benchee/conversion/duration.ex +++ b/lib/benchee/conversion/duration.ex @@ -8,50 +8,59 @@ defmodule Benchee.Conversion.Duration do @behaviour Scale @behaviour Format + @nanoseconds_per_microsecond 1000 @microseconds_per_millisecond 1000 @milliseconds_per_second 1000 @seconds_per_minute 60 @minutes_per_hour 60 - @microseconds_per_second @microseconds_per_millisecond * + + @nanoseconds_per_millisecond @nanoseconds_per_microsecond * @microseconds_per_millisecond + @nanoseconds_per_second @nanoseconds_per_millisecond * @milliseconds_per_second - @microseconds_per_minute @microseconds_per_second * @seconds_per_minute - @microseconds_per_hour @microseconds_per_minute * @minutes_per_hour + @nanoseconds_per_minute @nanoseconds_per_second * @seconds_per_minute + @nanoseconds_per_hour @nanoseconds_per_minute * @minutes_per_hour @units %{ hour: %Unit{ name: :hour, - magnitude: @microseconds_per_hour, + magnitude: @nanoseconds_per_hour, label: "h", long: "Hours" }, minute: %Unit{ name: :minute, - magnitude: @microseconds_per_minute, + magnitude: @nanoseconds_per_minute, label: "min", long: "Minutes" }, second: %Unit{ name: :second, - magnitude: @microseconds_per_second, + magnitude: @nanoseconds_per_second, label: "s", long: "Seconds" }, millisecond: %Unit{ name: :millisecond, - magnitude: @microseconds_per_millisecond, + magnitude: @nanoseconds_per_millisecond, label: "ms", long: "Milliseconds" }, microsecond: %Unit{ name: :microsecond, - magnitude: 1, + magnitude: @nanoseconds_per_microsecond, label: "μs", long: "Microseconds" + }, + nanosecond: %Unit{ + name: :nanosecond, + magnitude: 1, + label: "ns", + long: "Nanoseconds" } } @doc """ - Scales a duration value in microseconds into a larger unit if appropriate + Scales a duration value in nanoseconds into a larger unit if appropriate ## Examples @@ -59,35 +68,38 @@ defmodule Benchee.Conversion.Duration do iex> value 1.0 iex> unit.name - :microsecond + :nanosecond iex> {value, unit} = Benchee.Conversion.Duration.scale(1_234) iex> value 1.234 iex> unit.name - :millisecond + :microsecond - iex> {value, unit} = Benchee.Conversion.Duration.scale(11_234_567_890.123) + iex> {value, unit} = Benchee.Conversion.Duration.scale(11_234_567_890_123) iex> value 3.1207133028119443 iex> unit.name :hour """ - def scale(duration) when duration >= @microseconds_per_hour do + def scale(duration) when duration >= @nanoseconds_per_hour do scale_with_unit duration, :hour end - def scale(duration) when duration >= @microseconds_per_minute do + def scale(duration) when duration >= @nanoseconds_per_minute do scale_with_unit duration, :minute end - def scale(duration) when duration >= @microseconds_per_second do + def scale(duration) when duration >= @nanoseconds_per_second do scale_with_unit duration, :second end - def scale(duration) when duration >= @microseconds_per_millisecond do + def scale(duration) when duration >= @nanoseconds_per_millisecond do scale_with_unit duration, :millisecond end - def scale(duration) do + def scale(duration) when duration >= @nanoseconds_per_microsecond do scale_with_unit duration, :microsecond end + def scale(duration) do + scale_with_unit duration, :nanosecond + end # Helper function for returning a tuple of {value, unit} defp scale_with_unit(duration, unit) do @@ -103,20 +115,20 @@ defmodule Benchee.Conversion.Duration do iex> Benchee.Conversion.Duration.unit_for :hour %Benchee.Conversion.Unit{ name: :hour, - magnitude: 3_600_000_000, + magnitude: 3_600_000_000_000, label: "h", long: "Hours" } iex> Benchee.Conversion.Duration.unit_for(%Benchee.Conversion.Unit{ ...> name: :hour, - ...> magnitude: 3_600_000_000, + ...> magnitude: 3_600_000_000_000, ...> label: "h", ...> long: "Hours" ...>}) %Benchee.Conversion.Unit{ name: :hour, - magnitude: 3_600_000_000, + magnitude: 3_600_000_000_000, label: "h", long: "Hours" } @@ -126,18 +138,18 @@ defmodule Benchee.Conversion.Duration do end @doc """ - Scales a duration value in microseconds into a value in the specified unit + Scales a duration value in nanoseconds into a value in the specified unit ## Examples - iex> Benchee.Conversion.Duration.scale(12345, :microsecond) + iex> Benchee.Conversion.Duration.scale(12345, :nanosecond) 12345.0 - iex> Benchee.Conversion.Duration.scale(12345, :millisecond) + iex> Benchee.Conversion.Duration.scale(12345, :microsecond) 12.345 iex> Benchee.Conversion.Duration.scale(12345, :minute) - 2.0575e-4 + 2.0575e-7 """ def scale(count, unit) do @@ -170,15 +182,15 @@ defmodule Benchee.Conversion.Duration do iex> Benchee.Conversion.Duration.microseconds({1.234, :minute}) 7.404e7 - iex> Benchee.Conversion.Duration.microseconds({1.234, :minute}) |> Benchee.Conversion.Duration.scale(:minute) + iex> microseconds = Benchee.Conversion.Duration.microseconds({1.234, :minute}) + iex> {value, _} = Benchee.Conversion.Duration.convert({microseconds, :microsecond}, :minute) + iex> value 1.234 """ - def microseconds({duration, %Unit{magnitude: magnitude}}) do - duration * magnitude - end - def microseconds({duration, unit_atom}) do - microseconds {duration, unit_for(unit_atom)} + def microseconds({duration, unit}) do + {microseconds, _} = convert({duration, unit}, :microsecond) + microseconds end @doc """ @@ -191,15 +203,15 @@ defmodule Benchee.Conversion.Duration do ## Examples iex> Benchee.Conversion.Duration.best([23, 23_000, 34_000, 2_340_000]).name - :millisecond + :microsecond - iex> Benchee.Conversion.Duration.best([23, 23_000, 34_000, 2_340_000, 3_450_000]).name + iex> Benchee.Conversion.Duration.best([23, 23_000, 34_000_000, 2_340_000_000, 3_450_000_000]).name :second iex> Benchee.Conversion.Duration.best([23, 23_000, 34_000, 2_340_000], strategy: :smallest).name - :microsecond + :nanosecond - iex> Benchee.Conversion.Duration.best([23, 23_000, 34_000, 2_340_000], strategy: :largest).name + iex> Benchee.Conversion.Duration.best([23, 23_000, 34_000, 2_340_000_000], strategy: :largest).name :second """ def best(list, opts \\ [strategy: :best]) @@ -208,15 +220,15 @@ defmodule Benchee.Conversion.Duration do end @doc """ - The most basic unit in which measurements occur, microseconds. + The most basic unit in which measurements occur. ## Examples iex> Benchee.Conversion.Duration.base_unit.name - :microsecond + :nanosecond """ - def base_unit, do: unit_for(:microsecond) + def base_unit, do: unit_for(:nanosecond) @doc """ Formats a number as a string, with a unit label. To specify the unit, pass @@ -225,10 +237,10 @@ defmodule Benchee.Conversion.Duration do ## Examples iex> Benchee.Conversion.Duration.format(45_678.9) - "45.68 ms" + "45.68 μs" iex> Benchee.Conversion.Duration.format(45.6789) - "45.68 μs" + "45.68 ns" iex> Benchee.Conversion.Duration.format({45.6789, :millisecond}) "45.68 ms" diff --git a/test/benchee/conversion/duration_test.exs b/test/benchee/conversion/duration_test.exs index 527c8e0c..eba7c7f6 100644 --- a/test/benchee/conversion/duration_test.exs +++ b/test/benchee/conversion/duration_test.exs @@ -5,67 +5,67 @@ defmodule Benchee.Conversion.DurationTest do describe ".format" do test ".format(98.7654321)" do - assert format(98.7654321) == "98.77 μs" + assert format(98.7654321) == "98.77 ns" end test ".format(987.654321)" do - assert format(987.654321) == "987.65 μs" + assert format(987.654321) == "987.65 ns" end test ".format(9_876.54321)" do - assert format(9_876.54321) == "9.88 ms" + assert format(9_876.54321) == "9.88 μs" end test ".format(98_765.4321)" do - assert format(98_765.4321) == "98.77 ms" + assert format(98_765.4321) == "98.77 μs" end test ".format(987_654.321)" do - assert format(987_654.321) == "987.65 ms" + assert format(987_654.321) == "987.65 μs" end - test ".format(9_876_543.21)" do - assert format(9_876_543.21) == "9.88 s" + test ".format(9_876_543210)" do + assert format(9_876_543210) == "9.88 s" end - test ".format(98_765_432.19)" do - assert format(98_765_432.19) == "1.65 min" + test ".format(98_765_432190)" do + assert format(98_765_432190) == "1.65 min" end - test ".format(987_654_321.9876)" do - assert format(987_654_321.9876) == "16.46 min" + test ".format(987_654_321987.6)" do + assert format(987_654_321987.6) == "16.46 min" end - test ".format(9_876_543_219.8765)" do - assert format(9_876_543_219.8765) == "2.74 h" + test ".format(9_876_543_219876.5)" do + assert format(9_876_543_219876.5) == "2.74 h" end test ".format(523.0)" do - assert format(523.0) == "523 μs" + assert format(523.0) == "523 ns" end test ".format(0)" do - assert format(0) == "0 μs" + assert format(0) == "0 ns" end end - @list_with_mostly_milliseconds [1, 200, 3_000, 4_000, 500_000, 6_000_000, 77_000_000_000] + @list_with_mostly_microseconds [1, 200, 3_000, 4_000, 500_000, 6_000_000, 7_777_000_000_000] describe ".best" do - test "when list is mostly milliseconds" do - assert best(@list_with_mostly_milliseconds) == unit_for(:millisecond) + test "when list is mostly microseconds" do + assert best(@list_with_mostly_microseconds) == unit_for(:microsecond) end - test "when list is mostly milliseconds, strategy: :smallest" do - assert best(@list_with_mostly_milliseconds, strategy: :smallest) == unit_for(:microsecond) + test "when list is mostly microseconds, strategy: :smallest" do + assert best(@list_with_mostly_microseconds, strategy: :smallest) == unit_for(:nanosecond) end - test "when list is mostly milliseconds, strategy: :largest" do - assert best(@list_with_mostly_milliseconds, strategy: :largest) == unit_for(:hour) + test "when list is mostly microseconds, strategy: :largest" do + assert best(@list_with_mostly_microseconds, strategy: :largest) == unit_for(:hour) end - test "when list is mostly milliseconds, strategy: :none" do - assert best(@list_with_mostly_milliseconds, strategy: :none) == unit_for(:microsecond) + test "when list is mostly microseconds, strategy: :none" do + assert best(@list_with_mostly_microseconds, strategy: :none) == unit_for(:nanosecond) end end end From bebdeb21b433a60f3f18a22c83b038b1f77426cb Mon Sep 17 00:00:00 2001 From: Tobias Pfeiffer Date: Thu, 10 May 2018 19:30:51 +0200 Subject: [PATCH 2/9] And we are green with nano second level measurements --- lib/benchee/benchmark/runner.ex | 4 +- lib/benchee/configuration.ex | 12 ++--- lib/benchee/conversion.ex | 12 ++--- lib/benchee/formatters/console.ex | 4 +- lib/benchee/formatters/console/run_time.ex | 8 +-- lib/benchee/output/benchmark_printer.ex | 2 +- samples/fast_functions.exs | 2 +- test/benchee/benchmark/runner_test.exs | 54 ++++++------------- test/benchee/conversion/duration_test.exs | 8 +-- .../formatters/console/run_time_test.exs | 16 +++--- .../benchee/output/benchmark_printer_test.exs | 24 +++++---- test/benchee_test.exs | 10 +++- test/test_helper.exs | 8 ++- 13 files changed, 79 insertions(+), 85 deletions(-) diff --git a/lib/benchee/benchmark/runner.ex b/lib/benchee/benchmark/runner.ex index fb1d74fd..122644a1 100644 --- a/lib/benchee/benchmark/runner.ex +++ b/lib/benchee/benchmark/runner.ex @@ -116,7 +116,7 @@ defmodule Benchee.Benchmark.Runner do measure_runtimes(scenario, scenario_context, run_time, fast_warning) end - defp run_memory_benchmark(_, %ScenarioContext{config: %{memory_time: 0}}) do + defp run_memory_benchmark(_, %ScenarioContext{config: %{memory_time: 0.0}}) do [] end defp run_memory_benchmark( @@ -153,7 +153,7 @@ defmodule Benchee.Benchmark.Runner do end defp measure_runtimes(scenario, context, run_time, fast_warning) - defp measure_runtimes(_, _, 0, _), do: [] + defp measure_runtimes(_, _, 0.0, _), do: [] defp measure_runtimes(scenario, scenario_context, run_time, fast_warning) do end_time = current_time() + run_time diff --git a/lib/benchee/configuration.ex b/lib/benchee/configuration.ex index 1d6b8e08..bcf55539 100644 --- a/lib/benchee/configuration.ex +++ b/lib/benchee/configuration.ex @@ -15,7 +15,7 @@ defmodule Benchee.Configuration do defstruct parallel: 1, time: 5, warmup: 2, - memory_time: 0, + memory_time: 0.0, pre_check: false, formatters: [Console], print: %{ @@ -150,8 +150,8 @@ defmodule Benchee.Configuration do configuration: %Benchee.Configuration{ parallel: 1, - time: 5_000_000, - warmup: 2_000_000, + time: 5_000_000.0, + warmup: 2_000_000.0, inputs: nil, save: false, load: false, @@ -180,7 +180,7 @@ defmodule Benchee.Configuration do configuration: %Benchee.Configuration{ parallel: 1, - time: 1_000_000, + time: 1_000_000.0, warmup: 200_000.0, inputs: nil, save: false, @@ -210,7 +210,7 @@ defmodule Benchee.Configuration do configuration: %Benchee.Configuration{ parallel: 1, - time: 1_000_000, + time: 1_000_000.0, warmup: 200_000.0, inputs: nil, save: false, @@ -249,7 +249,7 @@ defmodule Benchee.Configuration do configuration: %Benchee.Configuration{ parallel: 2, - time: 1_000_000, + time: 1_000_000.0, warmup: 200_000.0, inputs: %{"Small" => 5, "Big" => 9999}, save: false, diff --git a/lib/benchee/conversion.ex b/lib/benchee/conversion.ex index 9737ed15..b91d8c12 100644 --- a/lib/benchee/conversion.ex +++ b/lib/benchee/conversion.ex @@ -18,7 +18,7 @@ defmodule Benchee.Conversion do ## Examples - iex> statistics = %Benchee.Statistics{average: 1000.0, ips: 1000.0} + iex> statistics = %Benchee.Statistics{average: 1_000_000.0, ips: 1000.0} iex> scenario = %Benchee.Benchmark.Scenario{ ...> run_time_statistics: statistics, ...> memory_usage_statistics: statistics @@ -34,14 +34,14 @@ defmodule Benchee.Conversion do run_time: %Benchee.Conversion.Unit{ label: "ms", long: "Milliseconds", - magnitude: 1000, + magnitude: 1_000_000, name: :millisecond }, memory: %Benchee.Conversion.Unit{ - label: "B", - long: "Bytes", - magnitude: 1, - name: :byte + label: "KB", + long: "Kilobytes", + magnitude: 1024, + name: :kilobyte } } """ diff --git a/lib/benchee/formatters/console.ex b/lib/benchee/formatters/console.ex index 63dafdfe..23bb05ec 100644 --- a/lib/benchee/formatters/console.ex +++ b/lib/benchee/formatters/console.ex @@ -54,8 +54,8 @@ defmodule Benchee.Formatters.Console do ...> } iex> Benchee.Formatters.Console.format(suite) [["\n##### With input My input #####", "\nName ips average deviation median 99th %\n", - "My Job 5 K 200 μs ±10.00% 190 μs 300.10 μs\n", - "Job 2 2.50 K 400 μs ±20.00% 390 μs 500.10 μs\n"]] + "My Job 5 K 200 ns ±10.00% 190 ns 300.10 ns\n", + "Job 2 2.50 K 400 ns ±20.00% 390 ns 500.10 ns\n"]] ``` diff --git a/lib/benchee/formatters/console/run_time.ex b/lib/benchee/formatters/console/run_time.ex index 0c18e18e..d83781f2 100644 --- a/lib/benchee/formatters/console/run_time.ex +++ b/lib/benchee/formatters/console/run_time.ex @@ -49,12 +49,12 @@ defmodule Benchee.Formatters.Console.RunTime do iex> configuration = %{comparison: false, unit_scaling: :best, extended_statistics: true} iex> Benchee.Formatters.Console.RunTime.format_scenarios(scenarios, configuration) ["\nName ips average deviation median 99th %\n", - "My Job 5 K 200 μs ±10.00% 190 μs 300.10 μs\n", - "Job 2 2.50 K 400 μs ±20.00% 390 μs 500.10 μs\n", + "My Job 5 K 200 ns ±10.00% 190 ns 300.10 ns\n", + "Job 2 2.50 K 400 ns ±20.00% 390 ns 500.10 ns\n", "\nExtended statistics: \n", "\nName minimum maximum sample size mode\n", - "My Job 100.10 μs 200.20 μs 10.10 K 333.20 μs\n", - "Job 2 200.20 μs 400.40 μs 20.20 K 612.30 μs, 554.10 μs\n"] + "My Job 100.10 ns 200.20 ns 10.10 K 333.20 ns\n", + "Job 2 200.20 ns 400.40 ns 20.20 K 612.30 ns, 554.10 ns\n"] ``` diff --git a/lib/benchee/output/benchmark_printer.ex b/lib/benchee/output/benchmark_printer.ex index de0caeda..068dbe93 100644 --- a/lib/benchee/output/benchmark_printer.ex +++ b/lib/benchee/output/benchmark_printer.ex @@ -80,7 +80,7 @@ defmodule Benchee.Output.BenchmarkPrinter do Prints a notice which job is currently being benchmarked. """ def benchmarking(_, _, %{print: %{benchmarking: false}}), do: nil - def benchmarking(_, _, %{time: 0, warmup: 0, memory_time: 0}), do: nil + def benchmarking(_, _, %{time: 0.0, warmup: 0.0, memory_time: 0.0}), do: nil def benchmarking(name, input_name, _config) do IO.puts("Benchmarking #{name}#{input_information(input_name)}...") diff --git a/samples/fast_functions.exs b/samples/fast_functions.exs index a355e50a..cc268c03 100644 --- a/samples/fast_functions.exs +++ b/samples/fast_functions.exs @@ -10,7 +10,7 @@ Benchee.run(%{ "++ array concat" => fn -> [1] ++ [1] end, "noop" => fn -> 0 end, "Enum.map(10)" => fn -> Enum.map(range, fn(i) -> i end) end -}, time: 3) +}, time: 1, warmup: 1) # # Before adding running fast functions multiple times, these where just too diff --git a/test/benchee/benchmark/runner_test.exs b/test/benchee/benchmark/runner_test.exs index dd356a17..d8f578eb 100644 --- a/test/benchee/benchmark/runner_test.exs +++ b/test/benchee/benchmark/runner_test.exs @@ -2,7 +2,7 @@ defmodule Benchee.Benchmark.RunnerTest do use ExUnit.Case, async: true import Benchee.TestHelpers import ExUnit.CaptureIO - alias Benchee.{Suite, Benchmark, Configuration, Statistics} + alias Benchee.{Suite, Benchmark, Configuration} alias Benchee.Benchmark.Scenario alias Benchee.Test.FakeBenchmarkPrinter, as: TestPrinter @@ -120,7 +120,7 @@ defmodule Benchee.Benchmark.RunnerTest do @tag :memory_measure test "records memory when the function only runs once" do suite = - test_suite(%Suite{configuration: %{time: 0, warmup: 0, memory_time: 1_000}}) + test_suite(%Suite{configuration: %{time: 0.0, warmup: 0.0, memory_time: 1_000}}) new_suite = suite @@ -152,6 +152,8 @@ defmodule Benchee.Benchmark.RunnerTest do assert memory_consumption <= 1_000 end + # not fast enough to get fast warnings on nano second accuracy + @tag :needs_fast_function_repetition test "very fast functions print a warning" do output = capture_io(fn -> @@ -176,8 +178,7 @@ defmodule Benchee.Benchmark.RunnerTest do [%{run_time_statistics: %{average: average}}] = suite.scenarios - # They are repeated but times are scaled down for the repetition again - assert average < 10 + assert average < 200 # around ~78 on my machine end @tag :performance @@ -204,32 +205,10 @@ defmodule Benchee.Benchmark.RunnerTest do end) end - test "variance does not skyrocket on very fast functions" do - retrying(fn -> - range = 0..10 - - suite = - %Suite{configuration: %{time: 150_000, warmup: 20_000}} - |> test_suite - |> Benchmark.benchmark("noop", fn -> 1 + 1 end) - |> Benchmark.benchmark("map", fn -> - Enum.map(range, fn i -> i end) - end) - |> Benchmark.measure(TestPrinter) - |> Statistics.statistics() - - stats = Enum.map(suite.scenarios, fn scenario -> scenario.run_time_statistics end) - - Enum.each(stats, fn %Statistics{std_dev_ratio: std_dev_ratio} -> - assert std_dev_ratio <= 2.5 - end) - end) - end - test "never calls the function if warmup and time are 0" do ref = self() - %Suite{configuration: %{time: 0, warmup: 0}} + %Suite{configuration: %{time: 0.0, warmup: 0.0}} |> test_suite |> Benchmark.benchmark("", fn -> send(ref, :called) end) |> Benchmark.measure(TestPrinter) @@ -239,7 +218,7 @@ defmodule Benchee.Benchmark.RunnerTest do test "run times of the scenarios are empty when nothing runs" do %{scenarios: [scenario]} = - %Suite{configuration: %{time: 0, warmup: 0}} + %Suite{configuration: %{time: 0.0, warmup: 0.0}} |> test_suite |> Benchmark.benchmark("don't care", fn -> 0 end) |> Benchmark.measure(TestPrinter) @@ -309,7 +288,7 @@ defmodule Benchee.Benchmark.RunnerTest do test "runs the job exactly once if its time exceeds given time" do new_suite = - %Suite{configuration: %{time: 100, warmup: 0}} + %Suite{configuration: %{time: 100, warmup: 0.0}} |> test_suite |> Benchmark.benchmark("Sleeps", fn -> :timer.sleep(2) end) |> Benchmark.measure(TestPrinter) @@ -329,7 +308,7 @@ defmodule Benchee.Benchmark.RunnerTest do end run_times = - %Suite{configuration: %{time: 70_000, warmup: 0}} + %Suite{configuration: %{time: 70_000, warmup: 0.0}} |> test_suite |> Benchmark.benchmark("Sleep more", increasing_function) |> Benchmark.measure(TestPrinter) @@ -372,7 +351,7 @@ defmodule Benchee.Benchmark.RunnerTest do %Suite{ configuration: %{ - warmup: 0, + warmup: 0.0, time: 100, before_each: fn input -> send(me, :before) @@ -393,7 +372,7 @@ defmodule Benchee.Benchmark.RunnerTest do %Suite{ configuration: %{ - warmup: 0, + warmup: 0.0, time: 100 } } @@ -458,7 +437,7 @@ defmodule Benchee.Benchmark.RunnerTest do %Suite{ configuration: %{ - warmup: 0, + warmup: 0.0, time: 100, before_each: fn input -> send(me, :global_before) @@ -515,7 +494,7 @@ defmodule Benchee.Benchmark.RunnerTest do %Suite{ configuration: %{ - warmup: 0, + warmup: 0.0, time: 100, before_each: fn input -> send(me, :global_before) @@ -558,7 +537,7 @@ defmodule Benchee.Benchmark.RunnerTest do %Suite{ configuration: %{ - warmup: 0, + warmup: 0.0, time: 100, before_each: fn input -> send(me, :global_before) @@ -613,7 +592,7 @@ defmodule Benchee.Benchmark.RunnerTest do suite = %Suite{ configuration: %{ - warmup: 0, + warmup: 0.0, time: 10_000, before_each: fn input -> send(me, :global_before) @@ -684,6 +663,7 @@ defmodule Benchee.Benchmark.RunnerTest do assert sample_size == hook_call_count end + @tag :needs_fast_function_repetition test "hooks also trigger for very fast invocations" do me = self() @@ -896,7 +876,7 @@ defmodule Benchee.Benchmark.RunnerTest do inputs = %{"small" => 1, "big" => 100} - config = %{time: 0, warmup: 0, inputs: inputs, pre_check: true} + config = %{time: 0.0, warmup: 0.0, inputs: inputs, pre_check: true} %Suite{configuration: config} |> test_suite diff --git a/test/benchee/conversion/duration_test.exs b/test/benchee/conversion/duration_test.exs index eba7c7f6..76e0e15f 100644 --- a/test/benchee/conversion/duration_test.exs +++ b/test/benchee/conversion/duration_test.exs @@ -25,19 +25,19 @@ defmodule Benchee.Conversion.DurationTest do end test ".format(9_876_543210)" do - assert format(9_876_543210) == "9.88 s" + assert format(9_876_543_210) == "9.88 s" end test ".format(98_765_432190)" do - assert format(98_765_432190) == "1.65 min" + assert format(98_765_432_190) == "1.65 min" end test ".format(987_654_321987.6)" do - assert format(987_654_321987.6) == "16.46 min" + assert format(987_654_321_987.6) == "16.46 min" end test ".format(9_876_543_219876.5)" do - assert format(9_876_543_219876.5) == "2.74 h" + assert format(9_876_543_219_876.5) == "2.74 h" end test ".format(523.0)" do diff --git a/test/benchee/formatters/console/run_time_test.exs b/test/benchee/formatters/console/run_time_test.exs index 54358fd5..faa9cc98 100644 --- a/test/benchee/formatters/console/run_time_test.exs +++ b/test/benchee/formatters/console/run_time_test.exs @@ -72,8 +72,8 @@ defmodule Benchee.Formatters.Console.RunTimeTest do [_header1, _result1, _header2, _header3, result2] = RunTime.format_scenarios(scenarios, @console_config_extended_params) - assert result2 =~ ~r/201.20 μs/ - assert result2 =~ ~r/205.55 μs/ + assert result2 =~ ~r/201.20 ns/ + assert result2 =~ ~r/205.55 ns/ end test "displays N/A when no mode exists" do @@ -318,9 +318,9 @@ defmodule Benchee.Formatters.Console.RunTimeTest do ] assert [_, result] = RunTime.format_scenarios(scenarios, @console_config) - assert Regex.match?(~r/0.150\s?μs/, result) - assert Regex.match?(~r/0.0125\s?μs/, result) - assert Regex.match?(~r/0.0234\s?μs/, result) + assert Regex.match?(~r/0.150\s?ns/, result) + assert Regex.match?(~r/0.0125\s?ns/, result) + assert Regex.match?(~r/0.0234\s?ns/, result) end test "doesn't output weird 'e' formats" do @@ -328,11 +328,11 @@ defmodule Benchee.Formatters.Console.RunTimeTest do %Scenario{ name: "Job", run_time_statistics: %Statistics{ - average: 11_000.0, + average: 11_000_000.0, ips: 12_000.0, std_dev_ratio: 13_000.0, - median: 140_000.0, - percentiles: %{99 => 200_000.1}, + median: 140_000_000.0, + percentiles: %{99 => 200_000_000.1}, sample_size: 200 }, memory_usage_statistics: %Statistics{} diff --git a/test/benchee/output/benchmark_printer_test.exs b/test/benchee/output/benchmark_printer_test.exs index 0eec5b48..38ce5113 100644 --- a/test/benchee/output/benchmark_printer_test.exs +++ b/test/benchee/output/benchmark_printer_test.exs @@ -42,11 +42,11 @@ defmodule Benchee.Output.BenchmarkPrintertest do assert output =~ "macOS" assert output =~ "8568392814" assert output =~ ~r/following configuration/i - assert output =~ "warmup: 0 μs" - assert output =~ "time: 10 ms" - assert output =~ "memory time: 0 μs" + assert output =~ "warmup: 0 ns" + assert output =~ "time: 10 μs" + assert output =~ "memory time: 0 ns" assert output =~ "parallel: 2" - assert output =~ "Estimated total run time: 20 ms" + assert output =~ "Estimated total run time: 20 μs" end test "it scales times appropriately" do @@ -54,9 +54,9 @@ defmodule Benchee.Output.BenchmarkPrintertest do %{ configuration: %Configuration{ parallel: 1, - time: 60_000_000, - warmup: 10_000_000, - memory_time: 5_000_000, + time: 60_000_000_000, + warmup: 10_000_000_000, + memory_time: 5_000_000_000, inputs: nil }, scenarios: [%Scenario{job_name: "one"}, %Scenario{job_name: "two"}], @@ -94,11 +94,11 @@ defmodule Benchee.Output.BenchmarkPrintertest do |> configuration_information end - assert output =~ "time: 10 ms" - assert output =~ "memory time: 1 ms" + assert output =~ "time: 10 μs" + assert output =~ "memory time: 1 μs" assert output =~ "parallel: 2" assert output =~ "inputs: Arg 1, Arg 2" - assert output =~ "Estimated total run time: 44 ms" + assert output =~ "Estimated total run time: 44 μs" end test "does not print if disabled" do @@ -140,7 +140,9 @@ defmodule Benchee.Output.BenchmarkPrintertest do test "doesn't print if all times are set to 0" do output = capture_io fn -> - benchmarking "Never", "don't care", %Configuration{time: 0, warmup: 0, memory_time: 0} + benchmarking "Never", + "don't care", + %Configuration{time: 0.0, warmup: 0.0, memory_time: 0.0} end assert output == "" diff --git a/test/benchee_test.exs b/test/benchee_test.exs index 154ac95a..59609a3e 100644 --- a/test/benchee_test.exs +++ b/test/benchee_test.exs @@ -118,6 +118,7 @@ defmodule BencheeTest do readme_sample_asserts(output) end + @tag :needs_fast_function_repetition test "integration super fast function print warnings" do output = capture_io fn -> Benchee.run(%{"Constant" => fn -> 0 end}, time: 0.001, warmup: 0) @@ -128,6 +129,7 @@ defmodule BencheeTest do assert output =~ ~r/^Constant\s+\d+.+\s+[0-2]\.\d+ μs/m end + @tag :needs_fast_function_repetition test "integration super fast function warning is printed once per job" do output = capture_io fn -> Benchee.run(%{"Fast" => fn -> 0 end}, time: 0.001, warmup: 0.001) @@ -322,8 +324,12 @@ defmodule BencheeTest do end assert output =~ @header_regex - assert output =~ ~r/fast/ - assert output =~ ~r/unreliable/ + + # fast fnction warnings only appear on Windows because of none nanosecond precision + if windows?() do + assert output =~ ~r/fast/ + assert output =~ ~r/unreliable/ + end assert String.contains? output, ["number_one", "symbol_one"] occurences = Regex.scan body_regex("identity"), output diff --git a/test/test_helper.exs b/test/test_helper.exs index a3dce69e..59afd993 100644 --- a/test/test_helper.exs +++ b/test/test_helper.exs @@ -5,6 +5,12 @@ exclusions = if otp_release > 18, do: [], else: [memory_measure: true] # On Windows we have by far worse time measurements (millisecond level) # see: https://github.com/PragTob/benchee/pull/195#issuecomment-377010006 {_, os} = :os.type() -exclusions = if os == :nt, do: [{:performance, true} | exclusions], else: exclusions +exclusions = if os == :nt do + [{:performance, true} | exclusions] + else + # with our new nanosecond accuracy we can't trigger our super fast function code + # anymore on Linux/MacOS + [{:needs_fast_function_repetition, true} |exclusions] + end ExUnit.start(exclude: exclusions) From 7a683528d0835edbcea90613cab410e6190ea288 Mon Sep 17 00:00:00 2001 From: Tobias Pfeiffer Date: Thu, 10 May 2018 20:00:08 +0200 Subject: [PATCH 3/9] get time display right again --- lib/benchee/benchmark/runner.ex | 2 +- lib/benchee/configuration.ex | 18 ++++++------ lib/benchee/conversion/duration.ex | 14 +++++----- lib/benchee/statistics.ex | 10 +++---- samples/fast_functions.exs | 2 +- test/benchee/benchmark/runner_test.exs | 38 +++++++++++++------------- test/benchee/statistics_test.exs | 4 +-- test/benchee_test.exs | 3 ++ 8 files changed, 47 insertions(+), 44 deletions(-) diff --git a/lib/benchee/benchmark/runner.ex b/lib/benchee/benchmark/runner.ex index 122644a1..796af859 100644 --- a/lib/benchee/benchmark/runner.ex +++ b/lib/benchee/benchmark/runner.ex @@ -172,7 +172,7 @@ defmodule Benchee.Benchmark.Runner do do_benchmark(scenario, new_context, Measure.Time, [initial_run_time]) end - defp current_time, do: :erlang.system_time(:micro_seconds) + defp current_time, do: :erlang.system_time(:nano_seconds) # If a function executes way too fast measurements are too unreliable and # with too high variance. Therefore determine an n how often it should be diff --git a/lib/benchee/configuration.ex b/lib/benchee/configuration.ex index bcf55539..61535082 100644 --- a/lib/benchee/configuration.ex +++ b/lib/benchee/configuration.ex @@ -150,8 +150,8 @@ defmodule Benchee.Configuration do configuration: %Benchee.Configuration{ parallel: 1, - time: 5_000_000.0, - warmup: 2_000_000.0, + time: 5_000_000_000.0, + warmup: 2_000_000_000.0, inputs: nil, save: false, load: false, @@ -180,8 +180,8 @@ defmodule Benchee.Configuration do configuration: %Benchee.Configuration{ parallel: 1, - time: 1_000_000.0, - warmup: 200_000.0, + time: 1_000_000_000.0, + warmup: 200_000_000.0, inputs: nil, save: false, load: false, @@ -210,8 +210,8 @@ defmodule Benchee.Configuration do configuration: %Benchee.Configuration{ parallel: 1, - time: 1_000_000.0, - warmup: 200_000.0, + time: 1_000_000_000.0, + warmup: 200_000_000.0, inputs: nil, save: false, load: false, @@ -249,8 +249,8 @@ defmodule Benchee.Configuration do configuration: %Benchee.Configuration{ parallel: 2, - time: 1_000_000.0, - warmup: 200_000.0, + time: 1_000_000_000.0, + warmup: 200_000_000.0, inputs: %{"Small" => 5, "Big" => 9999}, save: false, load: false, @@ -324,7 +324,7 @@ defmodule Benchee.Configuration do Enum.reduce(@time_keys, config, fn key, new_config -> {_, new_config} = Map.get_and_update!(new_config, key, fn seconds -> - {seconds, Duration.microseconds({seconds, :second})} + {seconds, Duration.convert_value({seconds, :second}, :nanosecond)} end) new_config diff --git a/lib/benchee/conversion/duration.ex b/lib/benchee/conversion/duration.ex index c029f178..fb07ce56 100644 --- a/lib/benchee/conversion/duration.ex +++ b/lib/benchee/conversion/duration.ex @@ -172,25 +172,25 @@ defmodule Benchee.Conversion.Duration do end @doc """ - Converts a value of the given unit into microseconds + Converts a value of the given unit into the desired unit, returning only the value not the unit. ## Examples - iex> Benchee.Conversion.Duration.microseconds({1.234, :second}) + iex> Benchee.Conversion.Duration.convert_value({1.234, :second}, :microsecond) 1_234_000.0 - iex> Benchee.Conversion.Duration.microseconds({1.234, :minute}) + iex> Benchee.Conversion.Duration.convert_value({1.234, :minute}, :microsecond) 7.404e7 - iex> microseconds = Benchee.Conversion.Duration.microseconds({1.234, :minute}) + iex> microseconds = Benchee.Conversion.Duration.convert_value({1.234, :minute}, :microsecond) iex> {value, _} = Benchee.Conversion.Duration.convert({microseconds, :microsecond}, :minute) iex> value 1.234 """ - def microseconds({duration, unit}) do - {microseconds, _} = convert({duration, unit}, :microsecond) - microseconds + def convert_value({duration, unit}, desired_unit) do + {value, _} = convert({duration, unit}, desired_unit) + value end @doc """ diff --git a/lib/benchee/statistics.ex b/lib/benchee/statistics.ex index 08242d6c..8e50c8d5 100644 --- a/lib/benchee/statistics.ex +++ b/lib/benchee/statistics.ex @@ -119,10 +119,10 @@ defmodule Benchee.Statistics do input: "Input", run_time_statistics: %Benchee.Statistics{ average: 500.0, - ips: 2000.0, + ips: 2000_000.0, std_dev: 200.0, std_dev_ratio: 0.4, - std_dev_ips: 800.0, + std_dev_ips: 800_000.0, median: 500.0, percentiles: %{50 => 500.0, 99 => 900.0}, mode: [500, 400], @@ -264,7 +264,7 @@ defmodule Benchee.Statistics do defp add_ips(statistics = %__MODULE__{sample_size: 0}), do: statistics defp add_ips(statistics = %__MODULE__{average: 0.0}), do: statistics defp add_ips(statistics) do - ips = Duration.microseconds({1, :second}) / statistics.average + ips = Duration.convert_value({1, :second}, :nanosecond) / statistics.average standard_dev_ips = ips * statistics.std_dev_ratio %__MODULE__{ @@ -303,10 +303,10 @@ defmodule Benchee.Statistics do input: "Input", run_time_statistics: %Benchee.Statistics{ average: 500.0, - ips: 2000.0, + ips: 2_000_000.0, std_dev: 200.0, std_dev_ratio: 0.4, - std_dev_ips: 800.0, + std_dev_ips: 800_000.0, median: 500.0, percentiles: %{25 => 400.0, 50 => 500.0, 75 => 600.0, 99 => 900.0}, mode: [500, 400], diff --git a/samples/fast_functions.exs b/samples/fast_functions.exs index cc268c03..f76e4130 100644 --- a/samples/fast_functions.exs +++ b/samples/fast_functions.exs @@ -10,7 +10,7 @@ Benchee.run(%{ "++ array concat" => fn -> [1] ++ [1] end, "noop" => fn -> 0 end, "Enum.map(10)" => fn -> Enum.map(range, fn(i) -> i end) end -}, time: 1, warmup: 1) +}, time: 1, warmup: 1, memory_time: 1) # # Before adding running fast functions multiple times, these where just too diff --git a/test/benchee/benchmark/runner_test.exs b/test/benchee/benchmark/runner_test.exs index d8f578eb..cdfd68af 100644 --- a/test/benchee/benchmark/runner_test.exs +++ b/test/benchee/benchmark/runner_test.exs @@ -8,8 +8,8 @@ defmodule Benchee.Benchmark.RunnerTest do @config %Configuration{ parallel: 1, - time: 40_000, - warmup: 20_000, + time: 40_000_000, + warmup: 20_000_000, inputs: nil, pre_check: false, print: %{fast_warning: false, configuration: true} @@ -44,7 +44,7 @@ defmodule Benchee.Benchmark.RunnerTest do @tag :performance test "runs a benchmark suite and enriches it with measurements" do retrying(fn -> - suite = test_suite(%Suite{configuration: %{time: 60_000, warmup: 10_000}}) + suite = test_suite(%Suite{configuration: %{time: 60_000_000, warmup: 10_000_000}}) new_suite = suite @@ -62,7 +62,7 @@ defmodule Benchee.Benchmark.RunnerTest do @tag :performance test "runs a suite with multiple jobs and gathers results" do retrying(fn -> - suite = test_suite(%Suite{configuration: %{time: 100_000, warmup: 10_000}}) + suite = test_suite(%Suite{configuration: %{time: 100_000_000, warmup: 10_000_000}}) new_suite = suite @@ -78,7 +78,7 @@ defmodule Benchee.Benchmark.RunnerTest do end test "can run multiple benchmarks in parallel" do - suite = test_suite(%Suite{configuration: %{parallel: 4, time: 60_000}}) + suite = test_suite(%Suite{configuration: %{parallel: 4, time: 60_000_000}}) new_suite = suite @@ -90,7 +90,7 @@ defmodule Benchee.Benchmark.RunnerTest do end test "combines results for parallel benchmarks into a single scenario" do - suite = test_suite(%Suite{configuration: %{parallel: 4, time: 60_000}}) + suite = test_suite(%Suite{configuration: %{parallel: 4, time: 60_000_000}}) new_suite = suite @@ -103,7 +103,7 @@ defmodule Benchee.Benchmark.RunnerTest do @tag :memory_measure test "measures the memory usage of a scenario" do suite = - test_suite(%Suite{configuration: %{time: 60_000, warmup: 10_000, memory_time: 10_000}}) + test_suite(%Suite{configuration: %{time: 60_000_000, warmup: 10_000, memory_time: 10_000}}) new_suite = suite @@ -120,7 +120,7 @@ defmodule Benchee.Benchmark.RunnerTest do @tag :memory_measure test "records memory when the function only runs once" do suite = - test_suite(%Suite{configuration: %{time: 0.0, warmup: 0.0, memory_time: 1_000}}) + test_suite(%Suite{configuration: %{time: 0.0, warmup: 0.0, memory_time: 1_000_000}}) new_suite = suite @@ -137,7 +137,7 @@ defmodule Benchee.Benchmark.RunnerTest do @tag :memory_measure test "correctly scales down memory usage of very fast functions" do suite = - test_suite(%Suite{configuration: %{time: 1_000, warmup: 1, memory_time: 1_000}}) + test_suite(%Suite{configuration: %{time: 0.0, warmup: 1, memory_time: 1_000_000}}) new_suite = suite @@ -176,16 +176,16 @@ defmodule Benchee.Benchmark.RunnerTest do |> Benchmark.measure(TestPrinter) |> Benchee.statistics() - [%{run_time_statistics: %{average: average}}] = suite.scenarios + [%{run_time_statistics: %{median: median}}] = suite.scenarios - assert average < 200 # around ~78 on my machine + assert median < 200 # around ~78 on my machine end @tag :performance test "doesn't take longer than advertised for very fast funs" do retrying(fn -> - time = 20_000 - warmup = 10_000 + time = 20_000_000 + warmup = 10_000_000 projected = time + warmup suite = @@ -193,7 +193,7 @@ defmodule Benchee.Benchmark.RunnerTest do |> test_suite() |> Benchmark.benchmark("", fn -> :timer.sleep(1) end) - {time, _} = :timer.tc(fn -> Benchmark.measure(suite, TestPrinter) end) + {time, _} = Benchmark.Measure.Time.measure(fn -> Benchmark.measure(suite, TestPrinter) end) # if the system is too busy there are too many false positives leeway = projected * 0.4 @@ -271,7 +271,7 @@ defmodule Benchee.Benchmark.RunnerTest do "Longer wait" => 19 } - config = %{time: 100_000, warmup: 10_000, inputs: inputs} + config = %{time: 100_000_000, warmup: 10_000_000, inputs: inputs} new_suite = %Suite{configuration: config} @@ -288,7 +288,7 @@ defmodule Benchee.Benchmark.RunnerTest do test "runs the job exactly once if its time exceeds given time" do new_suite = - %Suite{configuration: %{time: 100, warmup: 0.0}} + %Suite{configuration: %{time: 1, warmup: 0.0}} |> test_suite |> Benchmark.benchmark("Sleeps", fn -> :timer.sleep(2) end) |> Benchmark.measure(TestPrinter) @@ -308,7 +308,7 @@ defmodule Benchee.Benchmark.RunnerTest do end run_times = - %Suite{configuration: %{time: 70_000, warmup: 0.0}} + %Suite{configuration: %{time: 70_000_000, warmup: 0.0}} |> test_suite |> Benchmark.benchmark("Sleep more", increasing_function) |> Benchmark.measure(TestPrinter) @@ -593,7 +593,7 @@ defmodule Benchee.Benchmark.RunnerTest do suite = %Suite{ configuration: %{ warmup: 0.0, - time: 10_000, + time: 10_000_000, before_each: fn input -> send(me, :global_before) input @@ -670,7 +670,7 @@ defmodule Benchee.Benchmark.RunnerTest do suite = %Suite{ configuration: %{ warmup: 1, - time: 1_000, + time: 1_000_000, before_each: fn input -> send(me, :global_before) input diff --git a/test/benchee/statistics_test.exs b/test/benchee/statistics_test.exs index d0dcea27..0517ff90 100644 --- a/test/benchee/statistics_test.exs +++ b/test/benchee/statistics_test.exs @@ -121,7 +121,7 @@ defmodule Benchee.StatistcsTest do assert stats.average == 394.0 assert_in_delta stats.std_dev, 164.71, 0.01 assert_in_delta stats.std_dev_ratio, 0.41, 0.01 - assert_in_delta stats.ips, 2538, 1 + assert_in_delta stats.ips, 2_538_071, 1 assert stats.median == 430.0 assert stats.minimum == 170 assert stats.maximum == 600 @@ -133,7 +133,7 @@ defmodule Benchee.StatistcsTest do assert stats.average == 14.0 assert_in_delta stats.std_dev, 5.76, 0.01 assert_in_delta stats.std_dev_ratio, 0.41, 0.01 - assert_in_delta stats.ips, 71_428, 1 + assert_in_delta stats.ips, 71_428_571, 1 assert stats.median == 14.0 assert stats.minimum == 7 assert stats.maximum == 23 diff --git a/test/benchee_test.exs b/test/benchee_test.exs index 59609a3e..796fd1ed 100644 --- a/test/benchee_test.exs +++ b/test/benchee_test.exs @@ -565,6 +565,9 @@ defmodule BencheeTest do @slower_regex "\\s+- \\d+\\.\\d+x slower" defp readme_sample_asserts(output, tag_string \\ "") do + assert output =~ "warmup: 5 ms" + assert output =~ "time: 10 ms" + tag_regex = Regex.escape(tag_string) assert output =~ @header_regex assert output =~ body_regex("flat_map", tag_regex) From 915d1c77423ea9305dfbc3ad8882b95cab13f88e Mon Sep 17 00:00:00 2001 From: Tobias Pfeiffer Date: Thu, 10 May 2018 20:16:56 +0200 Subject: [PATCH 4/9] Fix Credo, CI, remove Erlang 18 as it doesnt seem to support time covnersion like we want --- .travis.yml | 1 - samples/memory_breaker.exs | 2 +- test/benchee/benchmark/runner_test.exs | 7 ++++--- test/benchee_test.exs | 2 +- 4 files changed, 6 insertions(+), 6 deletions(-) diff --git a/.travis.yml b/.travis.yml index 8040cb69..eb05e519 100644 --- a/.travis.yml +++ b/.travis.yml @@ -4,7 +4,6 @@ elixir: - 1.5.3 - 1.6.4 otp_release: - - 18.3 - 19.3 - 20.3 matrix: diff --git a/samples/memory_breaker.exs b/samples/memory_breaker.exs index 61be713c..9d4488d1 100644 --- a/samples/memory_breaker.exs +++ b/samples/memory_breaker.exs @@ -95,4 +95,4 @@ inputs = %{ "huge hit" => {Enum.map(1..10000, &{:"k#{&1}", &1}), :k10000} } -Benchee.run(benches, inputs: inputs, print: [fast_warning: false], memory_time: 0.001, warmup: 0, time: 0) +Benchee.run(benches, inputs: inputs, print: [fast_warning: false], memory_time: 0.001, warmup: 1, time: 2) diff --git a/test/benchee/benchmark/runner_test.exs b/test/benchee/benchmark/runner_test.exs index cdfd68af..b38409b7 100644 --- a/test/benchee/benchmark/runner_test.exs +++ b/test/benchee/benchmark/runner_test.exs @@ -103,7 +103,7 @@ defmodule Benchee.Benchmark.RunnerTest do @tag :memory_measure test "measures the memory usage of a scenario" do suite = - test_suite(%Suite{configuration: %{time: 60_000_000, warmup: 10_000, memory_time: 10_000}}) + test_suite(%Suite{configuration: %{time: 60_000, warmup: 10_000, memory_time: 10_000}}) new_suite = suite @@ -178,7 +178,7 @@ defmodule Benchee.Benchmark.RunnerTest do [%{run_time_statistics: %{median: median}}] = suite.scenarios - assert median < 200 # around ~78 on my machine + assert median < 1500 # around ~78 on my machine, CI is awful for performance end @tag :performance @@ -193,7 +193,8 @@ defmodule Benchee.Benchmark.RunnerTest do |> test_suite() |> Benchmark.benchmark("", fn -> :timer.sleep(1) end) - {time, _} = Benchmark.Measure.Time.measure(fn -> Benchmark.measure(suite, TestPrinter) end) + {time, _} = + Benchmark.Measure.Time.measure(fn -> Benchmark.measure(suite, TestPrinter) end) # if the system is too busy there are too many false positives leeway = projected * 0.4 diff --git a/test/benchee_test.exs b/test/benchee_test.exs index 796fd1ed..7781ceff 100644 --- a/test/benchee_test.exs +++ b/test/benchee_test.exs @@ -126,7 +126,7 @@ defmodule BencheeTest do assert output =~ ~r/fast/ assert output =~ ~r/unreliable/ - assert output =~ ~r/^Constant\s+\d+.+\s+[0-2]\.\d+ μs/m + assert output =~ ~r/^Constant\s+\d+.+\s+[0-2]\.\d+ ns/m end @tag :needs_fast_function_repetition From 2dc2a98480a045f4af049812b7e45a805fd8d9cf Mon Sep 17 00:00:00 2001 From: Tobias Pfeiffer Date: Thu, 10 May 2018 20:32:13 +0200 Subject: [PATCH 5/9] changelog --- CHANGELOG.md | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index d39929e6..5963941a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,14 @@ +## 0.14.0 (unreleased) + +### Breaking Changes (User Facing) +* dropped support for Erlang 18.x + +### Features (User Facing) +* benchee now uses the maximum precision available to measure which on Linux and OSX is nanoseonds instead of microseconds. Somewhat surprisingly `:timer.tc/1` always cut down to microseconds although better precision is available. + +### Breaking Changes (Plugins) +* all reported times are now in nanoseconds instead of microseconds + ## 0.13.1 (2018-05-02) Mostly fixing memory measurement bugs and related issues :) Enjoy a better memory measurement experience from now on! From acec2fab1cc13f5cdb9ce9dcea6a5978aeff2f52 Mon Sep 17 00:00:00 2001 From: Tobias Pfeiffer Date: Fri, 11 May 2018 12:31:16 +0200 Subject: [PATCH 6/9] Pull Runner apart for testability and usability * RepeatedMeasurement to unit test it and not pollute general runner with this very specific code for runtime measurements that's only relevant on Windows these days it seems * Hooks code in its own module to not pollute and reuse from both place * made `measure` public on the runner... not 100% happy with this but putting it into even another module seems like an overhead now. * temporarily duplicated `main_function` code --- lib/benchee/benchmark/hooks.ex | 63 ++++++ lib/benchee/benchmark/repeated_measurement.ex | 147 ++++++++++++ lib/benchee/benchmark/runner.ex | 213 +++--------------- 3 files changed, 241 insertions(+), 182 deletions(-) create mode 100644 lib/benchee/benchmark/hooks.ex create mode 100644 lib/benchee/benchmark/repeated_measurement.ex diff --git a/lib/benchee/benchmark/hooks.ex b/lib/benchee/benchmark/hooks.ex new file mode 100644 index 00000000..489ee507 --- /dev/null +++ b/lib/benchee/benchmark/hooks.ex @@ -0,0 +1,63 @@ +defmodule Benchee.Benchmark.Hooks do + @moduledoc false + # Non benchee code should not rely on this module. + + alias Benchee.Benchmark.{Scenario, ScenarioContext} + + def run_before_scenario( + %Scenario{ + before_scenario: local_before_scenario, + input: input + }, + %ScenarioContext{ + config: %{before_scenario: global_before_scenario} + } + ) do + input + |> run_before_function(global_before_scenario) + |> run_before_function(local_before_scenario) + end + + defp run_before_function(input, nil), do: input + defp run_before_function(input, function), do: function.(input) + + def run_before_each( + %{ + before_each: local_before_each + }, + %{ + config: %{before_each: global_before_each}, + scenario_input: input + } + ) do + input + |> run_before_function(global_before_each) + |> run_before_function(local_before_each) + end + +def run_after_each( + return_value, + %{ + after_each: local_after_each + }, + %{ + config: %{after_each: global_after_each} + } + ) do + if local_after_each, do: local_after_each.(return_value) + if global_after_each, do: global_after_each.(return_value) + end + + def run_after_scenario( + %{ + after_scenario: local_after_scenario + }, + %{ + config: %{after_scenario: global_after_scenario}, + scenario_input: input + } + ) do + if local_after_scenario, do: local_after_scenario.(input) + if global_after_scenario, do: global_after_scenario.(input) + end +end diff --git a/lib/benchee/benchmark/repeated_measurement.ex b/lib/benchee/benchmark/repeated_measurement.ex new file mode 100644 index 00000000..7c05a917 --- /dev/null +++ b/lib/benchee/benchmark/repeated_measurement.ex @@ -0,0 +1,147 @@ +defmodule Benchee.Benchmark.RepeatedMeasurement do + @moduledoc false + # This module is an internal implementation detail, and should absolutely not be relied upon + # from external clients. + # + # It is used when we can't conduct measurements precise enough with our measurement precision. + # I.e. we can measure in microseconds but we measure a function call to take 1 microsecond then + # most measurements will either be 1 or 2 microseconds which won't give us great results. + # Instead we repeat the function call n times until we measure at least ~10 (time unit) so + # that the difference between measurements can at least be ~10%. + # + # Today this is mostly only relevant on Windows as we have nanosecond precision on Linux and + # Mac OS and we've failed to produce a measurable function call that takes less than 10 nano + # seconds. + # + # That's also why this code lives in a separate module and not `Runner` - as it's rarely used + # and clutters that code + we need a way to test it even if we can't trigger it's conditions. + + # If a function executes way too fast measurements are too unreliable and + # with too high variance. Therefore determine an n how often it should be + # executed in the measurement cycle. + + alias Benchee.Benchmark.{Hooks, Runner, Scenario, ScenarioContext, Measure} + alias Benchee.Utility.RepeatN + + @minimum_execution_time 10 + @times_multiplier 10 + def determine_n_times( + scenario, + scenario_context = %ScenarioContext{ + num_iterations: num_iterations, + printer: printer + }, + fast_warning + ) do + run_time = measure_iteration(scenario, scenario_context, Measure.NativeTime) + + if run_time >= @minimum_execution_time do + {num_iterations, adjust_for_iterations(run_time, num_iterations)} + else + if fast_warning, do: printer.fast_warning() + + new_context = %ScenarioContext{ + scenario_context + | num_iterations: num_iterations * @times_multiplier + } + + determine_n_times(scenario, new_context, false) + end + end + + defp adjust_for_iterations(measurement, 1), do: measurement + defp adjust_for_iterations(measurement, num_iterations), do: measurement / num_iterations + + def measure( + scenario, + scenario_context = %ScenarioContext{ + num_iterations: num_iterations + }, + measurer + ) do + measurement = measure_iteration(scenario, scenario_context, measurer) + + adjust_for_iterations(measurement, num_iterations) + end + + defp measure_iteration( + scenario, + scenario_context = %ScenarioContext{ + num_iterations: 1 + }, + measurer + ) do + Runner.measure(scenario, scenario_context, measurer) + end + + defp measure_iteration( + scenario, + scenario_context = %ScenarioContext{ + num_iterations: iterations + }, + measurer + ) + when iterations > 1 do + # When we have more than one iteration, then the repetition and calling + # of hooks is already included in the function, for reference/reasoning see + # `build_benchmarking_function/2` + function = build_benchmarking_function(scenario, scenario_context) + + {measurement, _return_value} = measurer.measure(function) + + measurement + end + + # Builds the appropriate function to benchmark. Takes into account the + # combinations of the following cases: + # + # * an input is specified - creates a 0-argument function calling the original + # function with that input + # * number of iterations - when there's more than one iteration we repeat the + # benchmarking function during execution and measure the the total run time. + # We only run multiple iterations if a function is so fast that we can't + # accurately measure it in one go. Hence, we can't split up the function + # execution and hooks anymore and sadly we also measure the time of the + # hooks. + defp build_benchmarking_function( + %Scenario{ + function: function, + before_each: nil, + after_each: nil + }, + %ScenarioContext{ + num_iterations: iterations, + scenario_input: input, + config: %{after_each: nil, before_each: nil} + } + ) + when iterations > 1 do + main = main_function(function, input) + # with no before/after each we can safely omit them and don't get the hit + # on run time measurements (See PR discussions for this for more info #127) + fn -> RepeatN.repeat_n(main, iterations) end + end + + defp build_benchmarking_function( + scenario = %Scenario{function: function}, + scenario_context = %ScenarioContext{num_iterations: iterations} + ) + when iterations > 1 do + fn -> + RepeatN.repeat_n( + fn -> + new_input = Hooks.run_before_each(scenario, scenario_context) + main = main_function(function, new_input) + return_value = main.() + Hooks.run_after_each(return_value, scenario, scenario_context) + end, + iterations + ) + end + end + + # TODO: temporarily duplicated + @no_input Benchee.Benchmark.no_input() + defp main_function(function, @no_input), do: function + defp main_function(function, input), do: fn -> function.(input) end +end diff --git a/lib/benchee/benchmark/runner.ex b/lib/benchee/benchmark/runner.ex index 796af859..d810e36b 100644 --- a/lib/benchee/benchmark/runner.ex +++ b/lib/benchee/benchmark/runner.ex @@ -5,8 +5,8 @@ defmodule Benchee.Benchmark.Runner do """ alias Benchee.Benchmark - alias Benchee.Benchmark.{Scenario, ScenarioContext, Measure} - alias Benchee.Utility.{RepeatN, Parallel} + alias Benchee.Benchmark.{Scenario, ScenarioContext, Measure, Hooks, RepeatedMeasurement} + alias Benchee.Utility.Parallel alias Benchee.Configuration @doc """ @@ -32,10 +32,10 @@ defmodule Benchee.Benchmark.Runner do # This will run the given scenario exactly once, including the before and # after hooks, to ensure the function can execute without raising an error. defp pre_check(scenario, scenario_context = %ScenarioContext{config: %{pre_check: true}}) do - scenario_input = run_before_scenario(scenario, scenario_context) + scenario_input = Hooks.run_before_scenario(scenario, scenario_context) scenario_context = %ScenarioContext{scenario_context | scenario_input: scenario_input} - _ = measure_iteration(scenario, scenario_context, Measure.Time) - _ = run_after_scenario(scenario, scenario_context) + _ = measure(scenario, scenario_context, Measure.Time) + _ = Hooks.run_after_scenario(scenario, scenario_context) nil end @@ -68,33 +68,16 @@ defmodule Benchee.Benchmark.Runner do end defp measure_scenario(scenario, scenario_context) do - scenario_input = run_before_scenario(scenario, scenario_context) + scenario_input = Hooks.run_before_scenario(scenario, scenario_context) scenario_context = %ScenarioContext{scenario_context | scenario_input: scenario_input} _ = run_warmup(scenario, scenario_context) runtimes = run_runtime_benchmark(scenario, scenario_context) memory_usages = run_memory_benchmark(scenario, scenario_context) - run_after_scenario(scenario, scenario_context) + Hooks.run_after_scenario(scenario, scenario_context) {runtimes, memory_usages} end - defp run_before_scenario( - %Scenario{ - before_scenario: local_before_scenario, - input: input - }, - %ScenarioContext{ - config: %{before_scenario: global_before_scenario} - } - ) do - input - |> run_before_function(global_before_scenario) - |> run_before_function(local_before_scenario) - end - - defp run_before_function(input, nil), do: input - defp run_before_function(input, function), do: function.(input) - defp run_warmup( scenario, scenario_context = %ScenarioContext{ @@ -139,19 +122,6 @@ defmodule Benchee.Benchmark.Runner do do_benchmark(scenario, new_context, Measure.Memory, []) end - defp run_after_scenario( - %{ - after_scenario: local_after_scenario - }, - %{ - config: %{after_scenario: global_after_scenario}, - scenario_input: input - } - ) do - if local_after_scenario, do: local_after_scenario.(input) - if global_after_scenario, do: global_after_scenario.(input) - end - defp measure_runtimes(scenario, context, run_time, fast_warning) defp measure_runtimes(_, _, 0.0, _), do: [] @@ -160,7 +130,7 @@ defmodule Benchee.Benchmark.Runner do :erlang.garbage_collect() {num_iterations, initial_run_time} = - determine_n_times(scenario, scenario_context, fast_warning) + RepeatedMeasurement.determine_n_times(scenario, scenario_context, fast_warning) new_context = %ScenarioContext{ scenario_context @@ -174,35 +144,6 @@ defmodule Benchee.Benchmark.Runner do defp current_time, do: :erlang.system_time(:nano_seconds) - # If a function executes way too fast measurements are too unreliable and - # with too high variance. Therefore determine an n how often it should be - # executed in the measurement cycle. - @minimum_execution_time 10 - @times_multiplier 10 - defp determine_n_times( - scenario, - scenario_context = %ScenarioContext{ - num_iterations: num_iterations, - printer: printer - }, - fast_warning - ) do - run_time = measure_iteration(scenario, scenario_context, Measure.NativeTime) - - if run_time >= @minimum_execution_time do - {num_iterations, adjust_for_iterations(run_time, num_iterations)} - else - if fast_warning, do: printer.fast_warning() - - new_context = %ScenarioContext{ - scenario_context - | num_iterations: num_iterations * @times_multiplier - } - - determine_n_times(scenario, new_context, false) - end - end - # `run_times` is kept separately from the `Scenario` so that for the # `parallel` execution case we can easily concatenate and flatten the results # of all processes. That's why we add them to the scenario once after @@ -223,7 +164,7 @@ defmodule Benchee.Benchmark.Runner do end defp do_benchmark(scenario, scenario_context, measurer, measurements) do - measurement = iteration_measurements(scenario, scenario_context, measurer) + measurement = measure(scenario, scenario_context, measurer) updated_context = %ScenarioContext{scenario_context | current_time: current_time()} do_benchmark( @@ -238,131 +179,39 @@ defmodule Benchee.Benchmark.Runner do defp updated_measurements(nil, measurements), do: measurements defp updated_measurements(measurement, measurements), do: [measurement | measurements] - defp iteration_measurements( - scenario, - scenario_context = %ScenarioContext{ - num_iterations: num_iterations - }, - measurer - ) do - measurement = measure_iteration(scenario, scenario_context, measurer) - - adjust_for_iterations(measurement, num_iterations) - end - - defp adjust_for_iterations(measurement, 1), do: measurement - defp adjust_for_iterations(measurement, num_iterations), do: measurement / num_iterations + @doc """ + Takes one measure with the given measurer. - defp measure_iteration( - scenario = %Scenario{function: function}, - scenario_context = %ScenarioContext{ - num_iterations: 1, - }, - measurer - ) do - new_input = run_before_each(scenario, scenario_context) + Correctly dispatches based on the number of iterations to perform. + """ + def measure( + scenario = %Scenario{function: function}, + scenario_context = %ScenarioContext{ + num_iterations: 1, + }, + measurer + ) do + new_input = Hooks.run_before_each(scenario, scenario_context) function = main_function(function, new_input) {measurement, return_value} = measurer.measure(function) - run_after_each(return_value, scenario, scenario_context) + Hooks.run_after_each(return_value, scenario, scenario_context) measurement end - defp measure_iteration( - scenario, - scenario_context = %ScenarioContext{ - num_iterations: iterations - }, - measurer - ) - when iterations > 1 do - # When we have more than one iteration, then the repetition and calling - # of hooks is already included in the function, for reference/reasoning see - # `build_benchmarking_function/2` - function = build_benchmarking_function(scenario, scenario_context) - - {measurement, _return_value} = measurer.measure(function) - - measurement + def measure( + scenario, + scenario_context = %ScenarioContext{ + num_iterations: iterations + }, + measurer + ) + when iterations > 1 do + RepeatedMeasurement.measure(scenario, scenario_context, measurer) end @no_input Benchmark.no_input() defp main_function(function, @no_input), do: function defp main_function(function, input), do: fn -> function.(input) end - - # Builds the appropriate function to benchmark. Takes into account the - # combinations of the following cases: - # - # * an input is specified - creates a 0-argument function calling the original - # function with that input - # * number of iterations - when there's more than one iteration we repeat the - # benchmarking function during execution and measure the the total run time. - # We only run multiple iterations if a function is so fast that we can't - # accurately measure it in one go. Hence, we can't split up the function - # execution and hooks anymore and sadly we also measure the time of the - # hooks. - defp build_benchmarking_function( - %Scenario{ - function: function, - before_each: nil, - after_each: nil - }, - %ScenarioContext{ - num_iterations: iterations, - scenario_input: input, - config: %{after_each: nil, before_each: nil} - } - ) - when iterations > 1 do - main = main_function(function, input) - # with no before/after each we can safely omit them and don't get the hit - # on run time measurements (See PR discussions for this for more info #127) - fn -> RepeatN.repeat_n(main, iterations) end - end - - defp build_benchmarking_function( - scenario = %Scenario{function: function}, - scenario_context = %ScenarioContext{num_iterations: iterations} - ) - when iterations > 1 do - fn -> - RepeatN.repeat_n( - fn -> - new_input = run_before_each(scenario, scenario_context) - main = main_function(function, new_input) - return_value = main.() - run_after_each(return_value, scenario, scenario_context) - end, - iterations - ) - end - end - - defp run_before_each( - %{ - before_each: local_before_each - }, - %{ - config: %{before_each: global_before_each}, - scenario_input: input - } - ) do - input - |> run_before_function(global_before_each) - |> run_before_function(local_before_each) - end - - defp run_after_each( - return_value, - %{ - after_each: local_after_each - }, - %{ - config: %{after_each: global_after_each} - } - ) do - if local_after_each, do: local_after_each.(return_value) - if global_after_each, do: global_after_each.(return_value) - end end From 95ef82cba4e8555f2b5a3a3b8dc4d96addca1a57 Mon Sep 17 00:00:00 2001 From: Tobias Pfeiffer Date: Fri, 11 May 2018 13:24:57 +0200 Subject: [PATCH 7/9] Ok just reuse the main_function from Runner for now --- lib/benchee/benchmark/repeated_measurement.ex | 9 ++------- lib/benchee/benchmark/runner.ex | 4 ++-- 2 files changed, 4 insertions(+), 9 deletions(-) diff --git a/lib/benchee/benchmark/repeated_measurement.ex b/lib/benchee/benchmark/repeated_measurement.ex index 7c05a917..94fd7912 100644 --- a/lib/benchee/benchmark/repeated_measurement.ex +++ b/lib/benchee/benchmark/repeated_measurement.ex @@ -116,7 +116,7 @@ defmodule Benchee.Benchmark.RepeatedMeasurement do } ) when iterations > 1 do - main = main_function(function, input) + main = Runner.main_function(function, input) # with no before/after each we can safely omit them and don't get the hit # on run time measurements (See PR discussions for this for more info #127) fn -> RepeatN.repeat_n(main, iterations) end @@ -131,7 +131,7 @@ defmodule Benchee.Benchmark.RepeatedMeasurement do RepeatN.repeat_n( fn -> new_input = Hooks.run_before_each(scenario, scenario_context) - main = main_function(function, new_input) + main = Runner.main_function(function, new_input) return_value = main.() Hooks.run_after_each(return_value, scenario, scenario_context) end, @@ -139,9 +139,4 @@ defmodule Benchee.Benchmark.RepeatedMeasurement do ) end end - - # TODO: temporarily duplicated - @no_input Benchee.Benchmark.no_input() - defp main_function(function, @no_input), do: function - defp main_function(function, input), do: fn -> function.(input) end end diff --git a/lib/benchee/benchmark/runner.ex b/lib/benchee/benchmark/runner.ex index d810e36b..42474851 100644 --- a/lib/benchee/benchmark/runner.ex +++ b/lib/benchee/benchmark/runner.ex @@ -212,6 +212,6 @@ defmodule Benchee.Benchmark.Runner do end @no_input Benchmark.no_input() - defp main_function(function, @no_input), do: function - defp main_function(function, input), do: fn -> function.(input) end + def main_function(function, @no_input), do: function + def main_function(function, input), do: fn -> function.(input) end end From a44619546faa14f7d39570b29a9d265a433d90bb Mon Sep 17 00:00:00 2001 From: Tobias Pfeiffer Date: Fri, 11 May 2018 14:58:35 +0200 Subject: [PATCH 8/9] Test Repetition code even on platforms that don't trigger it/unit --- lib/benchee/benchmark/repeated_measurement.ex | 7 +- lib/benchee/benchmark/runner.ex | 8 +- .../benchmark/repeated_measurement_test.exs | 115 ++++++++++++++++++ 3 files changed, 123 insertions(+), 7 deletions(-) create mode 100644 test/benchee/benchmark/repeated_measurement_test.exs diff --git a/lib/benchee/benchmark/repeated_measurement.ex b/lib/benchee/benchmark/repeated_measurement.ex index 94fd7912..750d700e 100644 --- a/lib/benchee/benchmark/repeated_measurement.ex +++ b/lib/benchee/benchmark/repeated_measurement.ex @@ -31,9 +31,10 @@ defmodule Benchee.Benchmark.RepeatedMeasurement do num_iterations: num_iterations, printer: printer }, - fast_warning + fast_warning, + measurer \\ Measure.NativeTime ) do - run_time = measure_iteration(scenario, scenario_context, Measure.NativeTime) + run_time = measure_iteration(scenario, scenario_context, measurer) if run_time >= @minimum_execution_time do {num_iterations, adjust_for_iterations(run_time, num_iterations)} @@ -45,7 +46,7 @@ defmodule Benchee.Benchmark.RepeatedMeasurement do | num_iterations: num_iterations * @times_multiplier } - determine_n_times(scenario, new_context, false) + determine_n_times(scenario, new_context, false, measurer) end end diff --git a/lib/benchee/benchmark/runner.ex b/lib/benchee/benchmark/runner.ex index 42474851..397a6ec4 100644 --- a/lib/benchee/benchmark/runner.ex +++ b/lib/benchee/benchmark/runner.ex @@ -1,8 +1,8 @@ defmodule Benchee.Benchmark.Runner do - @moduledoc """ - This module actually runs our benchmark scenarios, adding information about - run time and memory usage to each scenario. - """ + @moduledoc false + + # This module actually runs our benchmark scenarios, adding information about + # run time and memory usage to each scenario. alias Benchee.Benchmark alias Benchee.Benchmark.{Scenario, ScenarioContext, Measure, Hooks, RepeatedMeasurement} diff --git a/test/benchee/benchmark/repeated_measurement_test.exs b/test/benchee/benchmark/repeated_measurement_test.exs new file mode 100644 index 00000000..ded93497 --- /dev/null +++ b/test/benchee/benchmark/repeated_measurement_test.exs @@ -0,0 +1,115 @@ +defmodule Bencheee.Benchmark.RepeatedMeasurementTest.FakeMeasurer do + @behaviour Benchee.Benchmark.Measure + + def measure(function) do + value = function.() + time = Process.get(:test_measurement_time, 5) + next_value = time * 10 + + Process.put(:test_measurement_time, next_value) + + {time, value} + end +end + +defmodule Bencheee.Benchmark.RepeatedMeasurementTest do + use ExUnit.Case + + import Benchee.Benchmark.RepeatedMeasurement + alias Benchee.Benchmark.{Scenario, ScenarioContext} + alias Benchee.Test.FakeBenchmarkPrinter + alias Bencheee.Benchmark.RepeatedMeasurementTest.FakeMeasurer + + @no_input Benchee.Benchmark.no_input() + @scenario_context %ScenarioContext{ + num_iterations: 1, + printer: FakeBenchmarkPrinter, + config: %Benchee.Configuration{}, + scenario_input: @no_input + } + + describe ".determine_n_times/4" do + test "it repeats the function calls until a suitable time is reached" do + function = fn -> send(self(), :called) end + scenario = %Scenario{function: function} + {num_iterations, time} = determine_n_times(scenario, @scenario_context, false, FakeMeasurer) + + assert num_iterations == 10 + assert time == 5 # 50 adjusted by the 10 iteration factor + + assert_received_exactly_n_times(:called, 11) # 1 initial + 10 more after repeat + end + + test "doesn't do repetitions if the time is small enough from the get go" do + function = fn -> send(self(), :called) end + scenario = %Scenario{function: function} + Process.put(:test_measurement_time, 10) + + {num_iterations, time} = determine_n_times(scenario, @scenario_context, false, FakeMeasurer) + + assert num_iterations == 1 + assert time == 10 + + assert_received_exactly_n_times(:called, 1) # 1 initial + 10 more after repeat + end + end + + describe ".measure" do + test "scales reported times approproately" do + scenario_context = %ScenarioContext{ + @scenario_context + | num_iterations: 10, + } + scenario = %Scenario{ + input: @no_input, + function: fn -> 42 end + } + Process.put(:test_measurement_time, 50) + + time = measure(scenario, scenario_context, FakeMeasurer) + + assert time == 5 + end + + test "calls hooks appropriately even with multiple iterations" do + num_iterations = 10 + scenario_context = %ScenarioContext{ + @scenario_context + | num_iterations: num_iterations, + config: %Benchee.Configuration{ + before_each: fn _ -> + send self(), :global_before + @no_input + end, + after_each: fn _ -> send self(), :global_after end + } + } + scenario = %Scenario{ + input: @no_input, + function: fn -> send(self(), :called) end, + before_each: fn _ -> + send self(), :local_before + @no_input + end, + after_each: fn _ -> send self(), :local_after end + } + Process.put(:test_measurement_time, 50) + + time = measure(scenario, scenario_context, FakeMeasurer) + + assert time == 5 + + expected_messages = [:global_before, :local_before, :called, :local_after, :global_after] + + Enum.each(expected_messages, fn message -> + assert_received_exactly_n_times(message, num_iterations) + end) + end + end + + defp assert_received_exactly_n_times(message, count) do + Enum.each(1..count, fn _ -> assert_received ^message end) + + refute_received ^message + end +end From dd5393b48f5fb50447747d36fc9e425c170e37dd Mon Sep 17 00:00:00 2001 From: Tobias Pfeiffer Date: Mon, 21 May 2018 10:04:41 +0200 Subject: [PATCH 9/9] be more private about our modules --- lib/benchee/benchmark/measure.ex | 8 ++++---- lib/benchee/benchmark/measure/memory.ex | 8 ++++---- lib/benchee/benchmark/measure/native_time.ex | 10 +++++----- lib/benchee/benchmark/measure/time.ex | 16 ++++++++-------- lib/benchee/benchmark/repeated_measurement.ex | 1 + lib/benchee/benchmark/scenario_context.ex | 7 ++++--- 6 files changed, 26 insertions(+), 24 deletions(-) diff --git a/lib/benchee/benchmark/measure.ex b/lib/benchee/benchmark/measure.ex index 464514f4..2ab29a10 100644 --- a/lib/benchee/benchmark/measure.ex +++ b/lib/benchee/benchmark/measure.ex @@ -1,8 +1,8 @@ defmodule Benchee.Benchmark.Measure do - @moduledoc """ - A thing that measures something about a function execution - like time or - memory needed. - """ + @moduledoc false + + # A thing that measures something about a function execution - like time or + # memory needed. @doc """ Takes an anonymous 0 arity function to measure and returns the measurement diff --git a/lib/benchee/benchmark/measure/memory.ex b/lib/benchee/benchmark/measure/memory.ex index 9587e335..6017a462 100644 --- a/lib/benchee/benchmark/measure/memory.ex +++ b/lib/benchee/benchmark/measure/memory.ex @@ -1,9 +1,9 @@ defmodule Benchee.Benchmark.Measure.Memory do - @moduledoc """ - Measure memory consumption of a function. + @moduledoc false - Returns `{nil, return_value}` in case the memory measurement went bad. - """ + # Measure memory consumption of a function. + # + # Returns `{nil, return_value}` in case the memory measurement went bad. @behaviour Benchee.Benchmark.Measure diff --git a/lib/benchee/benchmark/measure/native_time.ex b/lib/benchee/benchmark/measure/native_time.ex index 0d3ec8f4..d60527a8 100644 --- a/lib/benchee/benchmark/measure/native_time.ex +++ b/lib/benchee/benchmark/measure/native_time.ex @@ -1,10 +1,10 @@ defmodule Benchee.Benchmark.Measure.NativeTime do - @moduledoc """ - Measure the time elapsed while executing a given function. + @moduledoc false - Uses only the time unit native to the platform. Used for determining how many times a function - should be repeated in `Benchee.Benchmark.Runner.determine_n_times/3` (private method though). - """ + # Measure the time elapsed while executing a given function. + # + # Uses only the time unit native to the platform. Used for determining how many times a function + # should be repeated in `Benchee.Benchmark.Runner.determine_n_times/3` (private method though). @behaviour Benchee.Benchmark.Measure diff --git a/lib/benchee/benchmark/measure/time.ex b/lib/benchee/benchmark/measure/time.ex index e17838c9..a0898780 100644 --- a/lib/benchee/benchmark/measure/time.ex +++ b/lib/benchee/benchmark/measure/time.ex @@ -1,13 +1,13 @@ defmodule Benchee.Benchmark.Measure.Time do - @moduledoc """ - Measure the time elapsed while executing a given function. + @moduledoc false - In contrast to `:timer.tc/1` it always returns the result in nano seconds instead of micro - seconds. This helps us avoid losing precision as both Linux and MacOSX seem to be able to - measure in nano seconds. `:timer.tc/n` - [forfeits this precision]( - https://github.com/erlang/otp/blob/master/lib/stdlib/src/timer.erl#L164-L169). - """ + # Measure the time elapsed while executing a given function. + # + # In contrast to `:timer.tc/1` it always returns the result in nano seconds instead of micro + # seconds. This helps us avoid losing precision as both Linux and MacOSX seem to be able to + # measure in nano seconds. `:timer.tc/n` + # [forfeits this precision]( + # https://github.com/erlang/otp/blob/master/lib/stdlib/src/timer.erl#L164-L169). @behaviour Benchee.Benchmark.Measure diff --git a/lib/benchee/benchmark/repeated_measurement.ex b/lib/benchee/benchmark/repeated_measurement.ex index 750d700e..6f79a606 100644 --- a/lib/benchee/benchmark/repeated_measurement.ex +++ b/lib/benchee/benchmark/repeated_measurement.ex @@ -1,5 +1,6 @@ defmodule Benchee.Benchmark.RepeatedMeasurement do @moduledoc false + # This module is an internal implementation detail, and should absolutely not be relied upon # from external clients. # diff --git a/lib/benchee/benchmark/scenario_context.ex b/lib/benchee/benchmark/scenario_context.ex index f7983675..18e8c5ec 100644 --- a/lib/benchee/benchmark/scenario_context.ex +++ b/lib/benchee/benchmark/scenario_context.ex @@ -1,7 +1,8 @@ defmodule Benchee.Benchmark.ScenarioContext do - @moduledoc """ - This struct holds the context in which any scenario is run. - """ + @moduledoc false + + # This struct holds the context in which any scenario is run. + defstruct [ :config, :printer,