[erlang-questions] Low disk logging performance in SMP

[Hynek Vychodil]

It seems that block counting is not necessary. I'm taking same performance
(~5MB/s measured at 10 million messages) even this version:

-module(testLogger).

-compile(inline).

-export([listener/1, start/1, write/2]).

start(Filename) ->
    Pid = spawn(?MODULE, listener, [Filename]),
    register(?MODULE, Pid).

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, [Data]);
      {count, From} ->
          From ! {count, N}, listener(Fd, N, SoFar);
      stop -> ok;
      Msg ->
          io:format("Unexpected message: ~p~n", [Msg]),
          listener(Fd, N, SoFar)
    end;
listener(Fd, N, SoFar) ->
    receive
      {data, Data} -> listener(Fd, N + 1, [Data | SoFar]);
      {count, From} ->
          From ! {count, N}, listener(Fd, N, SoFar);
      stop -> ok;
      Msg ->
          io:format("Unexpected message: ~p~n", [Msg]),
          listener(Fd, N, SoFar)
      after 0 -> flush(Fd, N, SoFar)
    end.

flush(Fd, N, Data) ->
    file:write(Fd, lists:reverse(Data)),
    listener(Fd, N, []).

write(_Data, 0) -> ok;
write(Data, N) ->
    (?MODULE) ! {data, Data}, write(Data, N - 1).

On Fri, Apr 24, 2009 at 8:32 PM, Hynek Vychodil <vychodil.hynek@REDACTED>wrote:

> Try this one, I guess you will be surprised ;-)
>
> -define(BS, 65536).
>
> start(Filename) ->
>     Pid = spawn(?MODULE, listener, [Filename]),
>     register(?MODULE, Pid).
>
> listener(Filename) ->
>     case file:open(Filename, [append, raw]) of
>       {ok, Fd} -> listener(Fd, 0, [], 0);
>       {error, Reason} -> error_logger:error_msg(Reason)
>     end.
>
> listener(Fd, N, [] = SoFar, 0) ->
>     receive
>       {data, Data} ->
>           listener(Fd, N + 1, [Data], iolist_size(Data));
>       {count, From} ->
>           From ! {count, N}, listener(Fd, N, SoFar, 0);
>       stop -> ok;
>       Msg ->
>           io:format("Unexpected message: ~p~n", [Msg]),
>           listener(Fd, N, SoFar, 0)
>     end;
> listener(Fd, N, SoFar, S) when S > (?BS) ->
>     file:write(Fd, lists:reverse(SoFar)),
>     listener(Fd, N, [], 0);
> listener(Fd, N, SoFar, S) ->
>     receive
>       {data, Data} ->
>           listener(Fd, N + 1, [Data | SoFar],
>                    S + iolist_size(Data));
>       {count, From} ->
>           From ! {count, N}, listener(Fd, N, SoFar, S);
>       stop -> ok;
>       Msg ->
>           io:format("Unexpected message: ~p~n", [Msg]),
>           listener(Fd, N, SoFar, S)
>       after 0 ->
>                 file:write(Fd, lists:reverse(SoFar)),
>                 listener(Fd, N, [], 0)
>     end.
>
> write(_Data, 0) -> ok;
> write(Data, N) ->
>     (?MODULE) ! {data, Data}, write(Data, N - 1).
>
> 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
>



-- 
--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/31b07452/attachment.htm>