First run on last benchmark consistently 1+ms off

[mcelaney]

So I have a simple class demonstrating a couple ways to solve the first Euler problem:

defmodule EulerExample do
  @doc """
  Returns the sum of all values below a given number which are multiples
  of 3 or 5.

  This example uses a Stream to lazy load desired values. I expect it to be
  faster with much larger values.

  ## Example

      iex> EulerExample.sum_of_multiples(10)
      23
  """
  @spec sum_of_multiples_1(integer) :: integer
  def sum_of_multiples_1(value) do
    value
    |> find_range
    |> create_stream_of_desired_values
    |> Enum.sum
  end

  @doc """
  Returns the sum of all values below a given number which are multiples
  of 3 or 5.

  This example uses tail call recursion. I expect it to be faster with smaller
  initial values.

  ## Example

      iex> EulerExample.sum_of_multiples(10)
      23
  """
  @spec sum_of_multiples_2(integer) :: integer
  def sum_of_multiples_2(value) do
    value
    |> find_range
    |> Enum.to_list
    |> sum_of_multiples_2(0)
  end
  defp sum_of_multiples_2([], acc), do: acc
  defp sum_of_multiples_2([head|tail], acc) do
    value_to_add = if desired_value?(head), do: head, else: 0

    sum_of_multiples_2(tail, (acc + value_to_add))
  end

  @spec create_stream_of_desired_values(Range.t) :: Stream.t
  defp create_stream_of_desired_values(range) do
    Stream.filter(range, fn(x) -> desired_value?(x) end)
  end

  @spec find_range(integer) :: Range.t
  defp find_range(value) do
    Range.new(0, value - 1)
  end

  @spec desired_value?(integer) :: integer
  defp desired_value?(number) do
    cond do
      rem(number, 3) == 0 -> true
      rem(number, 5) == 0 -> true
      true                -> false
    end
  end
end

I then set up the benchmarks:

defmodule Example do
  use Bmark

  bmark :runner1, runs: 5 do
    EulerExample.sum_of_multiples_1(100)
  end

  bmark :runner2, runs: 5 do
    EulerExample.sum_of_multiples_2(100)
  end
end

And then run the benchmarks:

$ mix bmark
$ mix bmark.cmp results/example.runner1.results results/example.runner2.results
results/example.runner1.results:  results/example.runner2.results:
30                                1418
26                                26
25                                24
23                                22
23                                19

25.4 -> 301.8 (+1088.19%) with p < 1
t = 0.9904844302351117, 8 degrees of freedom

For some reason I always get a little over 1ms on the last example that runs.

defmodule Example do
  use Bmark

  bmark :runner1, runs: 5 do
    EulerExample.sum_of_multiples_1(100)
  end

  bmark :runner2, runs: 5 do
    EulerExample.sum_of_multiples_2(100)
  end

  bmark :runner3, runs: 5 do
    EulerExample.sum_of_multiples_2(100)
  end
end

results/example.runner1.results:  results/example.runner2.results:
31                                22
24                                20
24                                18
22                                20
22                                18

24.6 -> 19.6 (-20.33%) with p < 0.025
t = 2.7441064997422586, 8 degrees of freedom

results/example.runner1.results:  results/example.runner3.results:
31                                1626
24                                23
24                                18
22                                19
22                                18

24.6 -> 340.8 (+1285.37%) with p < 1
t = 0.9841097775094585, 8 degrees of freedom

In case it ends up mattering I'm using:

$ elixir -v
Erlang/OTP 18 [erts-7.3] [source] [64-bit] [smp:8:8] [async-threads:10] [hipe] [kernel-poll:false] [dtrace]

Elixir 1.2.4

on OS X 10.11.4

[jmitchell]

Hi @mcelaney. I just noticed this passing through.

Is the unexpected result the first row of times for :runner2/:runner3? This could be explained by sum_of_multiples_2 benefiting from some kind of caching in the first run whereas sum_of_multiples_1 is ready for action from the start.

If I understand your theory correctly, you could test it by moving :runner2 above :runner1 and then compare them. I suspect this should make :runner1 end up on the right instead. And if my theory about caching is right you'll still see an initial slow time for :runner2, even if runs before :runner1 and is reported on the left.