From b97850391ba0177f9383d85bec8e7fa951db48e5 Mon Sep 17 00:00:00 2001 From: Tobias Pfeiffer Date: Sun, 13 Feb 2022 17:19:23 +0100 Subject: [PATCH 01/10] First full stab at fixing the MacOSX time emasurements It's been way too long... this should _mostly_ fix it. In essence, check the resolution and adjust our running results. Contains some on the side fixes to the reporting around it. --- .tool-versions | 2 +- lib/benchee/benchmark/repeated_measurement.ex | 24 ++++-- lib/benchee/output/benchmark_printer.ex | 5 +- .../benchmark/repeated_measurement_test.exs | 86 +++++++++++++++++-- test/test_helper.exs | 2 +- 5 files changed, 100 insertions(+), 19 deletions(-) diff --git a/.tool-versions b/.tool-versions index a16efcb7..050fad40 100644 --- a/.tool-versions +++ b/.tool-versions @@ -1,2 +1,2 @@ elixir 1.10.3-otp-22 -erlang 22.3 +erlang 22.3.4.24 diff --git a/lib/benchee/benchmark/repeated_measurement.ex b/lib/benchee/benchmark/repeated_measurement.ex index 6ab6a2f8..f26ebdca 100644 --- a/lib/benchee/benchmark/repeated_measurement.ex +++ b/lib/benchee/benchmark/repeated_measurement.ex @@ -10,8 +10,8 @@ defmodule Benchee.Benchmark.RepeatedMeasurement do # 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 + # Today this is mostly only relevant on Windows & Mac OS as we have nanosecond precision on + # Linux 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 @@ -27,6 +27,8 @@ defmodule Benchee.Benchmark.RepeatedMeasurement do @minimum_execution_time 10 @times_multiplier 10 + @nanosecond_resolution Benchee.Conversion.Duration.convert_value({1, :second}, :nanosecond) + @spec determine_n_times(Scenario.t(), ScenarioContext.t(), boolean, module) :: {pos_integer, number} def determine_n_times( @@ -35,22 +37,30 @@ defmodule Benchee.Benchmark.RepeatedMeasurement do num_iterations: num_iterations, printer: printer }, - fast_warning, - collector \\ Collect.NativeTime + print_fast_warning, + collector \\ Collect.Time, + clock_info \\ :erlang.system_info(:os_monotonic_time_source) ) do run_time = measure_iteration(scenario, scenario_context, collector) + resolution = Access.fetch!(clock_info, :resolution) + # If the resolution is 1_000_000 that means microsecond, while 1_000_000_000 is nanosecond. + # we then need to adjust our measured time by that value. I.e. if we measured "5000" here we + # do not want to let it pass as it is essentially just "5" for our measurement purposes. + resolution_nanoscond_adjustment = @nanosecond_resolution / resolution + + resolution_adjusted_run_time = run_time / resolution_nanoscond_adjustment - if run_time >= @minimum_execution_time do + if resolution_adjusted_run_time >= @minimum_execution_time do {num_iterations, report_time(run_time, num_iterations)} else - if fast_warning, do: printer.fast_warning() + if print_fast_warning, do: printer.fast_warning() new_context = %ScenarioContext{ scenario_context | num_iterations: num_iterations * @times_multiplier } - determine_n_times(scenario, new_context, false, collector) + determine_n_times(scenario, new_context, false, collector, clock_info) end end diff --git a/lib/benchee/output/benchmark_printer.ex b/lib/benchee/output/benchmark_printer.ex index dd889ae0..95fe4b19 100644 --- a/lib/benchee/output/benchmark_printer.ex +++ b/lib/benchee/output/benchmark_printer.ex @@ -99,8 +99,9 @@ defmodule Benchee.Output.BenchmarkPrinter do def fast_warning do IO.puts(""" Warning: The function you are trying to benchmark is super fast, making measurements more unreliable! - This holds especially true for memory measurements. - See: https://github.com/PragTob/benchee/wiki/Benchee-Warnings#fast-execution-warning + This holds especially true for memory measurements or when running with hooks. + + See: https://github.com/bencheeorg/benchee/wiki/Benchee-Warnings#fast-execution-warning You may disable this warning by passing print: [fast_warning: false] as configuration options. """) diff --git a/test/benchee/benchmark/repeated_measurement_test.exs b/test/benchee/benchmark/repeated_measurement_test.exs index 7a30c6be..be6b3df8 100644 --- a/test/benchee/benchmark/repeated_measurement_test.exs +++ b/test/benchee/benchmark/repeated_measurement_test.exs @@ -3,7 +3,7 @@ defmodule Bencheee.Benchmark.RepeatedMeasurementTest.FakeCollector do def collect(function) do value = function.() - time = Process.get(:test_measurement_time, 5) + time = Process.get(:test_measurement_time) next_value = time * 10 Process.put(:test_measurement_time, next_value) @@ -13,7 +13,7 @@ defmodule Bencheee.Benchmark.RepeatedMeasurementTest.FakeCollector do end defmodule Bencheee.Benchmark.RepeatedMeasurementTest do - use ExUnit.Case + use ExUnit.Case, async: true import Benchee.Benchmark.RepeatedMeasurement alias Benchee.Benchmark.ScenarioContext @@ -29,33 +29,103 @@ defmodule Bencheee.Benchmark.RepeatedMeasurementTest do scenario_input: @no_input } + # Linux (mostly) + @nano_second_accuracy_clock [ + resolution: Benchee.Conversion.Duration.convert_value({1, :second}, :nanosecond) + ] + + # MacOS (mostly, it seems) + @micro_second_accuracy_clock [ + resolution: Benchee.Conversion.Duration.convert_value({1, :second}, :microsecond) + ] + 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} + function_run_time = 5 + Process.put(:test_measurement_time, function_run_time) {num_iterations, time} = - determine_n_times(scenario, @scenario_context, false, FakeCollector) + determine_n_times( + scenario, + @scenario_context, + false, + FakeCollector, + @nano_second_accuracy_clock + ) assert num_iterations == 10 # 50 adjusted by the 10 iteration factor - # we need to use convert_time_unit cos windows is funny, see: - # https://twitter.com/PragTob/status/1108024728734838784 - expected_time = :erlang.convert_time_unit(5, :native, :nanosecond) - assert_in_delta time, expected_time, 1 + assert_in_delta time, function_run_time, 1 + + # 1 initial + 10 more after repeat + assert_received_exactly_n_times(:called, 11) + end + + # https://github.com/bencheeorg/benchee/issues/313 + test "it repeats the function calls until a suitable time is reached even with micro second clocks" do + function = fn -> send(self(), :called) end + scenario = %Scenario{function: function} + + function_run_time = 1000 + Process.put(:test_measurement_time, function_run_time) + + {num_iterations, time} = + determine_n_times( + scenario, + @scenario_context, + false, + FakeCollector, + @micro_second_accuracy_clock + ) + + assert num_iterations == 10 + + assert_in_delta time, function_run_time, 1 # 1 initial + 10 more after repeat assert_received_exactly_n_times(:called, 11) end + test "it repeats the function calls even more times to reach a doable time" do + function = fn -> send(self(), :called) end + scenario = %Scenario{function: function} + + function_run_time = 10 + Process.put(:test_measurement_time, function_run_time) + + {num_iterations, time} = + determine_n_times( + scenario, + @scenario_context, + false, + FakeCollector, + @micro_second_accuracy_clock + ) + + assert num_iterations == 1000 + + assert_in_delta time, function_run_time, 1 + + # 1 initial + 10 + 100 + 1000 + assert_received_exactly_n_times(:called, 1111) + 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, FakeCollector) + determine_n_times( + scenario, + @scenario_context, + false, + FakeCollector, + @nano_second_accuracy_clock + ) assert num_iterations == 1 diff --git a/test/test_helper.exs b/test/test_helper.exs index 94777f60..493e0627 100644 --- a/test/test_helper.exs +++ b/test/test_helper.exs @@ -12,7 +12,7 @@ exclusions = [{:performance, true} | exclusions] :darwin -> - [{:performance, true}, {:needs_fast_function_repetition, true}] ++ exclusions + [{:performance, true} | exclusions] _ -> # with our new nanosecond accuracy we can't trigger our super fast function code From ba293033abc6c39c378707278918ea7017d1bc0b Mon Sep 17 00:00:00 2001 From: Tobias Pfeiffer Date: Sun, 13 Feb 2022 17:28:12 +0100 Subject: [PATCH 02/10] Only call out to get the clock once as the clock info does not change --- lib/benchee/benchmark/repeated_measurement.ex | 39 ++++++++++++++----- 1 file changed, 30 insertions(+), 9 deletions(-) diff --git a/lib/benchee/benchmark/repeated_measurement.ex b/lib/benchee/benchmark/repeated_measurement.ex index f26ebdca..43aebedf 100644 --- a/lib/benchee/benchmark/repeated_measurement.ex +++ b/lib/benchee/benchmark/repeated_measurement.ex @@ -33,22 +33,43 @@ defmodule Benchee.Benchmark.RepeatedMeasurement do {pos_integer, number} def determine_n_times( scenario, - scenario_context = %ScenarioContext{ - num_iterations: num_iterations, - printer: printer - }, + scenario_context, print_fast_warning, collector \\ Collect.Time, clock_info \\ :erlang.system_info(:os_monotonic_time_source) ) do - run_time = measure_iteration(scenario, scenario_context, collector) - resolution = Access.fetch!(clock_info, :resolution) + resolution_adjustment = determine_resolution_adjustment(clock_info) + + do_determine_n_times( + scenario, + scenario_context, + print_fast_warning, + collector, + resolution_adjustment + ) + end + + defp determine_resolution_adjustment(clock_info) do # If the resolution is 1_000_000 that means microsecond, while 1_000_000_000 is nanosecond. # we then need to adjust our measured time by that value. I.e. if we measured "5000" here we # do not want to let it pass as it is essentially just "5" for our measurement purposes. - resolution_nanoscond_adjustment = @nanosecond_resolution / resolution + resolution = Access.fetch!(clock_info, :resolution) - resolution_adjusted_run_time = run_time / resolution_nanoscond_adjustment + @nanosecond_resolution / resolution + end + + defp do_determine_n_times( + scenario, + scenario_context = %ScenarioContext{ + num_iterations: num_iterations, + printer: printer + }, + print_fast_warning, + collector, + resolution_adjustment + ) do + run_time = measure_iteration(scenario, scenario_context, collector) + resolution_adjusted_run_time = run_time / resolution_adjustment if resolution_adjusted_run_time >= @minimum_execution_time do {num_iterations, report_time(run_time, num_iterations)} @@ -60,7 +81,7 @@ defmodule Benchee.Benchmark.RepeatedMeasurement do | num_iterations: num_iterations * @times_multiplier } - determine_n_times(scenario, new_context, false, collector, clock_info) + do_determine_n_times(scenario, new_context, false, collector, resolution_adjustment) end end From 68eb522de037ab68e578714fd9773d1c35e0dd79 Mon Sep 17 00:00:00 2001 From: Tobias Pfeiffer Date: Sun, 13 Feb 2022 19:40:23 +0100 Subject: [PATCH 03/10] Work around the faulty erlang version actively This was way more work than anticipated. But basically, if the erlang version is beloe 22.2 and it is macOS, do not trust the time at all and instead assume microseconds. --- lib/benchee/benchmark.ex | 4 +- lib/benchee/benchmark/repeated_measurement.ex | 50 ++++--- lib/benchee/benchmark/scenario_context.ex | 1 + lib/benchee/utility/erlang_version.ex | 124 ++++++++++++++++++ .../benchmark/repeated_measurement_test.exs | 110 ++++++++++++++-- test/benchee/utility/erlang_version_test.exs | 5 + 6 files changed, 264 insertions(+), 30 deletions(-) create mode 100644 lib/benchee/utility/erlang_version.ex create mode 100644 test/benchee/utility/erlang_version_test.exs diff --git a/lib/benchee/benchmark.ex b/lib/benchee/benchmark.ex index 3cf41699..368874bb 100644 --- a/lib/benchee/benchmark.ex +++ b/lib/benchee/benchmark.ex @@ -94,12 +94,12 @@ defmodule Benchee.Benchmark do """ @spec collect(Suite.t(), module, module) :: Suite.t() def collect( - suite = %Suite{scenarios: scenarios, configuration: config}, + suite = %Suite{scenarios: scenarios, configuration: config, system: system}, printer \\ Printer, runner \\ Runner ) do printer.configuration_information(suite) - scenario_context = %ScenarioContext{config: config, printer: printer} + scenario_context = %ScenarioContext{config: config, printer: printer, system: system} scenarios = runner.run_scenarios(scenarios, scenario_context) %Suite{suite | scenarios: scenarios} end diff --git a/lib/benchee/benchmark/repeated_measurement.ex b/lib/benchee/benchmark/repeated_measurement.ex index 43aebedf..146eb449 100644 --- a/lib/benchee/benchmark/repeated_measurement.ex +++ b/lib/benchee/benchmark/repeated_measurement.ex @@ -23,6 +23,7 @@ defmodule Benchee.Benchmark.RepeatedMeasurement do alias Benchee.Benchmark.{Collect, Hooks, Runner, ScenarioContext} alias Benchee.Scenario + alias Benchee.Utility.ErlangVersion alias Benchee.Utility.RepeatN @minimum_execution_time 10 @@ -33,31 +34,50 @@ defmodule Benchee.Benchmark.RepeatedMeasurement do {pos_integer, number} def determine_n_times( scenario, - scenario_context, + scenario_context = %ScenarioContext{system: system_info}, print_fast_warning, - collector \\ Collect.Time, - clock_info \\ :erlang.system_info(:os_monotonic_time_source) + clock_info \\ :erlang.system_info(:os_monotonic_time_source), + collector \\ Collect.Time ) do - resolution_adjustment = determine_resolution_adjustment(clock_info) + resolution_adjustment = determine_resolution_adjustment(system_info, clock_info) do_determine_n_times( scenario, scenario_context, print_fast_warning, - collector, - resolution_adjustment + resolution_adjustment, + collector ) end - defp determine_resolution_adjustment(clock_info) do - # If the resolution is 1_000_000 that means microsecond, while 1_000_000_000 is nanosecond. - # we then need to adjust our measured time by that value. I.e. if we measured "5000" here we - # do not want to let it pass as it is essentially just "5" for our measurement purposes. - resolution = Access.fetch!(clock_info, :resolution) + # See ERL-1067 aka which was fixed here + # https://erlang.org/download/otp_src_22.2.readme + @fixed_erlang_vesion "22.2.0" + # MacOS usually measures in micro seconds so that's the best default to return when not given + @old_macos_value 1_000 - @nanosecond_resolution / resolution + defp determine_resolution_adjustment(system_info, clock_info) do + if trust_clock?(system_info) do + # If the resolution is 1_000_000 that means microsecond, while 1_000_000_000 is nanosecond. + # we then need to adjust our measured time by that value. I.e. if we measured "5000" here we + # do not want to let it pass as it is essentially just "5" for our measurement purposes. + resolution = Access.fetch!(clock_info, :resolution) + + @nanosecond_resolution / resolution + else + @old_macos_value + end end + # Can't really trust the macOS clock on OTP before mentioned version, see tickets linked above + defp trust_clock?(%{os: :macOS, erlang: erlang_version}) do + ErlangVersion.includes_fixes_from?(erlang_version, @fixed_erlang_vesion) + end + + # If `suite.system` wasn't populated then we'll not mistrust it as well as all others + # (can happen if people call parts of benchee themselves without calling system first) + defp trust_clock?(_), do: true + defp do_determine_n_times( scenario, scenario_context = %ScenarioContext{ @@ -65,8 +85,8 @@ defmodule Benchee.Benchmark.RepeatedMeasurement do printer: printer }, print_fast_warning, - collector, - resolution_adjustment + resolution_adjustment, + collector ) do run_time = measure_iteration(scenario, scenario_context, collector) resolution_adjusted_run_time = run_time / resolution_adjustment @@ -81,7 +101,7 @@ defmodule Benchee.Benchmark.RepeatedMeasurement do | num_iterations: num_iterations * @times_multiplier } - do_determine_n_times(scenario, new_context, false, collector, resolution_adjustment) + do_determine_n_times(scenario, new_context, false, resolution_adjustment, collector) end end diff --git a/lib/benchee/benchmark/scenario_context.ex b/lib/benchee/benchmark/scenario_context.ex index ff2d0737..b5966f8a 100644 --- a/lib/benchee/benchmark/scenario_context.ex +++ b/lib/benchee/benchmark/scenario_context.ex @@ -6,6 +6,7 @@ defmodule Benchee.Benchmark.ScenarioContext do defstruct [ :config, :printer, + :system, :current_time, :end_time, # before_scenario can alter the original input diff --git a/lib/benchee/utility/erlang_version.ex b/lib/benchee/utility/erlang_version.ex new file mode 100644 index 00000000..e7c2c809 --- /dev/null +++ b/lib/benchee/utility/erlang_version.ex @@ -0,0 +1,124 @@ +defmodule Benchee.Utility.ErlangVersion do + @moduledoc false + + # Internal module to deal with erlang version parsing oddity + + @doc """ + Was the given version before the reference version? + + Used to check if a bugfix has already landed. + + Applies some manual massaging, as erlang likes to report versios number not compatible with + SemVer. If we can't parse the version, to minimize false positives, we assume it's newer. + + Only the `version_to_check` is treated loosely. `version_to_check` must be SemVer compatible, + as it is assumed to be provided by project maintainers. + + ## Examples + + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("22.0.0", "22.0.0") + true + + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("22.0.1", "22.0.0") + true + + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("22.0.0", "22.0.1") + false + + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("22.0.4", "22.0.5") + false + + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("22.0.4", "22.0.4") + true + + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("22.0.5", "22.0.4") + true + + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("21.999.9999", "22.0.0") + false + + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("23.0.0", "22.0.0") + true + + # weird longer version numbers work + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("22.0.0.0", "22.0.0") + true + + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("22.0.0.14", "22.0.0") + true + + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("23.3.5.14", "22.0.0") + true + + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("21.3.5.14", "22.0.0") + false + + # weird shorter version numbers work + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("22.0", "22.0.0") + true + + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("22.0", "22.0.1") + false + + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("22.1", "22.0.0") + true + + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("21.3", "22.0.0") + false + + # rc version numbers work + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("22.0-rc3", "22.0.0") + false + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("23.0-rc0", "22.0.0") + true + + # completely broken versions are assumed to be good to avoid false positives + # as this is not a main functionality but code to potentially work around an older erlang + # bug. + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("super erlang", "22.0.0") + true + iex> Benchee.Utility.ErlangVersion.includes_fixes_from?("", "22.0.0") + true + """ + def includes_fixes_from?(version_to_check, reference_version) do + erlang_version = parse_erlang_version(version_to_check) + + case erlang_version do + {:ok, version} -> Version.compare(version, reference_version) != :lt + # we do not know which version this is, so don't trust it? + _ -> true + end + end + + # `Version` only supports full SemVer, Erlang loves version numbers like `22.3.4.24` or `22.0` + # which makes `Version` error out so we gotta manually alter them so that it's `22.3.4` + @last_version_segment ~r/\.\d+$/ + defp parse_erlang_version(erlang_version) do + # dot count is a heuristic but it should work + dot_count = + erlang_version + |> String.graphemes() + |> Enum.count(&(&1 == ".")) + + version = + case dot_count do + 3 -> Regex.replace(@last_version_segment, erlang_version, "") + 1 -> deal_with_major_minor(erlang_version) + _ -> erlang_version + end + + Version.parse(version) + end + + # Only major/minor seem to get the rc treatment + # but if it is major/minor/patch `Version` handles it correctly. + # For the 4 digit versions we don't really care right now/normally does not happen. + defp deal_with_major_minor(erlang_version) do + # -rc and other weird versions contain - + if String.contains?(erlang_version, "-") do + String.replace(erlang_version, "-", ".0-") + else + "#{erlang_version}.0" + end + end +end diff --git a/test/benchee/benchmark/repeated_measurement_test.exs b/test/benchee/benchmark/repeated_measurement_test.exs index be6b3df8..a9320b14 100644 --- a/test/benchee/benchmark/repeated_measurement_test.exs +++ b/test/benchee/benchmark/repeated_measurement_test.exs @@ -21,12 +21,17 @@ defmodule Bencheee.Benchmark.RepeatedMeasurementTest do alias Benchee.Test.FakeBenchmarkPrinter alias Bencheee.Benchmark.RepeatedMeasurementTest.FakeCollector + @good_system_info %{erlang: "24.0.2"} + @macos_fixed_system_info %{os: :macOS, erlang: "22.2"} + @macos_broken_system_info %{os: :macOS, erlang: "22.1.34"} + @no_input Benchee.Benchmark.no_input() @scenario_context %ScenarioContext{ num_iterations: 1, printer: FakeBenchmarkPrinter, config: %Benchee.Configuration{}, - scenario_input: @no_input + scenario_input: @no_input, + system: @good_system_info } # Linux (mostly) @@ -51,8 +56,8 @@ defmodule Bencheee.Benchmark.RepeatedMeasurementTest do scenario, @scenario_context, false, - FakeCollector, - @nano_second_accuracy_clock + @nano_second_accuracy_clock, + FakeCollector ) assert num_iterations == 10 @@ -77,8 +82,8 @@ defmodule Bencheee.Benchmark.RepeatedMeasurementTest do scenario, @scenario_context, false, - FakeCollector, - @micro_second_accuracy_clock + @micro_second_accuracy_clock, + FakeCollector ) assert num_iterations == 10 @@ -101,8 +106,8 @@ defmodule Bencheee.Benchmark.RepeatedMeasurementTest do scenario, @scenario_context, false, - FakeCollector, - @micro_second_accuracy_clock + @micro_second_accuracy_clock, + FakeCollector ) assert num_iterations == 1000 @@ -116,26 +121,105 @@ defmodule Bencheee.Benchmark.RepeatedMeasurementTest do 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) + function_time = 10 + Process.put(:test_measurement_time, function_time) {num_iterations, time} = determine_n_times( scenario, @scenario_context, false, - FakeCollector, - @nano_second_accuracy_clock + @nano_second_accuracy_clock, + FakeCollector ) assert num_iterations == 1 - # Why erlang time conversion? See test above. - expected_time = :erlang.convert_time_unit(10, :native, :nanosecond) - assert_in_delta time, expected_time, 1 + assert_in_delta time, function_time, 1 # 1 initial + 10 more after repeat assert_received_exactly_n_times(:called, 1) end + + test "trusts the clock if no system information is present" do + function = fn -> send(self(), :called) end + scenario = %Scenario{function: function} + function_run_time = 100 + Process.put(:test_measurement_time, function_run_time) + + {num_iterations, time} = + determine_n_times( + scenario, + %{@scenario_context | system: nil}, + false, + @nano_second_accuracy_clock, + FakeCollector + ) + + assert num_iterations == 1 + assert_in_delta time, function_run_time, 1 + assert_received_exactly_n_times(:called, 1) + end + + test "trusts the clock on a good system" do + function = fn -> send(self(), :called) end + scenario = %Scenario{function: function} + function_run_time = 100 + Process.put(:test_measurement_time, function_run_time) + + {num_iterations, time} = + determine_n_times( + scenario, + %{@scenario_context | system: @good_system_info}, + false, + @nano_second_accuracy_clock, + FakeCollector + ) + + assert num_iterations == 1 + assert_in_delta time, function_run_time, 1 + assert_received_exactly_n_times(:called, 1) + end + + test "trusts the clock on macOS but with a fixed OTP version" do + function = fn -> send(self(), :called) end + scenario = %Scenario{function: function} + function_run_time = 100 + Process.put(:test_measurement_time, function_run_time) + + {num_iterations, time} = + determine_n_times( + scenario, + %{@scenario_context | system: @macos_fixed_system_info}, + false, + @nano_second_accuracy_clock, + FakeCollector + ) + + assert num_iterations == 1 + assert_in_delta time, function_run_time, 1 + assert_received_exactly_n_times(:called, 1) + end + + test "does not trust the macOS clock on a broken OTP version, repeating the calls assuming milliseconds" do + function = fn -> send(self(), :called) end + scenario = %Scenario{function: function} + function_run_time = 100 + Process.put(:test_measurement_time, function_run_time) + + {num_iterations, time} = + determine_n_times( + scenario, + %{@scenario_context | system: @macos_broken_system_info}, + false, + @nano_second_accuracy_clock, + FakeCollector + ) + + assert num_iterations == 100 + assert_in_delta time, function_run_time, 1 + assert_received_exactly_n_times(:called, 111) + end end describe "collect/3" do diff --git a/test/benchee/utility/erlang_version_test.exs b/test/benchee/utility/erlang_version_test.exs new file mode 100644 index 00000000..3e613c25 --- /dev/null +++ b/test/benchee/utility/erlang_version_test.exs @@ -0,0 +1,5 @@ +defmodule Benchee.Utility.ErlangVersionTest do + use ExUnit.Case, async: true + + doctest Benchee.Utility.ErlangVersion +end From 4ea2aa15335d9df3e8d0ce788359a30b4c65ba5e Mon Sep 17 00:00:00 2001 From: Tobias Pfeiffer Date: Sun, 13 Feb 2022 21:04:23 +0100 Subject: [PATCH 04/10] Fix tests failing on Windows + make tests more beautiful --- .../benchmark/repeated_measurement_test.exs | 130 +++++------------- 1 file changed, 38 insertions(+), 92 deletions(-) diff --git a/test/benchee/benchmark/repeated_measurement_test.exs b/test/benchee/benchmark/repeated_measurement_test.exs index a9320b14..1c5b177d 100644 --- a/test/benchee/benchmark/repeated_measurement_test.exs +++ b/test/benchee/benchmark/repeated_measurement_test.exs @@ -46,115 +46,56 @@ defmodule Bencheee.Benchmark.RepeatedMeasurementTest do 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} function_run_time = 5 - Process.put(:test_measurement_time, function_run_time) - {num_iterations, time} = - determine_n_times( - scenario, - @scenario_context, - false, - @nano_second_accuracy_clock, - FakeCollector - ) + {num_iterations, time} = run_function_taking(function_run_time) assert num_iterations == 10 - - # 50 adjusted by the 10 iteration factor assert_in_delta time, function_run_time, 1 - # 1 initial + 10 more after repeat assert_received_exactly_n_times(:called, 11) end # https://github.com/bencheeorg/benchee/issues/313 test "it repeats the function calls until a suitable time is reached even with micro second clocks" do - function = fn -> send(self(), :called) end - scenario = %Scenario{function: function} - function_run_time = 1000 - Process.put(:test_measurement_time, function_run_time) {num_iterations, time} = - determine_n_times( - scenario, - @scenario_context, - false, - @micro_second_accuracy_clock, - FakeCollector - ) + run_function_taking(function_run_time, clock: @micro_second_accuracy_clock) assert num_iterations == 10 - assert_in_delta time, function_run_time, 1 - # 1 initial + 10 more after repeat assert_received_exactly_n_times(:called, 11) end test "it repeats the function calls even more times to reach a doable time" do - function = fn -> send(self(), :called) end - scenario = %Scenario{function: function} - function_run_time = 10 - Process.put(:test_measurement_time, function_run_time) {num_iterations, time} = - determine_n_times( - scenario, - @scenario_context, - false, - @micro_second_accuracy_clock, - FakeCollector - ) + run_function_taking(function_run_time, clock: @micro_second_accuracy_clock) assert num_iterations == 1000 - assert_in_delta time, function_run_time, 1 - # 1 initial + 10 + 100 + 1000 assert_received_exactly_n_times(:called, 1111) 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} + test "doesn't do repetitions if the time is big enough from the get go" do function_time = 10 - Process.put(:test_measurement_time, function_time) - {num_iterations, time} = - determine_n_times( - scenario, - @scenario_context, - false, - @nano_second_accuracy_clock, - FakeCollector - ) + {num_iterations, time} = run_function_taking(function_time) assert num_iterations == 1 - assert_in_delta time, function_time, 1 - - # 1 initial + 10 more after repeat assert_received_exactly_n_times(:called, 1) end test "trusts the clock if no system information is present" do - function = fn -> send(self(), :called) end - scenario = %Scenario{function: function} function_run_time = 100 - Process.put(:test_measurement_time, function_run_time) {num_iterations, time} = - determine_n_times( - scenario, - %{@scenario_context | system: nil}, - false, - @nano_second_accuracy_clock, - FakeCollector - ) + run_function_taking(function_run_time, system: nil, clock: @nano_second_accuracy_clock) assert num_iterations == 1 assert_in_delta time, function_run_time, 1 @@ -162,18 +103,12 @@ defmodule Bencheee.Benchmark.RepeatedMeasurementTest do end test "trusts the clock on a good system" do - function = fn -> send(self(), :called) end - scenario = %Scenario{function: function} function_run_time = 100 - Process.put(:test_measurement_time, function_run_time) {num_iterations, time} = - determine_n_times( - scenario, - %{@scenario_context | system: @good_system_info}, - false, - @nano_second_accuracy_clock, - FakeCollector + run_function_taking(function_run_time, + system: @good_system_info, + clock: @nano_second_accuracy_clock ) assert num_iterations == 1 @@ -182,18 +117,12 @@ defmodule Bencheee.Benchmark.RepeatedMeasurementTest do end test "trusts the clock on macOS but with a fixed OTP version" do - function = fn -> send(self(), :called) end - scenario = %Scenario{function: function} function_run_time = 100 - Process.put(:test_measurement_time, function_run_time) {num_iterations, time} = - determine_n_times( - scenario, - %{@scenario_context | system: @macos_fixed_system_info}, - false, - @nano_second_accuracy_clock, - FakeCollector + run_function_taking(function_run_time, + system: @macos_fixed_system_info, + clock: @nano_second_accuracy_clock ) assert num_iterations == 1 @@ -202,18 +131,12 @@ defmodule Bencheee.Benchmark.RepeatedMeasurementTest do end test "does not trust the macOS clock on a broken OTP version, repeating the calls assuming milliseconds" do - function = fn -> send(self(), :called) end - scenario = %Scenario{function: function} function_run_time = 100 - Process.put(:test_measurement_time, function_run_time) {num_iterations, time} = - determine_n_times( - scenario, - %{@scenario_context | system: @macos_broken_system_info}, - false, - @nano_second_accuracy_clock, - FakeCollector + run_function_taking(function_run_time, + system: @macos_broken_system_info, + clock: @nano_second_accuracy_clock ) assert num_iterations == 100 @@ -280,6 +203,29 @@ defmodule Bencheee.Benchmark.RepeatedMeasurementTest do end end + defp run_function_taking(time_in_nanoseconds, opts \\ []) do + system = Access.get(opts, :system, @good_system_info) + clock = Access.get(opts, :clock, @nano_second_accuracy_clock) + + function = fn -> send(self(), :called) end + scenario = %Scenario{function: function} + + # The reverse of this happens in the measurer so for Windows where the native time unit + # is not nanoseconds we gotta convert this here, but the return value in the test will + # be nanosecond again + function_run_time = :erlang.convert_time_unit(time_in_nanoseconds, :nanosecond, :native) + + Process.put(:test_measurement_time, function_run_time) + + determine_n_times( + scenario, + %{@scenario_context | system: system}, + false, + clock, + FakeCollector + ) + end + defp assert_received_exactly_n_times(message, count) do Enum.each(1..count, fn _ -> assert_received ^message end) From f480e6f67b1eef48a5a303078e16223396b45050 Mon Sep 17 00:00:00 2001 From: Tobias Pfeiffer Date: Sun, 13 Feb 2022 21:06:48 +0100 Subject: [PATCH 05/10] fix backwards incompatible fetch access --- lib/benchee/benchmark/repeated_measurement.ex | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/benchee/benchmark/repeated_measurement.ex b/lib/benchee/benchmark/repeated_measurement.ex index 146eb449..e863eca1 100644 --- a/lib/benchee/benchmark/repeated_measurement.ex +++ b/lib/benchee/benchmark/repeated_measurement.ex @@ -61,7 +61,7 @@ defmodule Benchee.Benchmark.RepeatedMeasurement do # If the resolution is 1_000_000 that means microsecond, while 1_000_000_000 is nanosecond. # we then need to adjust our measured time by that value. I.e. if we measured "5000" here we # do not want to let it pass as it is essentially just "5" for our measurement purposes. - resolution = Access.fetch!(clock_info, :resolution) + {:ok, resolution} = Access.fetch(clock_info, :resolution) @nanosecond_resolution / resolution else From c18cd52881e524059b790b03136eccbeaeb37201 Mon Sep 17 00:00:00 2001 From: Tobias Pfeiffer Date: Sun, 13 Feb 2022 21:17:39 +0100 Subject: [PATCH 06/10] Run tests before dialyzer I distrust dialyzer to a degree and want to see if the tests really fail/what's wrong. --- .github/workflows/main.yml | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/.github/workflows/main.yml b/.github/workflows/main.yml index ada3b8c9..123513d0 100644 --- a/.github/workflows/main.yml +++ b/.github/workflows/main.yml @@ -49,9 +49,10 @@ jobs: - name: Check if formatted if: ${{ contains(matrix.elixir_version, '1.10') }} run: mix format --check-formatted + - name: Actual Tests + run: MIX_ENV=test mix coveralls.github - name: Dialyzer run: mix dialyzer --halt-exit-status - - run: MIX_ENV=test mix coveralls.github - name: After script if: ${{ contains(matrix.elixir_version, '1.10') }} run: mix deps.get --only docs && MIX_ENV=docs mix inch.report From 47ce7fc354e18f5927c150f127657f0daf04a030 Mon Sep 17 00:00:00 2001 From: Tobias Pfeiffer Date: Sun, 13 Feb 2022 21:22:06 +0100 Subject: [PATCH 07/10] Deactivate 1.6.6 x 21 Dialyzer fails here while both 1.6.6 and 21 pass on other versions of elixir and erlang respectively. https://github.com/bencheeorg/benchee/runs/5175942788?check_suite_focus=true --- .github/workflows/main.yml | 3 +++ 1 file changed, 3 insertions(+) diff --git a/.github/workflows/main.yml b/.github/workflows/main.yml index 123513d0..58230e1e 100644 --- a/.github/workflows/main.yml +++ b/.github/workflows/main.yml @@ -18,6 +18,9 @@ jobs: - elixir_version: '1.6.6' otp_version: '19.3' exclude: + # has shown weird behavior when it comes to dialyzer (aka only this one failing) + - elixir_version: '1.6.6' + otp_version: '21.3' - elixir_version: '1.6.6' otp_version: '22.3' - elixir_version: '1.10.3' From 1a4176fc723af9e64f1a633f7f75343d8c914824 Mon Sep 17 00:00:00 2001 From: Tobias Pfeiffer Date: Mon, 14 Feb 2022 18:15:45 +0100 Subject: [PATCH 08/10] Exclude Windows from repeated measurement tests due to weird clock --- test/benchee/benchmark/repeated_measurement_test.exs | 4 ++++ test/test_helper.exs | 2 +- 2 files changed, 5 insertions(+), 1 deletion(-) diff --git a/test/benchee/benchmark/repeated_measurement_test.exs b/test/benchee/benchmark/repeated_measurement_test.exs index 1c5b177d..029342d1 100644 --- a/test/benchee/benchmark/repeated_measurement_test.exs +++ b/test/benchee/benchmark/repeated_measurement_test.exs @@ -44,6 +44,10 @@ defmodule Bencheee.Benchmark.RepeatedMeasurementTest do resolution: Benchee.Conversion.Duration.convert_value({1, :second}, :microsecond) ] + # We need a nano second resolution clock here as we are converting from/with native time + # which on Windows does not exist and loses us time + @moduletag :nanosecond_resolution_clock + describe ".determine_n_times/4" do test "it repeats the function calls until a suitable time is reached" do function_run_time = 5 diff --git a/test/test_helper.exs b/test/test_helper.exs index 493e0627..3804b940 100644 --- a/test/test_helper.exs +++ b/test/test_helper.exs @@ -9,7 +9,7 @@ exclusions = if otp_release > 18, do: [], else: [memory_measure: true] exclusions = case os do :nt -> - [{:performance, true} | exclusions] + [{:performance, true}, {:nanosecond_resolution_clock, true}] ++ exclusions :darwin -> [{:performance, true} | exclusions] From c3048db2272331c6ef7ad240755334d09adff8a7 Mon Sep 17 00:00:00 2001 From: Tobias Pfeiffer Date: Mon, 14 Feb 2022 18:30:53 +0100 Subject: [PATCH 09/10] stop double conversion of values - we use the normal clock so it is fine --- lib/benchee/benchmark/repeated_measurement.ex | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/lib/benchee/benchmark/repeated_measurement.ex b/lib/benchee/benchmark/repeated_measurement.ex index e863eca1..b562bb71 100644 --- a/lib/benchee/benchmark/repeated_measurement.ex +++ b/lib/benchee/benchmark/repeated_measurement.ex @@ -108,9 +108,7 @@ defmodule Benchee.Benchmark.RepeatedMeasurement do # we need to convert the time here since we measure native time to see when we have enough # repetitions but the first time is used in the actual samples defp report_time(measurement, num_iterations) do - measurement - |> :erlang.convert_time_unit(:native, :nanosecond) - |> adjust_for_iterations(num_iterations) + adjust_for_iterations(measurement, num_iterations) end defp adjust_for_iterations(measurement, 1), do: measurement From 6676b8df644165eceeb82c827121f545b0052006 Mon Sep 17 00:00:00 2001 From: Tobias Pfeiffer Date: Mon, 14 Feb 2022 18:31:32 +0100 Subject: [PATCH 10/10] NativeTime is unused now, get rid of it --- lib/benchee/benchmark/collect/native_time.ex | 19 ------------------- 1 file changed, 19 deletions(-) delete mode 100644 lib/benchee/benchmark/collect/native_time.ex diff --git a/lib/benchee/benchmark/collect/native_time.ex b/lib/benchee/benchmark/collect/native_time.ex deleted file mode 100644 index d41f90a2..00000000 --- a/lib/benchee/benchmark/collect/native_time.ex +++ /dev/null @@ -1,19 +0,0 @@ -defmodule Benchee.Benchmark.Collect.NativeTime do - @moduledoc false - - # 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.Collect - - @spec collect((() -> any)) :: {non_neg_integer, any} - def collect(function) do - start = :erlang.monotonic_time() - result = function.() - finish = :erlang.monotonic_time() - - {finish - start, result} - end -end