payload: {"action":"created","issue":{"url":"https://api.github.com/repos/bencheeorg/benchee/issues/296","repository_url":"https://api.github.com/repos/bencheeorg/benchee","labels_url":"https://api.github.com/repos/bencheeorg/benchee/issues/296/labels{/name}","comments_url":"https://api.github.com/repos/bencheeorg/benchee/issues/296/comments","events_url":"https://api.github.com/repos/bencheeorg/benchee/issues/296/events","html_url":"https://github.com/bencheeorg/benchee/issues/296","id":444495072,"node_id":"MDU6SXNzdWU0NDQ0OTUwNzI=","number":296,"title":"Inaccurate results when benchmarking `Phoenix.Token`","user":{"login":"nathanl","id":338814,"node_id":"MDQ6VXNlcjMzODgxNA==","avatar_url":"https://avatars2.githubusercontent.com/u/338814?v=4","gravatar_id":"","url":"https://api.github.com/users/nathanl","html_url":"https://github.com/nathanl","followers_url":"https://api.github.com/users/nathanl/followers","following_url":"https://api.github.com/users/nathanl/following{/other_user}","gists_url":"https://api.github.com/users/nathanl/gists{/gist_id}","starred_url":"https://api.github.com/users/nathanl/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/nathanl/subscriptions","organizations_url":"https://api.github.com/users/nathanl/orgs","repos_url":"https://api.github.com/users/nathanl/repos","events_url":"https://api.github.com/users/nathanl/events{/privacy}","received_events_url":"https://api.github.com/users/nathanl/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":1,"created_at":"2019-05-15T15:10:42Z","updated_at":"2019-05-16T18:27:41Z","closed_at":null,"author_association":"NONE","body":"I ran a benchmark on `Phoenix.Token` to get info about how different `:key_iterations` values would impact performance.\r\n\r\nTo my surprise, benchee reports no difference in how long it takes sign + verify with 1 key iteration vs 20,000,000. However, there clearly is a difference, because the wall clock run time is very different depending on which value I use.\r\n\r\nHere's the mix task where I run the comparison: \r\n\r\n```elixir\r\ndefmodule Mix.Tasks.BenchMarkToken do\r\n  use Mix.Task\r\n  alias MyApp.Endpoint\r\n\r\n  @shortdoc \"Compares token runs\"\r\n  def run(_) do\r\n    Mix.Task.run(\"app.start\")\r\n\r\n    Benchee.run(\r\n      %{\r\n        \"sign_and_verify\" => fn key_iterations ->\r\n          signed_token =\r\n            Phoenix.Token.sign(\r\n              Endpoint,\r\n              \"some salt\",\r\n              \"some value\",\r\n              key_iterations: key_iterations\r\n            )\r\n\r\n          {:ok, \"some value\"} =\r\n            Phoenix.Token.verify(\r\n              Endpoint,\r\n              \"some salt\",\r\n              signed_token,\r\n              key_iterations: key_iterations,\r\n              max_age: :infinity\r\n            )\r\n        end\r\n      },\r\n      inputs: %{\r\n        1 => 1,\r\n        20_000_000 => 20_000_000\r\n      }\r\n    )\r\n  end\r\nend\r\n```\r\n\r\nIf I comment out one or the other of the `:inputs`, I get large variations in measurement from the mix task itself.\r\n\r\nFor `1`:\r\n\r\n```\r\nmix bench_mark_token  12.41s user 1.12s system 149% cpu 9.021 total\r\n```\r\n\r\nFor `20_000_000`\r\n\r\n```\r\nmix bench_mark_token  33.60s user 0.97s system 106% cpu 32.496 total\r\n```\r\n\r\nOne of my colleagues guessed that this may be explained as follows:\r\n\r\n> Execution time may not include the BIF/NIF time used for the signing"},"comment":{"url":"https://api.github.com/repos/bencheeorg/benchee/issues/comments/493180849","html_url":"https://github.com/bencheeorg/benchee/issues/296#issuecomment-493180849","issue_url":"https://api.github.com/repos/bencheeorg/benchee/issues/296","id":493180849,"node_id":"MDEyOklzc3VlQ29tbWVudDQ5MzE4MDg0OQ==","user":{"login":"PragTob","id":606517,"node_id":"MDQ6VXNlcjYwNjUxNw==","avatar_url":"https://avatars1.githubusercontent.com/u/606517?v=4","gravatar_id":"","url":"https://api.github.com/users/PragTob","html_url":"https://github.com/PragTob","followers_url":"https://api.github.com/users/PragTob/followers","following_url":"https://api.github.com/users/PragTob/following{/other_user}","gists_url":"https://api.github.com/users/PragTob/gists{/gist_id}","starred_url":"https://api.github.com/users/PragTob/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/PragTob/subscriptions","organizations_url":"https://api.github.com/users/PragTob/orgs","repos_url":"https://api.github.com/users/PragTob/repos","events_url":"https://api.github.com/users/PragTob/events{/privacy}","received_events_url":"https://api.github.com/users/PragTob/received_events","type":"User","site_admin":false},"created_at":"2019-05-16T18:27:41Z","updated_at":"2019-05-16T18:27:41Z","author_association":"MEMBER","body":"Hi, \r\n\r\nthe behaviour heavily hints at what I was suspecting.\r\n\r\nI mildy modified it (not as many iterations as it takes too long) and added a small custom formatter to look at the raw run times:\r\n\r\n```\r\n      inputs: %{\r\n        1 => 1,\r\n        20_000 => 20_000\r\n      },\r\n      warmup: 0,\r\n      time: 1,\r\n      formatters: [\r\n        {Benchee.Formatters.Console, extended_statistics: true},\r\n        fn suite ->\r\n          Enum.each(suite.scenarios, fn scenario ->\r\n            IO.puts(\"#{scenario.name}:\")\r\n            IO.inspect(scenario.run_time_data.samples)\r\n          end)\r\n        end\r\n      ]\r\n    )\r\n```\r\n\r\nas you can see, I also took warmup out of the equation (because that one big time where it is first calculated happens during warmup and hence doesn't show up in the results at all).\r\n\r\nHere's what I get:\r\n\r\n```\r\nsign_and_verify:\r\n[3464088.0, 55764.0, 30283.0, 29346.0, 26398.0, 27421.0, 26489.0, 26442.0,\r\n 25288.0, 27206.0, 25236.0, 25531.0, 2.34e4, 22253.0, 24424.0, 25257.0, 25676.0,\r\n 29571.0, 23954.0, 26265.0, 22351.0, 27024.0, 22443.0, 21854.0, 27460.0,\r\n 41186.0, 26549.0, 29703.0, 23529.0, 22679.0, 29550.0, 22873.0, 2.23e4, 27988.0,\r\n 23040.0, 23002.0, 27774.0, 22435.0, 22208.0, 26973.0, 22513.0, 22569.0,\r\n 27488.0, 24514.0, 22431.0, 29543.0, 32822.0, 38169.0, 25355.0, 25009.0, ...]\r\nsign_and_verify:\r\n[40175774.0, 39955.0, 29489.0, 26335.0, 23168.0, 24290.0, 24974.0, 25533.0,\r\n 25953.0, 26969.0, 23825.0, 27584.0, 22642.0, 26907.0, 22638.0, 22058.0,\r\n 27950.0, 22145.0, 21529.0, 27354.0, 22368.0, 22736.0, 28298.0, 21946.0,\r\n 21485.0, 27308.0, 22926.0, 22013.0, 28218.0, 22931.0, 23343.0, 27576.0,\r\n 22926.0, 24748.0, 39374.0, 23984.0, 28529.0, 45464.0, 29909.0, 25449.0,\r\n 26165.0, 22488.0, 22248.0, 23947.0, 24769.0, 25590.0, 27690.0, 22967.0,\r\n 27042.0, 23329.0, ...]\r\n```\r\n\r\nyou can see that after a first big initial time the times normalize. Caching at this point also makes sense so I'd say that's what it is and recommend one of the approaches suggested above :)\r\n\r\nCheers,\r\nTobi"}}
other: {"actor":{"display_login":"PragTob"}}