[erlang-questions] Low disk logging performance in SMP

[Hynek Vychodil]

It behaves much worse on my laptop. In smp it performs 4kB in about 5 sec.
It is not issue of R13B because I'm using version 5.6.5. I have suspected
issue in message queue in file:write then changed listener to

listener(Fd,N) ->
  receive
    {data,Data} -> Fd ! {io_request, self(), Fd, {put_chars, Data}},
listener(Fd,N+1);
    {count,From} -> From ! {count,N}, listener(Fd,N);
    {stop,From} -> From ! {stop,success};
    {io_reply, Fd, ok} -> listener(Fd, N);
    Msg -> io:format("Unexpected message: ~p~n", [Msg]), listener(Fd, N)
  end.

but without any effect. Than I have tried ad kernel pool and asynchronous
threads (erl +K true +A 2) without any observable effect. I have also tried
file:open(Filename,[append, delayed_write]). No effect.
It seems that when I solve issue with message queue in testLogger:listener
it happen again in file_io_server. I have end up with reasonable fast but
still not good enough (it is able to fall to swapping)

-define(BS, 65536).

listener(Filename) ->
    case file:open(Filename,[append, raw]) of
        {ok,Fd} -> listener(Fd,0, <<>>);
        {error,Reason} -> error_logger:error_msg(Reason)
    end.

listener(Fd,N, <<>> = SoFar) ->
    receive
        {data,Data} -> listener(Fd, N+1, iolist_to_binary(Data));
        {count,From} -> From ! {count,N}, listener(Fd, N, SoFar);
        {stop,From} -> From ! {stop,success};
        Msg -> io:format("Unexpected message: ~p~n", [Msg]), listener(Fd, N,
SoFar)
    end;
listener(Fd,N, SoFar) when size(SoFar) > ?BS -> file:write(Fd, SoFar),
listener(Fd, N, <<>>);
listener(Fd,N, SoFar) ->
    receive
        {data,Data} ->
            BinData = iolist_to_binary(Data),
            Bin = <<SoFar/binary, BinData/binary>>,
            listener(Fd, N+1, Bin);
        {count,From} -> From ! {count,N}, listener(Fd, N, SoFar);
        {stop,From} -> file:write(Fd, SoFar), From ! {stop,success};
        Msg -> io:format("Unexpected message: ~p~n", [Msg]), listener(Fd, N,
SoFar)
    after 0 ->
        file:write(Fd, SoFar),
        listener(Fd, N, <<>>)
    end.

P.S.: Version with caching and asynchronnous calls to file_io_server instead
prim_file (raw) consumes more memory.

On Fri, Apr 24, 2009 at 4:23 PM, chaitanya Chalasani <
chaitanya.chalasani@REDACTED> wrote:

>  Hi,
>
> I am facing performance issue with my file logger. The file logger is an
> event handler holding the file reference is its state. The performance of
> the module is way ahead in the smp disabled erl shell compared with default
> smp enabled erl shell.
>
> I tried ...
> case#1
> *Erlang R13B (erts-5.7.1) [source] [rq:1] [async-threads:0] [hipe]
> [kernel-poll:false]*
>
> *Eshell V5.7.1  (abort with ^G)*
> *1> testLogger:start("test.log").*
> *true*
> *2> testLogger:write("Testing...",1000000).*
> *{ok,done}*
> *3>*
>
> and
>
> case#2
> *Erlang R13B (erts-5.7.1) [source] [smp:2:2] [rq:2] [async-threads:0]
> [hipe] [kernel-poll:false]*
>
> *Eshell V5.7.1  (abort with ^G)*
> *1> testLogger:start("test.log").*
> *true*
> *2> testLogger:write("Testing...",1000000).*
> *{ok,done}*
> *3>*
>
>
> What I observed was -
> Case 1:
>    1. The testLogger:write("Testing...",1000000) did not return back the
> control to the shell until all the messages are written to log.
>     2. The data was written at 400 KB/s
>
> Case 2:
>     1. The testLogger:write("Testing...",1000000) return back the control
> to the shell with {ok, done} after a short while but the messages where
> being written to log even after that.
>     2. The data was written at 4 KB/s
>     3. I checked in the pman tool it shows current funtion as
> io:wait_io_mon_reply/2 and the messages in the message pool are about 880k.
>
> Below is the code which I tested.
>
> *start(Filename) ->
> register(testLogger,spawn(testLogger,listener,[Filename])).*
>
> *listener(Filename) ->*
> * case file:open(Filename,[append]) of*
> * {ok,Fd} -> listener(Fd,0);*
> * {error,Reason} -> error_logger:error_msg(Reason)*
> * end.*
>
> *listener(Fd,N) ->*
> * receive*
> * {data,Data} -> file:write(Fd,Data), listener(Fd,N+1);*
> * {count,From} -> From ! {count,N}, listener(Fd,N);*
> * {stop,From} -> From ! {stop,success}*
> * end.*
>
> *write(_Data,0) -> {ok,done};*
> *write(Data,N) ->  testLogger ! {data,Data}, write(Data,N-1).*
>
> Is there a problem with my code or is it a known issue?
>
>   *------*
> *CHAITANYA CHALASANI*
>
> _______________________________________________
> erlang-questions mailing list
> erlang-questions@REDACTED
> http://www.erlang.org/mailman/listinfo/erlang-questions
>



-- 
--Hynek (Pichi) Vychodil

Analyze your data in minutes. Share your insights instantly. Thrill your
boss.  Be a data hero!
Try Good Data now for free: www.gooddata.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://erlang.org/pipermail/erlang-questions/attachments/20090424/b6720b87/attachment.htm>