Performance discrepancies between two dice rolling libraries...

[Mike Chmielewski]

So I have 2 dice rolling libraries, Dicer and Rollex. I'm trying to get Rollex to perform better than Dicer, but it only does so in naive case (passing a single number to evaluate).

Some details:

• Dicer library
  
• Recursive descent algorithm
• Rollex library
  
• Pratt parser algorithm

They both use protocols, though Dicer uses it just to parse a token from the input string, while Rollex does that, as well as has 3 more protocol functions used during the evaluation phase. I did a check a while ago, and the Lexer and Validator functions appear to be essential equivalent. The actual random number generator library is the same for both libraries. I have run `MIX_ENV=prod iex -S mix`, and then run my timings calls `(Rollex|Dicer).Timings.time` to test total time over multiple invocations.

---

My question is, how can get timings on sub-calls within my evaluator call, to narrow down the specific slowdown? I was really expecting the Pratt parser to be no slower, and in cases, faster... Is it a case of more frequent protocol calls (vs. a case clause in the Dicer library)?

Thanks for any suggestions!

[Saša Jurić]

 

My question is, how can get timings on sub-calls within my evaluator call, to narrow down the specific slowdown? I was really expecting the Pratt parser to be no slower, and in cases, faster... Is it a case of more frequent protocol calls (vs. a case clause in the Dicer library)?

Are your protocols consolidated?

If you want to analyze the problem deeper, you could consider profiling with fprof. Here's a simple example:

defmodule Test do

  def run do

    Enum.each(1..50, &simulated_bottleneck/1)

  end

  defp simulated_bottleneck(x) do

    :timer.sleep(x)

  end

end

defmodule Profiler do

  def profile(fun) do

    :fprof.apply(fun, [], file: 'profile.trace')

    :fprof.profile({:file, 'profile.trace'})

    :fprof.analyse(dest: 'profile.analyse')

    

    File.rm("profile.trace")

    File.read!("profile.analyse") |> IO.puts

    File.rm("profile.analyst")

  end

end

Profiler.profile(fn -> Test.run end)

It takes some time getting used to the output, but I found I can usually pinpoint bottlenecks.

[José Valim]

 

Are your protocols consolidated?

To clarify a bit: if you are running with MIX_ENV=prod, both projects should run with consolidated protocols. You should see a message while compiling.
 

If you want to analyze the problem deeper, you could consider profiling with fprof. Here's a simple example:

Maybe we should provide a "mix fprof" task that runs a given file/string under fprof? It would be fantastic to ask people to just run "mix fprof -e Test.run" instead of shipping some code snippets around.

[Sasa Juric]

On 26 May 2015, at 09:42, José Valim <jose....@plataformatec.com.br> wrote:

 

Are your protocols consolidated?

To clarify a bit: if you are running with MIX_ENV=prod, both projects should run with consolidated protocols. You should see a message while compiling.

IIRC that was a recent addition, right? So it could be possible that OP is running an older Elixir 1.0.x where auto consolidation in prod is not happening?

 

If you want to analyze the problem deeper, you could consider profiling with fprof. Here's a simple example:

Maybe we should provide a "mix fprof" task that runs a given file/string under fprof? It would be fantastic to ask people to just run "mix fprof -e Test.run" instead of shipping some code snippets around.

Yeah, that sounds like a good idea. I could try playing with it. Looking at docs, I think it’s even possible to trace directly to some process, and thus avoid creating temp files. Presumably, it should work like mix run, and then produce the profile output at the end?

[José Valim]

IIRC that was a recent addition, right? So it could be possible that OP is running an older Elixir 1.0.x where auto consolidation in prod is not happening?

Ah, yes. I looked at his Mix file and it had both flags in there but he needs to be using Elixir 1.0.4.

 

Yeah, that sounds like a good idea. I could try playing with it. Looking at docs, I think it’s even possible to trace directly to some process, and thus avoid creating temp files. Presumably, it should work like mix run, and then produce the profile output at the end?

Yes, I think so.

[Mike Chmielewski]

I am using 1.0.4, and see the consolidation output (I consolidated both projects).

I will check out fprof, thanks!

[Mike Chmielewski]

So months later I finally got time to do a comparison with fprof. I am on Max OS X, Erlang 18.1 and Elixir 1.1.1. I ran with MIX_ENV=prod, `iex -S mix compile`. the output said my protocols were consolidated.

I tried using fprof, and couldn't glean much, except some data that the Pratt Parser lexer was noticeably slower. the difference there is that my recursive descent library uses a "hard-coded" cond to match the available tokens, and then create them. For my Pratt parser, I use protocol dispatch to create the token. (I did this to make my code organization easier, as my token structs implement their create and the Pratt parser functions all in one token file, which means fewer places to change when modifying items, shorter files, and easier addition of new tokens.

Switching to use a cond in the lexer and not using protocol dispatch dropped my :timer.tc timings of 100 evaluations of a test input from 230000 to 150000 with just that change. It was still overall slower than the RD library, but I'm guessign that also has to do with the protocol dispatching I do on the evaluation side.

Is this just the way things are, or am I missing an optimization that allows me to keep using protocols (which I find more elegant)?