Why does this simple GenServer timeout?

Questions / Help
, ,
1

I’ve condensed the problem I found while playing around with GenServers (I don’t know much about OTP yet) into the following script:

defmodule Test do
  use GenServer

  def handle_call({:work, item}, _from, _state) do
    IO.puts "Processing item #{item}..."
    :timer.sleep(3000)
    {:reply, "Done processing item #{item}!", []}
  end
end

GenServer.start_link(Test, [], name: Test)

Task.start(fn -> GenServer.call(Test, {:work, 1}, 5000) end)
Task.start(fn -> GenServer.call(Test, {:work, 2}, 5000) end)

:timer.sleep(15000)

When I run this, I get the following:

C:\Users\Joe\test>elixir script.exs
Processing item 1...
Processing item 2...

12:17:24.056 [error] Task #PID<0.77.0> started from #PID<0.69.0> terminating
** (stop) exited in: GenServer.call(Test, {:work, 2}, 5000)
    ** (EXIT) time out
    (elixir) lib/gen_server.ex:737: GenServer.call/3
    (elixir) lib/task/supervised.ex:85: Task.Supervised.do_apply/2
    (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3
Function: #Function<1.117183472 in file:script.exs>
    Args: []

It seems to me that this should never timeout because handle_call only sleeps for 3000 milliseconds, and the call is allotted 5000 milliseconds of timeout time. So then, why do I get a timeout in the second call?

1 Like
2

The Genserver is a single threaded process. If you sleep in the handle call, the second message sent will not start processing until the first sleep is finished, so 3000 + 3000 > 5000.

3

The second call has to wait about 6 seconds until the job finishes, but you told it to not wait longer than 5.

The genserver itself processes jobs one by one, not in parallel or concurrently.

4

Based on GenServer.reply/2:

defmodule Test do
  use GenServer

  def handle_call({:work, item}, from, state) do
    IO.puts "Processing item #{item}..."
    Process.send_after self(), {:reply, from, item}, 3_000
    {:noreply, state}
  end

  def handle_info({:reply, from, item}, state) do
    GenServer.reply from, "Done processing item #{item}!"
    {:noreply, state}
  end

end

GenServer.start_link(Test, [], name: Test)

Task.start(fn -> IO.puts (GenServer.call Test, {:work, 1}, 5_000) end)
Task.start(fn -> IO.puts (GenServer.call Test, {:work, 2}, 5_000) end)

:timer.sleep(15_000)

.

$ elixir test.exs
Processing item 1...
Processing item 2...
Done processing item 1!
Done processing item 2!
$

So GenServer doesn’t have to reply to a call immediately. It can store “intermediate results” in its own state - for example when it’s still “waiting” for results from other processes while not being blocked so that it can accept new requests even before the other work is completely done.

The one big drawback to GenServer.call/3 is that it blocks the client process. So when processes “co-operate” it isn’t that uncommon to use GenServer.cast/2 instead by simply including a return pid (or from) in the request message proper, for the eventual result message - that way none of the processes ever have to be blocked - they just process the (cast) messages (and results) as they come in.

PS: version that gets the GenServer state actively involved:

defmodule Test do
  use GenServer

  def handle_call({:work, item}, from, old_state) do
    state = add_result old_state, from, item
    IO.puts "Processing item #{item}..."
    Process.send_after self(), {:reply, from}, 3_000
    {:noreply, state}
  end

  def handle_info({:reply, from}, old_state) do
    {item, state} = pop_result old_state, from
    GenServer.reply from, "Done processing item #{item}!"
    {:noreply, state}
  end

  defp add_result(state, from, item),
    do: Map.put state, from, item

  defp pop_result(state, from) do
    item = state[from]
    new_state = Map.delete state, from
    {item, new_state}
  end

end

GenServer.start_link(Test, %{}, name: Test)

Task.start(fn -> IO.puts (GenServer.call Test, {:work, 1}, 5_000) end)
Task.start(fn -> IO.puts (GenServer.call Test, {:work, 2}, 5_000) end)

:timer.sleep(15_000)
3 Likes