Crash in statistics

[michalmuskala]

I'm getting following crashes on master right before statistics are calculated:

** (EXIT from #PID<0.73.0>) an exception was raised:
    ** (ArithmeticError) bad argument in arithmetic expression
        (benchee) lib/benchee/statistics.ex:326: Benchee.Statistics.iterations_per_second/1
        (benchee) lib/benchee/statistics.ex:231: Benchee.Statistics.job_statistics/1
        (benchee) lib/benchee/statistics.ex:157: anonymous fn/1 in Benchee.Statistics.statistics/1
        (elixir) lib/task/supervised.ex:88: Task.Supervised.do_apply/2
        (elixir) lib/task/supervised.ex:38: Task.Supervised.reply/5
        (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3

example script: https://gist.github.com/michalmuskala/5ff53581b4b53adec2fff7fb4d69fd52

[michalmuskala]

I also got another failure:

** (EXIT from #PID<0.73.0>) an exception was raised:
    ** (MatchError) no match of right hand side value: %Benchee.Benchmark.Scenario{after_each: nil, after_scenario: nil, before_each: nil, before_scenario: nil, function: #Function<2.78505830 in file:benches/keyword.ex>, input: {[k1: 1, k2: 2, k3: 3, k4: 4, k5: 5, k6: 6, k7: 7, k8: 8, k9: 9, k10: 10, k11: 11, k12: 12, k13: 13, k14: 14, k15: 15, k16: 16, k17: 17, k18: 18, k19: 19, k20: 20, k21: 21, k22: 22, k23: 23, k24: 24, k25: 25, k26: 26, k27: 27, k28: 28, k29: 29, k30: 30, k31: 31, k32: 32, k33: 33, k34: 34, k35: 35, k36: 36, k37: 37, k38: 38, k39: 39, k40: 40, k41: 41, k42: 42, k43: 43, ...], :k100}, input_name: "large hit", job_name: "delete reverse", memory_usage_statistics: %Benchee.Statistics{average: nil, ips: nil, maximum: nil, median: nil, minimum: nil, mode: nil, percentiles: nil, sample_size: 0, std_dev: nil, std_dev_ips: nil, std_dev_ratio: nil}, memory_usages: [], name: "delete reverse", run_time_statistics: %Benchee.Statistics{average: 1.1881014046694967, ips: 841678.9981644519, maximum: 450.0, median: 1.1, minimum: 1.0, mode: 1.1, percentiles: %{50 => 1.1, 99 => 4.2}, sample_size: 393828, std_dev: 1.1369878580941948, std_dev_ips: 805468.9587645745, std_dev_ratio: 0.9569788013258679}, run_times: [3.0, 2.7, 4.0, 2.8, 2.7, 2.6, 2.7, 2.9, 2.7, 2.7, 2.7, 2.4, 2.6, 2.6, 2.7, 2.6, 2.5, 2.7, 2.7, 2.6, 2.6, 2.6, 2.9, 2.7, 2.6, 2.7, 2.4, 2.6, 2.7, 2.6, 2.6, 2.5, 2.7, 2.7, 3.0, 2.7, 2.6, ...], tag: nil}
        (benchee) lib/benchee/formatters/console/memory.ex:127: Benchee.Formatters.Console.Memory.format_scenario/4
        (elixir) lib/enum.ex:1298: Enum."-map/2-lists^map/1-0-"/2
        (benchee) lib/benchee/formatters/console/memory.ex:60: Benchee.Formatters.Console.Memory.render/2
        (benchee) lib/benchee/formatters/console.ex:106: Benchee.Formatters.Console.generate_output/3
        (elixir) lib/enum.ex:1302: anonymous fn/3 in Enum.map/2
        (stdlib) lists.erl:1263: :lists.foldl/3
        (elixir) lib/enum.ex:1921: Enum.map/2
        (benchee) lib/benchee/formatter.ex:66: anonymous fn/2 in Benchee.Formatter.parallel_output/2

This time with the same module as in the previous gist, but with different jobs:

benches = %{
  "delete old" => fn {kv, key} -> BenchKeyword.delete_v0(kv, key) end,
  "delete throw" => fn {kv, key} -> BenchKeyword.delete_v1(kv, key) end,
  "delete reverse" => fn {kv, key} -> BenchKeyword.delete_v2(kv, key) end,
  "delete keymember reverse" => fn {kv, key} -> BenchKeyword.delete_v3(kv, key) end,
  "delete keymember body" => fn {kv, key} -> BenchKeyword.delete_v4(kv, key) end
}

inputs = %{
  # "small miss" => {Enum.map(1..10, &{:"k#{&1}", &1}), :k11},
  # "small hit" => {Enum.map(1..10, &{:"k#{&1}", &1}), :k10},
  "large miss" => {Enum.map(1..100, &{:"k#{&1}", &1}), :k101},
  "large hit" => {Enum.map(1..100, &{:"k#{&1}", &1}), :k100},
  "huge miss" => {Enum.map(1..10000, &{:"k#{&1}", &1}), :k10001},
  "huge hit" => {Enum.map(1..10000, &{:"k#{&1}", &1}), :k10000}
}

Benchee.run(benches, inputs: inputs, print: [fast_warning: false], memory_time: 0.1, time: 5)

[michalmuskala]

And another one:

** (EXIT from #PID<0.73.0>) an exception was raised:
    ** (KeyError) key nil not found in: %{hour: %Benchee.Conversion.Unit{label: "h", long: "Hours", magnitude: 3600000000, name: :hour}, microsecond: %Benchee.Conversion.Unit{label: "μs", long: "Microseconds", magnitude: 1, name: :microsecond}, millisecond: %Benchee.Conversion.Unit{label: "ms", long: "Milliseconds", magnitude: 1000, name: :millisecond}, minute: %Benchee.Conversion.Unit{label: "min", long: "Minutes", magnitude: 60000000, name: :minute}, second: %Benchee.Conversion.Unit{label: "s", long: "Seconds", magnitude: 1000000, name: :second}}
        (stdlib) :maps.get(nil, %{hour: %Benchee.Conversion.Unit{label: "h", long: "Hours", magnitude: 3600000000, name: :hour}, microsecond: %Benchee.Conversion.Unit{label: "μs", long: "Microseconds", magnitude: 1, name: :microsecond}, millisecond: %Benchee.Conversion.Unit{label: "ms", long: "Milliseconds", magnitude: 1000, name: :millisecond}, minute: %Benchee.Conversion.Unit{label: "min", long: "Minutes", magnitude: 60000000, name: :minute}, second: %Benchee.Conversion.Unit{label: "s", long: "Seconds", magnitude: 1000000, name: :second}})
        (benchee) lib/benchee/conversion/scale.ex:92: Benchee.Conversion.Scale.unit_for/2
        (benchee) lib/benchee/conversion/scale.ex:71: Benchee.Conversion.Scale.scale/3
        (benchee) lib/benchee/formatters/console/helpers.ex:43: Benchee.Formatters.Console.Helpers.duration_output/2
        (benchee) lib/benchee/formatters/console/memory.ex:134: Benchee.Formatters.Console.Memory.format_scenario/4
        (elixir) lib/enum.ex:1298: Enum."-map/2-lists^map/1-0-"/2
        (benchee) lib/benchee/formatters/console/memory.ex:60: Benchee.Formatters.Console.Memory.render/2
        (benchee) lib/benchee/formatters/console.ex:106: Benchee.Formatters.Console.generate_output/3

with

benches = %{
  "delete old" => fn {kv, key} -> BenchKeyword.delete_v0(kv, key) end,
  "delete throw" => fn {kv, key} -> BenchKeyword.delete_v1(kv, key) end,
  "delete reverse" => fn {kv, key} -> BenchKeyword.delete_v2(kv, key) end,
  "delete keymember reverse" => fn {kv, key} -> BenchKeyword.delete_v3(kv, key) end,
  "delete keymember body" => fn {kv, key} -> BenchKeyword.delete_v4(kv, key) end
}

inputs = %{
  # "small miss" => {Enum.map(1..10, &{:"k#{&1}", &1}), :k11},
  # "small hit" => {Enum.map(1..10, &{:"k#{&1}", &1}), :k10},
  "large miss" => {Enum.map(1..100, &{:"k#{&1}", &1}), :k101},
  "large hit" => {Enum.map(1..100, &{:"k#{&1}", &1}), :k100},
  "huge miss" => {Enum.map(1..10000, &{:"k#{&1}", &1}), :k10001},
  "huge hit" => {Enum.map(1..10000, &{:"k#{&1}", &1}), :k10000}
}

Benchee.run(benches, inputs: inputs, print: [fast_warning: false], memory_time: 1, time: 5)

I seem to be very lucky today 😂

[devonestes]

Woah! Yeah, I guess there's a bug in there, probably around getting units for memory management. I'll take a peek.

Oh, and thanks for the reproduction script!

[PragTob]

At least the crashing part should now be completely handled in #214

The trouble is some of them don't collect memory at all, to cite @devonestes from slack (so we don't lose it):

Ok, so the plot thickens. I’m finding that for a couple of benchmark/input combos aren’t actually measuring memory. There’s just an empty list that’s returned from the memory measurement, but only for these magical combinations.

"NAME: delete old     INPUT: large hit"
"NAME: delete old     INPUT: large miss"
"NAME: delete reverse     INPUT: large hit"
"NAME: delete reverse     INPUT: large miss"

That not measuring is what’s causing the next two errors that Michał noted in his issue.
so, if anyone has any brilliant ideas as to why those would return an empty list instead of all 0's (assuming it’s not using any memory), then I’m all ears!
I don’t think it has anything to do with execution time since if that were the case, we’d be seeing the “huge hit” and “huge miss” in there as well, but it’s just these middle values. And it’s consistent! I get the same results every time I run it - these always end up with memory_usages: [] after measurement is done and statistics are about to be calculated.
The memory measurement process for those 5 is actually returning nil…
and the process isn’t crashing while it’s measuring memory, so that’s not it…
ok, and even weirder, when I run just “delete reverse” with “large hit” and “large miss”, it all works just fine!

[PragTob]

Fixed by #214 and #216

[michalmuskala]

Thank you both for your hard work on benchee! ❤️