Better logger for console with direct access

[olafura]

Hi I've been doing some experiments that you can try out and veryify the result:
https://github.com/olafura/test_io

With sending messages directly to user_drv we are able to have less blocking, significantly less cpu time and less memory usage over all.

I'm making these changes to Logger and not IO directly since IO does a lot more than just print things to the console.

It's not faster per se at putting thing on the terminal but that is something that is going to be difficult to make faster according to my tests.

We might want to handle these reply cases:
https://github.com/erlang/otp/blob/maint/lib/stdlib/src/io.erl#L573
I'm currently pushing everything back to self so it won't be blocking

[josevalim]

Thank you! However, this clause will never be raised now. Can you try the following variation instead of the try do:

case :unicode.characters_to_binary(output) do
  {:error, good, bad} ->
    send(device, {:io_request, self(), self(), {:put_chars, :unicode, [good | Logger.Formatter.prune(bad)]}})
  good ->
    send(device, {:io_request, self(), self(), {:put_chars, :unicode, good}})
end

And let us know how it performs CPU and memory wise?

[olafura]

Thanks @josevalim for the review, I was wondering about that.

Still performs better a little bit less difference in memory usage but always less. And still a big difference in CPU usage.

[olafura]

I'm running:
/usr/bin/time --verbose ../elixir/bin/iex -S mix test test/test_io_test.exs:31
/usr/bin/time --verbose iex -S mix test test/test_io_test.exs:31
and then ctrl-c since the running times seem to be the same and I only
need the cpu and memory information.

[josevalim]

❤️ 💚 💙 💛 💜

[fishcakez]

I like what this PR is trying to achieve. However this creates the tricky situation where Logger.flush will return before its guaranteed that we have written to the device. This doesn't occur in tests because the io messages at the time of flushing will be ahead of the read message to the StringIO process.

If we want to speed up writing to terminal I wonder if we could introduce a middleman process that we send to async and it batches messages to the device. When flushing we get the list of handlers but ignore it. Instead we could call all Console handlers and have them sync with their middleman.

I think this would allow us to do async with back pressure too? With the current setup I think we could build up message queue of :user. Also do we get side effect that Logger sync mode comes on twice as early because replies will increase length of Logger message queue?

[fishcakez]

Perhaps we can achieve batching without middleman as we have replies for backpressure

[josevalim]

@fishcakez since flush makes it clear it was designed for testing, I am ok with changing its guarantees to say the messages were pushed to the handlers as long as we maintain the testing semantics.

[josevalim]

@fishcakez I have pushed this change: fb6eafe

However, this may slow things down altogether. An alternative approach is to not encode on the client and handle the {:error, ...} messages from the IO server on each device. I will push it to a branch.

[josevalim]

With the current setup I think we could build up message queue of :user. Also do we get side effect that Logger sync mode comes on twice as early because replies will increase length of Logger message queue?

I am not sure how back pressure will be affected given we will now consumer messages much faster as well.

[fishcakez]

@fishcakez since flush makes it clear it was designed for testing, I am ok with changing its guarantees to say the messages were pushed to the handlers as long as we maintain the testing semantics.

Won't this break this:

elixir/lib/elixir/lib/kernel/cli.ex

Line 42 in ed8aac2

pid when is_pid(pid) -> Logger.flush()

I am not sure how back pressure will be affected given we will now consumer messages much faster as well.

If we are handling messages much faster that means we are pushing the queue to the :user message queue, instead of Logger's. If Logger is handling messages faster then it will stay in async mode and we lose backpressure and the :user message queue could grow faster than Logger's message queue could previously.

[fishcakez]

However, this may slow things down altogether. An alternative approach is to not encode on the client and handle the {:error, ...} messages from the IO server on each device.

This has the race condition where messages from the same process can get out of order if the first message has an error and the second doesn't. The first message is sent, the second message is sent, first fails, seconds succeeds, then we handle the error and send the first again. This would be very confusing.

[josevalim]

@olafura can you please benchmark the current code in master and let us know how it goes?

[olafura]

It shouldn't really have anything to do with Logger itself since the patch is to remove the push and wait for confirmation that :io has, plus sending the message a couple of times. You can probably flood user_drv with messages but you can also fill the message box of Logger or :group which are also involved.

I'll benchmark the new master when I get back from lunch ;)

[fishcakez]

You can probably flood user_drv with messages but you can also fill the message box of Logger or :group which are also involved.

If we fill up Logger we get some backpressure as logs to it become synchronous, this means the :error_logger handler will be slowed and may start dropping error reports to keep up, and direct Logger calls will become synchronous, slowing down their rate too. We lose a lot of this by not having backpressure from :user.