Sending messages in recursive functions performance degradation

[tinglei8]

Environment

• Elixir version (elixir -v): Elixir 1.1.1
• Erlang version: Erlang/OTP 18
• Operating system: Mac OSX El Capitan 10.11.3, CentOS 6

Current behavior

In following test snippet, we send two messages from a process to another process, and repeat for 5000, 50000, 500000 times. It's surprising to notice the send performance degrades dramatically with respect to message total number. In one of my run it shows sending 5000 count is in 5ms, while 500000 count is in 7.3s.

Even more confusing, uncomment either [Code Block #1] or [Code Block #2], and we get expected linear performance with respect to message count.

[Code Block #1] use Enum.each() instead of recursive functions.
[Code Block #2] simply send the message in the recursive function body instead of calling a third module function to send.

Code below:

defmodule A do

  def start(count) do
    Kernel.spawn fn ->
      loop(count)
      {_, 0} = :erlang.process_info(self(), :message_queue_len)
      IO.puts "A.loop() finished"
    end
  end

  def loop(_, 0), do: nil
  def loop(count) do
    receive do
      {:c2a, _} ->
        loop(count - 1)
      _ -> raise "A.loop() error!"
    end
  end

  def send_msg(pid, {:c2a, n}) do
    send(pid, {:c2a, n})
  end

end

defmodule C do

  def run(count) do
    a = A.start(count)
    c = self()
    send_all(a, c, count)
    IO.puts "C.send_all() finished"

    loop(count)
    {_, 0} = :erlang.process_info(self(), :message_queue_len)
    IO.puts "C.loop() finished"
  end

  # ---------------------------------------------------------------------
  # [Code Block #1]: uncomment this to get expected linear performance
  # ---------------------------------------------------------------------
  # def send_all(a, c, count) do
  #   (1..count) |> Enum.into([]) |> Enum.each(fn (_) ->
  #     send_one(a, c)
  #   end)
  # end

  def send_all(_, _, 0), do: nil
  def send_all(a, c, count) do
    send_one(a, c)
    send_all(a, c, count - 1)
  end

  def send_one(a, c) do
    # ----------------------------------------------------------------------------------------
    # [Code Block #2]: replace A.send_msg() call with this to get expected linear performance
    # ----------------------------------------------------------------------------------------
    # send(a, {:c2a, 1})
    A.send_msg(a, {:c2a, 1})
    send(c, :c2c)
  end

  def loop(0), do: nil
  def loop(count) do
    receive do
      :c2c -> loop(count - 1)
      _ -> raise "C.loop() error!"
    end
  end

end

defmodule Test do

  def test(count) do
    IO.puts "===========================   test #{count}..."
    {time, :ok} = :timer.tc(fn -> C.run(count) end)
    IO.puts "===========================   test #{count} time=#{time}"
  end

end

Test.test(5000)
Test.test(50000)
Test.test(500000)

To reproduce, save the code as test.exs, run it with "elixir test.exs".

Expected behavior

Sending of messages should be in linear performance with respect to message count, regardless of how and where the sending is done.

I'm not sure this is a erlang bug or elixir bug yet. Selective receive is already ruled out by raising exceptions on unmatched messages.

[josevalim]

@tinglei8 there are two important things to consider here:

1. Every process has a number of reductions, basically a number of operations it is allowed to perform before it is scheduled out. Every time you send a message to another process, the number of reduction it takes increases with the receiver's message queue. This works as a backpressure mechanism, you want to make sending messages to large queues more expensive.

2. Your particular issue, however, is being caused by the GC. If you rewrite this function:

   def send_msg(pid, {:c2a, n}) do
     send(pid, {:c2a, n})
   end

   as:

   def send_msg(pid, {:c2a, _} = msg) do
     send(pid, msg)
   end

You will get better performance. In your current version, you are building a new tuple on every operation, that will eventually trigger the GC. And you will trigger it more frequently when the amount of messages to send increases which in turn will take more time because the GC may also scan your message queue (and you are sending messages to yourself).

That said, two considerations:

1. As "evax" said on IRC, it's actually a good illustration the per-process gc holds its promises when multiple processes are involved. With only two processes, you feel it as if you were on the JVM.
2. I agree the Erlang compiler could be smarter and avoid creating the new tuple in your definition for send_msg/2. I will open up an issue with the Erlang team and hopefully contribute a patch.

[josevalim]

Thank you for this fantastic example, it was highly educative. If you have more questions, please ask them!

[tinglei8]

Thanks for the quick comment, looking forward to the improvement in erlang compiler!