IO lag returned

[alco]

On master:

$ mix new lagg --sup
$ cd lagg

# open lib/lagg.ex and add the following line in the start() function:
# IO.puts "THIS TOOK LONGER THAN YOU EXPECTED"

$ mix run
# works fine

$ iex -S mix
Erlang/OTP 17 [erts-6.0] [source] [64-bit] [smp:8:8] [async-threads:10] [hipe] [kernel-poll:false] [dtrace]

# >>> it is hanging here for 2 seconds <<<

THIS TOOK LONGER THAN YOU EXPECTED
Interactive Elixir (0.14.2-dev) - press Ctrl+C to exit (type h() ENTER for help)

[josevalim]

Can you please check if :io.format("~p~n", [:hello]) causes the issue? If so, there is nothing we can do besides waiting my patch to be merged into OTP.

[alco]

Yes, :io.format() has the same lag. Can we reference the OTP patch in this issue and leave it open?

[josevalim]

Certainly: erlang/otp#351

I have created a new tag to mention the bug is in Erlang/OTP.

[fishcakez]

Isn't this fixed in 8e4a8e9?

mix new lagg does not create a start/2 function on master, you need mix new lagg --sup but that is likely a typo otherwise you have a weird setup given 0-14.2-dev version shown in shell.

[alco]

@fishcakez it was a typo, I updated the initial post. Thanks.

[fishcakez]

OK, I see that its IO.puts not IO.inspect, so that commit (8e4a8e9) would have no effect and I don't think the linked issue is related. Also I tried to reproduce this but could not.

If you apply a change like this to a new lagg app and run mix deps.get && iex -S mix what output do you get?

index 35ee586..f84fe98 100644
--- a/lib/lagg.ex
+++ b/lib/lagg.ex
@@ -6,6 +6,16 @@ defmodule Lagg do
   def start(_type, _args) do
     import Supervisor.Spec, warn: false

+    Dbg.trace(Process.group_leader())
+    Dbg.trace(self())
+
+    :io.columns()
+
+    IO.puts "THIS TOOK LONGER THAN YOU EXPECTED"
+
+    Dbg.trace(Process.group_leader(), :clear)
+    Dbg.trace(self(), :clear)
+
     children = [
       # Define workers and child supervisors to be supervised
       # worker(Lagg.Worker, [arg1, arg2, arg3])
diff --git a/mix.exs b/mix.exs
index 0254876..bcf9358 100644
--- a/mix.exs
+++ b/mix.exs
@@ -12,7 +12,7 @@ defmodule Lagg.Mixfile do
   #
   # Type `mix help compile.app` for more information
   def application do
-    [applications: [],
+    [applications: [:dbg],
      mod: {Lagg, []}]
   end

@@ -26,6 +26,6 @@ defmodule Lagg.Mixfile do
   #
   # Type `mix help deps` for more examples and options
   defp deps do
-    []
+    [{:dbg, github: "fishcakez/dbg", tag: "v0.14.0"}]
   end
 end

[alco]

@fishcakez Calling :io.format instead of IO.puts has the same lag.

Here's the output after applying your patch. To be clear: it first hangs for ~4 seconds after printing the first line, then it prints all of the Dbg output at once.

λ iex -S mix
Erlang/OTP 17 [erts-6.0] [source] [64-bit] [smp:8:8] [async-threads:10] [hipe] [kernel-poll:false] [dtrace]


** (Dbg) #PID<0.78.0> (at 21:33:20) receives:
    {:dbg, {:ok, [{:matched, :nonode@nohost, 1}]}}
THIS TOOK LONGER THAN YOU EXPECTED

** (Dbg) #PID<0.78.0> (at 21:33:20) schedules in with :dbg.req/1

** (Dbg) #PID<0.78.0> (at 21:33:20) sends to #PID<0.77.0>:
    {:io_request, #PID<0.78.0>, #PID<0.77.0>, {:get_geometry, :columns}}
Interactive Elixir (0.14.2-dev) - press Ctrl+C to exit (type h() ENTER for help)

** (Dbg) #PID<0.77.0> (at 21:33:20) receives:
    {:io_request, #PID<0.78.0>, #PID<0.77.0>, {:get_geometry, :columns}}

** (Dbg) #PID<0.78.0> (at 21:33:20) schedules out with :io.wait_io_mon_reply/2

** (Dbg) #PID<0.77.0> (at 21:33:20) schedules in with :application_master.init_loop/4
iex(1)>
** (Dbg) #PID<0.77.0> (at 21:33:20) sends to #PID<0.24.0>:
    {:io_request, #PID<0.78.0>, #PID<0.77.0>, {:get_geometry, :columns}}

** (Dbg) #PID<0.77.0> (at 21:33:20) schedules out with :application_master.init_loop/4

** (Dbg) #PID<0.78.0> (at 21:33:24) receives:
    {:io_reply, #PID<0.77.0>, {:error, :enotsup}}

** (Dbg) #PID<0.78.0> (at 21:33:24) schedules in with :io.wait_io_mon_reply/2

** (Dbg) #PID<0.78.0> (at 21:33:24) schedules out with :code_server.call/2

** (Dbg) #PID<0.78.0> (at 21:33:24) receives:
    {:code_server, {:module, String.Chars.BitString}}

** (Dbg) #PID<0.78.0> (at 21:33:24) schedules in with :code_server.call/2

** (Dbg) #PID<0.78.0> (at 21:33:24) starts garbage collecting:
    [old_heap_block_size: 0, heap_block_size: 233, mbuf_size: 0, recent_size: 0,
     stack_size: 20, old_heap_size: 0, heap_size: 211, bin_vheap_size: 4,
     bin_vheap_block_size: 46422, bin_old_vheap_size: 0,
     bin_old_vheap_block_size: 46422]

** (Dbg) #PID<0.78.0> (at 21:33:24) stops garbage collecting:
    [old_heap_block_size: 0, heap_block_size: 233, mbuf_size: 0, recent_size: 19,
     stack_size: 20, old_heap_size: 0, heap_size: 19, bin_vheap_size: 4,
     bin_vheap_block_size: 46422, bin_old_vheap_size: 0,
     bin_old_vheap_block_size: 46422]

** (Dbg) #PID<0.78.0> (at 21:33:24) sends to #PID<0.77.0>:
    {:io_request, #PID<0.78.0>, #PID<0.77.0>,
     {:put_chars, :unicode, "THIS TOOK LONGER THAN YOU EXPECTED\n"}}

** (Dbg) #PID<0.77.0> (at 21:33:24) receives:
    {:io_request, #PID<0.78.0>, #PID<0.77.0>,
     {:put_chars, :unicode, "THIS TOOK LONGER THAN YOU EXPECTED\n"}}

** (Dbg) #PID<0.78.0> (at 21:33:24) schedules out with :io.wait_io_mon_reply/2

** (Dbg) #PID<0.77.0> (at 21:33:24) schedules in with :application_master.init_loop/4

** (Dbg) #PID<0.77.0> (at 21:33:24) sends to #PID<0.24.0>:
    {:io_request, #PID<0.78.0>, #PID<0.77.0>,
     {:put_chars, :unicode, "THIS TOOK LONGER THAN YOU EXPECTED\n"}}

** (Dbg) #PID<0.77.0> (at 21:33:24) schedules out with :application_master.init_loop/4

** (Dbg) #PID<0.78.0> (at 21:33:24) receives:
    {:io_reply, #PID<0.77.0>, :ok}

** (Dbg) #PID<0.78.0> (at 21:33:24) schedules in with :io.wait_io_mon_reply/2

** (Dbg) #PID<0.78.0> (at 21:33:24) sends to #PID<0.74.0>:
    {#PID<0.78.0>, {:p, #PID<0.77.0>, [:clear]}}

** (Dbg) #PID<0.78.0> (at 21:33:24) schedules out with :dbg.req/1

** (Dbg) #PID<0.78.0> (at 21:33:24) receives:
    {:dbg, {:ok, [{:matched, :nonode@nohost, 1}]}}

** (Dbg) #PID<0.78.0> (at 21:33:24) schedules in with :dbg.req/1

** (Dbg) #PID<0.78.0> (at 21:33:24) sends to #PID<0.74.0>:
    {#PID<0.78.0>, {:p, #PID<0.78.0>, [:clear]}}

** (Dbg) #PID<0.78.0> (at 21:33:24) schedules out with :dbg.req/1

[fishcakez]

It takes 4 seconds for :io.columns to get a reply. This should be 2 seconds I think. If you remove the columns call does IO.puts take 2 sexonds? This suggests something else is blocking an io server.

[alco]

@fishcakez it takes 2 seconds when I remove the :io.columns call.

[fishcakez]

We are in agreement that io blocks for two seconds on startup and afterwards there is no "io lag"? I am unsure what could cause the io to block for two second on startup. This is strangely similar (2 seconds) to @josevalim's patch above so you could try that and see if it goes away but it is likely a coincidence as I don't think anything would call :io.columns|rows unless pretty printing afterwards. Otherwise I would suggest posting on erlang questions or bugs.

[fishcakez]

@alco, to be clear I can't reproduce. All Dbg messages have same time for me - there is no delay - when I remove io:columns. With io:columns I have a 2 second delay waiting for the {:error, :enotsup} message. The times you see from Dbg are the times the trace is produced, not the time the Dbg process handles/inspects/prints the log message.

[alco]

@fishcakez has created an equivalent example in Erlang https://github.com/fishcakez/lagg. It doesn't have the delay.

[josevalim]

Ok, I think the reason for this is because we wait for the application to be started before launching IEx. That's because you can get garbled output or something of sorts. I will try some alternatives and ping back.