CODEWITHSUNDEEP
erlang
aseychell
aseychell

Reputation: 1804

Erlang - Receiving timeout messages when calling io:format

I have the following program. However, when tracing the spawned process, I am seeing a trace message with a timeout as can be seen in the trace below.

start() ->
    register(addone, spawn(addone, loop, [])).

loop() ->
receive
    {request, Pid, Msg} ->
        io:format("log ~n", []),
        loop();
    {stop, _Reason} ->
        stop
end.

I am executing this process with the following function:

run() ->
addone:start(),
dbg:start(),
dbg:tracer(),
dbg:p(whereis(addone), [c,m]),
dbg:tpl({'_','_','_'},[{'_',['true'],[{'silent', 'false'}]}]),
addone:request(4).

Trace observed is as follows:

1> addone_scenarios:run().
log
(<0.32.0>) << {request,<0.30.0>,4}
(<0.32.0>) call io:format("log ~n",[])
(<0.32.0>) call io:default_output()
(<0.32.0>) call erlang:group_leader()
(<0.32.0>) call io:format(<0.23.0>,"log ~n",[])
(<0.32.0>) call io:o_request(<0.23.0>,{format,"log ~n",[]},format)
(<0.32.0>) call io:request(<0.23.0>,{format,"log ~n",[]})
(<0.32.0>) call io:io_request(<0.23.0>,{format,"log ~n",[]})
(<0.32.0>) call io:bc_req(<0.23.0>,{put_chars,unicode,io_lib,format,["log ~n",[]]},false)
(<0.32.0>) call net_kernel:dflag_unicode_io(<0.23.0>)
(<0.32.0>) call io:execute_request(<0.23.0>,{false,{put_chars,unicode,io_lib,format,["log ~n",[]]}})
(<0.32.0>) call erlang:monitor(process,<0.23.0>)
(<0.32.0>) <0.23.0> ! {io_request,<0.32.0>,<0.23.0>,
                          {put_chars,unicode,io_lib,format,["log ~n",[]]}}
(<0.32.0>) call io:wait_io_mon_reply(<0.23.0>,#Ref<0.0.0.29>)
(<0.32.0>) << {io_reply,<0.23.0>,ok}
(<0.32.0>) call erlang:demonitor(#Ref<0.0.0.29>)
(<0.32.0>) << timeout
(<0.32.0>) call addone:loop()

What is strange is the timeout trace message that is received. When I remove the io:format(...), this message is not received. Can someone indicate what can be the reason please?

EDIT: I have updated the tracing to include the call for all functions maybe it might help.

Upvotes: 1

Views: 853

Answers (2)

rvirding
rvirding

Reputation: 20916

The only place in the io module where there are timeouts in the function io:wait_io_mon_reply/2 where it waits for the reply to the io request message. To make sure the client process never hangs the io process has been monitored to detect the case where it dies before returning a reply. The io:wait_io_mon_reply/2 has to handle the various cases of what it can receive AND also clean-up the message queue in case it gets multiple returns, for example both a reply message and a process dying message send before the monitoring was turned off. Because of the non-deterministic asynchronous nature of erlang communication this happens and must be taken care of.

The standard way of handling this is by doing (taken straight out of the function):

receive
    {io_reply, From, Reply} ->
        erlang:demonitor(Mref),
        receive 
            {'DOWN', Mref, _, _, _} -> true
        after 0 -> true
        end,
        Reply;

Using a timeout of 0 means you never wait if the message is not there but you do get a timeout. I am guessing that this is what you see in the trace. It is not an error but just way the code is written. There is no viable alternative to doing it this way.

This means that in some way you will have to ignore this timeout, or perhaps just accept timeouts as a natural part of the program and not some form of "exception" or error.

If I have understood how it works.

Upvotes: 1

Vincenzo Maggio
Vincenzo Maggio

Reputation: 3869

My two cents here: if you read erlang doc for dbg you see that timeout message as well, my opinion is that the io_server registered for printing debug message spawn a dedicated process which ease performance for huge blocking I/O tracing, but after a while that nothing is traced, it simply drop the listening 'socket' (I mean socket from the erlang passing message system point of view). Indeed you see the io_request and io_reply to and from <0.23.0> which is the printing server, I think you can simply ignore it as a (unuseful) further debug message.

Upvotes: 0

Related Questions